同步等待 rsyslog 刷新完成

Question

我正在使用本地日志文件运行 rsyslogd 8.24.0。

我有一个测试，它运行一个程序，该程序执行一些 syslog 日志记录（我的测试中的条目通过 rsyslog.conf 设置转到另一个文件）然后退出到 shell 脚本以检查日志是否具有预期的内容。这通常有效，但有时会失败，就好像日志记录没有发生一样。在执行检查之前，我已经向 shell 脚本添加了一个刷新（使用 HUP 信号）。我可以看到 HUP 已经发生并且正确的条目在日志中，但是脚本的检查仍然失败。 有没有办法让 shell 脚本等到刷新完成？我可以添加任意睡眠，但希望有更明确的内容。

以下是 shell 脚本的相关部分：

# Set syslog to send dump_hook's logging to a local logfile...
sudo echo "user.*   `pwd`/dump_hook_log" >> /etc/rsyslog.conf
sudo systemctl restart rsyslog.service
echo "" > ./dump_hook_log

# run the test program which does syslog logging

kill -HUP `cat /var/run/syslogd.pid` # flush syslog 
if [ $? -ne 0 ]
then 
    logFail "failed to HUP `cat /var/run/syslogd.pid`: $?"
fi
echo "sent HUP to `cat /var/run/syslogd.pid`" 
grep <the string I want> ./dump_hook_log >/dev/null

当测试报告失败时，有问题的字符串总是在 dump_hook_log 中，我已经去查看它了。我想它一定是在 grep 的时候刷新还没有完成。

这是一个例子： 在 /var/log/messages 中

2019-01-30T12:13:27.216523+00:00 apx-ont-1 apx_dump_hook[28279]: Failed to open raw dump file "core" (Is a directory)
2019-01-30T12:13:27.216754+00:00 apx-ont-1 rsyslogd: [origin software="rsyslogd" swVersion="8.24.0" x-pid="28185" x-info="http://www.rsyslog.com"] rsyslogd was HUPed

日志文件的修改日期（注意，这早于它包含的条目！）：

rw-rw-rw- 1 nealec appexenv1_group 2205 2019-01-30 12:13:27.215053296 +0000 testdir_OPT/dump_hook_log

日志文件的最后一行（这里只有 apx_dump_hook 条目）：

2019-01-30T12:13:27.216523+00:00 apx-ont-1 apx_dump_hook[28279]: Failed to open raw dump file "core" (Is a directory)

脚本报错：

Wed 30 Jan 12:13:27 GMT 2019 PSE Test 0.2b FAILED: 'Failed to open raw dump file' not found in ./dump_hook_log

Answer 1

这似乎有点重量级的解决方案，但是你可以使用系统的inotify api 来等待日志文件被关闭（HUP 信号的结果）。例如，

inotifywait -e close ./dump_hook_log

将挂起，直到rsyslogd（或任何进程）关闭文件，然后您将收到消息

./dump_hook_log CLOSE_WRITE,CLOSE 

程序将退出并返回代码 0。您可以添加超时。

Answer 2

我想我现在明白了。 HUP 导致 rsyslogd 关闭其打开的文件，但在需要登录文件之前它不会重新打开文件。 考虑以下： 我使用 inotify 等待文件关闭，如下所示：

case 9:
    {
        // Wait for the file, specified in argv[2], to be closed
        int inotfd = inotify_init();           
        if (inotfd < 0) {
            printf("inotify_init failed; errno %d: %s\n",
                errno, strerror(errno));
            exit(99);
        }
        int watch_desc = inotify_add_watch(inotfd, argv[2], IN_CLOSE);
        if (watch_desc < 0) {
            printf("can't watch %s failed; errno %d: %s\n",
                argv[2], errno, strerror(errno));
            exit(99);
        }
        size_t bufsiz = sizeof(struct inotify_event) + PATH_MAX + 1;
        struct inotify_event* event = static_cast<inotify_event*>(malloc(bufsiz));
        if (!event) {
            printf("Failed to malloc event buffer; errno %d: %s\n",
                errno, strerror(errno));
            exit(99);
        }

        /* wait for an event to occur with blocking read*/
        read(inotfd, event, bufsiz);
    }

然后在我的 shell 脚本中等待：

# Start a process that waits for the log file be closed
${bin}/test_dump_hook.exe 9 "./dump_hook_log" &  
wait_pid=$!

# Signal syslogd to cause it it close/reopen its log files
kill -HUP `cat /var/run/syslogd.pid` # flush syslog 
if [ $? -ne 0 ]
then 
    logFail "failed to HUP `cat /var/run/syslogd.pid`: $?"
fi
wait $waid_pid

我发现这永远不会回来。从另一个进程向 rsyslogd 发送 HUP 也不会中断等待，但是日志文件的 cat（它会打开/关闭文件）会。

这是因为 shell 脚本中的 HUP 是在其他进程等待它之前完成的。所以文件在等待开始时已经关闭，并且因为没有更多的日志记录到该文件，它没有重新打开，也不需要在收到任何后续 HUP 时关闭，所以永远不会发生事件来结束等待.

了解了这种行为后，我如何才能确定在检查日志之前已写入日志？我已经采用了这个解决方案；将已知消息放入日志并等待它出现，我知道我正在等待的条目必须在此之前。像这样：-

function flushSyslog
{
    logger -p user.info -t dump_hoook_test "flushSyslog"
    # Signal syslogd to cause it it close its log file
    kill -HUP `cat /var/run/syslogd.pid` # flush syslog 
    if [ $? -ne 0 ]
    then 
        logFail "failed to HUP `cat /var/run/syslogd.pid`: $?"
    fi
    # wait upto 10 secs for the entry we've just logged to appear
    sleeps=0 
    until     
        grep "flushSyslog" ./dump_hook_log > /dev/null 
    do  
        sleeps=$((sleeps+1))
        if [ $sleeps -gt 100 ]
        then
            logFail "failed to flush syslog dump_hook_log"
        fi
        sleep 0.1
    done        
}