Test case failed - cli/cli-action-conf.sh

[wzyhay]

Checklist before starting to submit this support request

I confirm that:

• I am requesting support! :)
• I have tested this with the latest stable Snoopy version (or the latest master build).
• I have checked the FAQ.
• I have read Snoopy's documentation here and here.
• I have searched Snoopy issues for an existing issue that matches my problem, and found none.

Issue description

Hi, I am currently using version 2.5.1 of snoopy on Centos7. After compiling and installing, I wanted to verify the soundness of the functionality through testing components, so I manually executed the testing command
./configure --enable-everything && make && make tests

Issue reproduction steps

Expected result

All tests passed

Actual result

I don't know why this test failed or what other impact it would have

[bostjan]

Hey @wzyhay, thanks for reporting this, and sorry for the long delay, but I finally figured out why I am not getting email notifications for new issues.

Not sure yet what's going on here, but I'll suggest two things to start with:

1. After the test suite fails, run the test manually, with ./tests/cli/cli-action-conf.sh command and check the output you get.
2. Additionally, use strace to run the binary like this: strace ./src/cli/snoopyctl conf and paste the output here (feel free to do it as a text, not as a screenshot ;) )

I suspect it's the missing target snoopy.ini file (i.e. /etc/snoopy.ini) that's "causing" this and I'll need to fix the test to make it look for something local in the tests directory.

[wzyhay]

Thank you for your reply. I executed the strace command as you said and found that the result was as follows：

root@ov-qacommonvpnvpntest-17 ~/hids-wazuh-wzy_branch_wazuh/snoopy # strace ./src/cli/snoopyctl conf
execve("./src/cli/snoopyctl", ["./src/cli/snoopyctl", "conf"], 0x7fffdff5d078 /* 31 vars */) = 0
brk(NULL)                               = 0x6e6000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f13ebb6f000
access("/etc/ld.so.preload", R_OK)      = 0
open("/etc/ld.so.preload", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=28, ...}) = 0
mmap(NULL, 28, PROT_READ|PROT_WRITE, MAP_PRIVATE, 3, 0) = 0x7f13ebb6e000
close(3)                                = 0
open("/usr/local/lib/libsnoopy.so", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\3004\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=321472, ...}) = 0
mmap(NULL, 59632, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f13ebb5f000
mmap(0x7f13ebb62000, 24576, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) = 0x7f13ebb62000
mmap(0x7f13ebb68000, 12288, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x9000) = 0x7f13ebb68000
mmap(0x7f13ebb6b000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xb000) = 0x7f13ebb6b000
mmap(0x7f13ebb6d000, 2288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f13ebb6d000
close(3)                                = 0
munmap(0x7f13ebb6e000, 28)              = 0
open("/opt/rh/devtoolset-9/root/usr/lib64/tls/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/rh/devtoolset-9/root/usr/lib64/tls/x86_64", 0x7ffc8098fab0) = -1 ENOENT (No such file or directory)
open("/opt/rh/devtoolset-9/root/usr/lib64/tls/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/rh/devtoolset-9/root/usr/lib64/tls", {st_mode=S_IFDIR|0555, st_size=6, ...}) = 0
open("/opt/rh/devtoolset-9/root/usr/lib64/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/rh/devtoolset-9/root/usr/lib64/x86_64", 0x7ffc8098fab0) = -1 ENOENT (No such file or directory)
open("/opt/rh/devtoolset-9/root/usr/lib64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/rh/devtoolset-9/root/usr/lib64", {st_mode=S_IFDIR|0555, st_size=144, ...}) = 0
open("/opt/rh/devtoolset-9/root/usr/lib/tls/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/rh/devtoolset-9/root/usr/lib/tls/x86_64", 0x7ffc8098fab0) = -1 ENOENT (No such file or directory)
open("/opt/rh/devtoolset-9/root/usr/lib/tls/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/rh/devtoolset-9/root/usr/lib/tls", 0x7ffc8098fab0) = -1 ENOENT (No such file or directory)
open("/opt/rh/devtoolset-9/root/usr/lib/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/rh/devtoolset-9/root/usr/lib/x86_64", 0x7ffc8098fab0) = -1 ENOENT (No such file or directory)
open("/opt/rh/devtoolset-9/root/usr/lib/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/rh/devtoolset-9/root/usr/lib", {st_mode=S_IFDIR|0555, st_size=17, ...}) = 0
open("/opt/rh/devtoolset-9/root/usr/lib64/dyninst/tls/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/rh/devtoolset-9/root/usr/lib64/dyninst/tls/x86_64", 0x7ffc8098fab0) = -1 ENOENT (No such file or directory)
open("/opt/rh/devtoolset-9/root/usr/lib64/dyninst/tls/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/rh/devtoolset-9/root/usr/lib64/dyninst/tls", 0x7ffc8098fab0) = -1 ENOENT (No such file or directory)
open("/opt/rh/devtoolset-9/root/usr/lib64/dyninst/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/rh/devtoolset-9/root/usr/lib64/dyninst/x86_64", 0x7ffc8098fab0) = -1 ENOENT (No such file or directory)
open("/opt/rh/devtoolset-9/root/usr/lib64/dyninst/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/rh/devtoolset-9/root/usr/lib64/dyninst", 0x7ffc8098fab0) = -1 ENOENT (No such file or directory)
open("/opt/rh/devtoolset-9/root/usr/lib/dyninst/tls/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/rh/devtoolset-9/root/usr/lib/dyninst/tls/x86_64", 0x7ffc8098fab0) = -1 ENOENT (No such file or directory)
open("/opt/rh/devtoolset-9/root/usr/lib/dyninst/tls/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/rh/devtoolset-9/root/usr/lib/dyninst/tls", 0x7ffc8098fab0) = -1 ENOENT (No such file or directory)
open("/opt/rh/devtoolset-9/root/usr/lib/dyninst/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/rh/devtoolset-9/root/usr/lib/dyninst/x86_64", 0x7ffc8098fab0) = -1 ENOENT (No such file or directory)
open("/opt/rh/devtoolset-9/root/usr/lib/dyninst/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/opt/rh/devtoolset-9/root/usr/lib/dyninst", 0x7ffc8098fab0) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=38383, ...}) = 0
mmap(NULL, 38383, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f13ebb55000
close(3)                                = 0
open("/lib64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\200m\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=142144, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f13ebb6e000
mmap(NULL, 2208904, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f13eb733000
mprotect(0x7f13eb74a000, 2093056, PROT_NONE) = 0
mmap(0x7f13eb949000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16000) = 0x7f13eb949000
mmap(0x7f13eb94b000, 13448, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f13eb94b000
close(3)                                = 0
open("/opt/rh/devtoolset-9/root/usr/lib64/tls/libdl.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/rh/devtoolset-9/root/usr/lib64/libdl.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/rh/devtoolset-9/root/usr/lib/libdl.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/lib64/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\16\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=19248, ...}) = 0
mmap(NULL, 2109744, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f13eb52f000
mprotect(0x7f13eb531000, 2097152, PROT_NONE) = 0
mmap(0x7f13eb731000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7f13eb731000
close(3)                                = 0
open("/opt/rh/devtoolset-9/root/usr/lib64/tls/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/rh/devtoolset-9/root/usr/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/rh/devtoolset-9/root/usr/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/lib64/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0`&\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=2156592, ...}) = 0
mmap(NULL, 3985920, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f13eb161000
mprotect(0x7f13eb325000, 2093056, PROT_NONE) = 0
mmap(0x7f13eb524000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1c3000) = 0x7f13eb524000
mmap(0x7f13eb52a000, 16896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f13eb52a000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f13ebb54000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f13ebb52000
arch_prctl(ARCH_SET_FS, 0x7f13ebb52740) = 0
access("/etc/sysconfig/strcasecmp-nonascii", F_OK) = -1 ENOENT (No such file or directory)
access("/etc/sysconfig/strcasecmp-nonascii", F_OK) = -1 ENOENT (No such file or directory)
mprotect(0x7f13eb524000, 16384, PROT_READ) = 0
mprotect(0x7f13eb731000, 4096, PROT_READ) = 0
mprotect(0x7f13eb949000, 4096, PROT_READ) = 0
mprotect(0x7f13ebb6b000, 4096, PROT_READ) = 0
mprotect(0x405000, 4096, PROT_READ)     = 0
mprotect(0x7f13ebb70000, 4096, PROT_READ) = 0
munmap(0x7f13ebb55000, 38383)           = 0
set_tid_address(0x7f13ebb52a10)         = 1425
set_robust_list(0x7f13ebb52a20, 24)     = 0
rt_sigaction(SIGRTMIN, {sa_handler=0x7f13eb739860, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7f13eb742630}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {sa_handler=0x7f13eb7398f0, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0x7f13eb742630}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
access("/usr/local/lib/libsnoopy.so", R_OK) = 0
futex(0x7f13eb7320d0, FUTEX_WAKE_PRIVATE, 2147483647) = 0
brk(NULL)                               = 0x6e6000
brk(0x707000)                           = 0x707000
brk(NULL)                               = 0x707000
futex(0x7f13ebb6d788, FUTEX_WAKE_PRIVATE, 2147483647) = 0
open("/usr/local/etc/snoopy.ini", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=9606, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f13ebb5e000
read(3, ";;; REQUIRED Section\n;\n[snoopy]\n"..., 4096) = 4096
read(3, "- this would only log uids who e"..., 4096) = 4096
read(3, ";;; Error Logging\n;\n; Whether to"..., 4096) = 1414
read(3, "", 4096)                       = 0
close(3)                                = 0
munmap(0x7f13ebb5e000, 4096)            = 0
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 1), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f13ebb5e000
write(1, "; Options from config file (or d"..., 68; Options from config file (or defaults): /usr/local/etc/snoopy.ini
) = 68
write(1, "[snoopy]\n", 9[snoopy]
)               = 9
write(1, "error_logging = no\n", 19error_logging = no
)    = 19
write(1, "filter_chain = only_tty:0\n", 26filter_chain = only_tty:0
) = 26
write(1, "message_format = [datetime:%{dat"..., 372message_format = [datetime:%{datetime} username:%{username} hostname:%{hostname} uid:%{uid} sid:%{sid} pid:%{pid} ppid:%{ppid} egid:%{egid} egroup:%{egroup} euid:%{euid} eusername:%{eusername} gid:%{gid} group:%{group} ipaddr:%{ipaddr} login:%{login} rpname:%{rpname} tty:%{tty} tty_uid:%{tty_uid} tty_username:%{tty_username} cwd:%{cwd} filename:%{filename}]: %{cmdline}
) = 372
write(1, "output = file:/var/ossec/wazuh/l"..., 47output = file:/var/ossec/wazuh/logs/snoopy.log
) = 47
write(1, "syslog_facility = AUTHPRIV\n", 27syslog_facility = AUTHPRIV
) = 27
write(1, "syslog_ident = snoopy\n", 22syslog_ident = snoopy
) = 22
write(1, "syslog_level = INFO\n", 20syslog_level = INFO
)   = 20
exit_group(0)                           = ?
+++ exited with 0 +++

The output of another check command is as follows：

root@ov-qacommonvpnvpntest-17 ~/hids-wazuh-wzy_branch_wazuh/snoopy/tests/cli # ./cli-action-conf.sh
Current test path: /root/hids-wazuh-wzy_branch_wazuh/snoopy/tests/cli/cli-action-conf.sh
[WARNING] Using non-default path to libsnoopy.so: /root/hids-wazuh-wzy_branch_wazuh/snoopy/tests/cli/../../src/.libs/libsnoopy.so
FAIL
Expected string not encountered: 'message_format'

[bostjan]

Hey @wzyhay, thanks for your response.

I've just run Snoopy's test suite in a CentOS 7 (x86_64) Docker container and the tests/cli/cli-action-conf.sh test is working fine, along everything else (once all the required software was installed, namely socat).

Not exactly sure yet what's going on, but by the looks of your strace output, snoopyctl command seems to be working fine. It finds the /usr/local/etc/snoopy.ini file (the open("/usr/local/etc/snoopy.ini", O_RDONLY) = 3 call), and it outputs the expected message_format line to the stdout (the write(1, "message_format = [datetime:%{dat"...) = 372 call.

Can you double check first that you see the message_format = ... line in the output of ./src/cli/snoopyctl conf command?

Furthermore, here is the (abbreviated) test case tests/cli/cli-action-conf.sh:

#...

### Test for error(s)
#
EXPECTED_STRING="message_format"
if ! $SNOOPY_CLI conf | fgrep "$EXPECTED_STRING" > /dev/null ; then
    snoopy_testResult_fail "Expected string not encountered: '$EXPECTED_STRING'"
fi

# ...

I think there is something off with the check itself and the way it works in your system. The only line where (by the data I currently have) the test can fail is this one:

if ! $SNOOPY_CLI conf | fgrep "$EXPECTED_STRING" > /dev/null ; then

By the looks of it, we've narrowed it down to a single line, but I have no idea why this line of code would fail on your system. If you can figure out how to change this test case to make it work on your system too, let me know and I'll consider including the fix with the next release. I am not sure of how much further help I can be without being able to reproduce the issue myself, but if you have questions, ask away.

If it turns out that all this is just some weird setting on your system causing this error (i.e. some weird bash settings, or a missing fgrep or something similarly far-fetched), I'll appreciate your feedback.

Best of luck!

[bostjan]

I may have stumbled upon this yesterday while working on #270 - it started happening when "system" Snoopy (so the one already installed into the target directory and enabled) was already loaded into the process(es). I'll see if I can actually reproduce this.