exclude_spawns_of not working as expected

[alo0]

Hello,

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

I installed snoopy on a freshly installed proxmox and I have a lot of noise coming from the pve-firewall process. I tried to filter it using exclude_spawns_of and following the provided guide without any success. To be more precise, even using the "sh" keyword provided within the guide I was not able to achieve the same results (as in the guide). It seems exclude_spawns_of doesn't have any effect on my setup. What am I missing ?

Below you will find more info on my setup:
$ uname -a
Linux ns386187 5.15.64-1-pve #1 SMP PVE 5.15.64-1 (Thu, 13 Oct 2022 10:30:34 +0200) x86_64 GNU/Linux
(Latest version of proxmox)

$ snoopyctl status
/etc/ld.so.preload: OK - Snoopy is enabled.
LD_PRELOAD environment var: NOT OK - Not set.
Current process (shared libs): OK - libsnoopy.so is loaded in front of libc.so.6.
Current process (execve addr): OK - execve() symbol address changed, looks like Snoopy is loaded.

$ snoopyctl version
Snoopy CLI tool version: 2.5.1
Snoopy library version: 2.5.1 (path: /lib/x86_64-linux-gnu/libsnoopy.so)

$ snoopyctl conf
; Options from config file (or defaults): /etc/snoopy.ini
[snoopy]
error_logging = no
filter_chain = "only_tty;exclude_spawns_of:cron,pve-firewall"
message_format = [login:%{login} ssh:(%{env:SSH_CONNECTION}) sid:%{sid} tty:%{tty} (%{tty_uid}/%{tty_username}) uid:%{username}(%{uid})/%{eusername}(%{euid}) cwd:%{cwd}]: %{cmdline}
output = devlog
syslog_facility = AUTHPRIV
syslog_ident = snoopy
syslog_level = INFO

I changed the message_format and the modification was visible in the /var/log/auth.log file. So modification of the ini are taken into account. Moreover i tried filter_chain = "only_uid:1000" and it was successful. So no reason exclude_spawns_of should not work.

These are the lines that I want to filter
...
Nov 9 10:42:50 ns386187 snoopy[217814]: [login:(unknown) ssh:((undefined)) sid:1555 tty:(none) ((none)/(none)) uid:root(0)/root(0) cwd:/]: sed s/ebtable_//
Nov 9 10:42:50 ns386187 snoopy[217813]: [login:(unknown) ssh:((undefined)) sid:1555 tty:(none) ((none)/(none)) uid:root(0)/root(0) cwd:/]: cut -f1 -d
Nov 9 10:43:00 ns386187 snoopy[217825]: [login:(unknown) ssh:((undefined)) sid:1555 tty:(none) ((none)/(none)) uid:root(0)/root(0) cwd:/]: grep -E ^ebtable_ /proc/modules
Nov 9 10:43:00 ns386187 snoopy[217826]: [login:(unknown) ssh:((undefined)) sid:1555 tty:(none) ((none)/(none)) uid:root(0)/root(0) cwd:/]: cut -f1 -d
Nov 9 10:43:00 ns386187 snoopy[217827]: [login:(unknown) ssh:((undefined)) sid:1555 tty:(none) ((none)/(none)) uid:root(0)/root(0) cwd:/]: sed s/ebtable_//
Nov 9 10:43:00 ns386187 snoopy[217845]: [login:(unknown) ssh:((undefined)) sid:1555 tty:(none) ((none)/(none)) uid:root(0)/root(0) cwd:/]: grep -E ^ebtable_ /proc/modules
Nov 9 10:43:00 ns386187 snoopy[217846]: [login:(unknown) ssh:((undefined)) sid:1555 tty:(none) ((none)/(none)) uid:root(0)/root(0) cwd:/]: cut -f1 -d
Nov 9 10:43:00 ns386187 snoopy[217847]: [login:(unknown) ssh:((undefined)) sid:1555 tty:(none) ((none)/(none)) uid:root(0)/root(0) cwd:/]: sed s/ebtable_//
...

# cat /proc/1555/stat
1555 (pve-firewall) S 1 1555 1555 0 -1 1077936448 32491726 44278219 0 601 7086 11816 19959 18266 20 0 1 0 2201 281214976 22488 18446744073709551615 94748966924288 94748968513589 140728626643408 0 0 0 0 4224 81927 1 0 0 17 2 0 0 0 0 0 94748970247464 94748970316388 94748980756480 140728626646787 140728626646830 140728626646830 140728626647009 0

I am thinking about filtering the log using regexp through syslog, but I would prefer to use the native function of snoopy available for that. Any idea on how to make it work ?

Thanks

[alo0]

Forgot to add that I installed snoopy using the debian 11 (Bullseye) repo:
curl https://a2o.github.io/snoopy-packages/snoopy-packages-key.pub | apt-key add - &&
echo "deb https://a2o.github.io/snoopy-packages/repo/debian bullseye stable" > /etc/apt/sources.list.d/snoopy-stable.list &&
apt update &&
apt install snoopy
(Installed without warnings)

Proxmox VE 7.0 is based on Debian 11 so it seems appropriate to choose this repo. Nevertheless, the kernel provided in Proxmox is different from the generic one provided in a debian 11 vanilla.

[bostjan]

@alo0, thanks for the detailed report.

The only things that immediately spring to my mind are:

1. A potential cron vs crond discrepancy, but I've checked on Ubuntu (which is based on Debian and usually not too dissimilar) and indeed the process name is cron. Is the daemon name indeed cron and not crond on your Proxmox system too?
2. Are all processes that are executed under cron logged by Snoopy, or just some of them?
3. I suspect your cron scripts are just regular scripts, without trying to detach from the parent process & any similar shenanigans? Should you run pstree when the script is running, does it clearly fall under the cron process subtree?
4. Have you perchance tried reproducing this issue on a regular Ubuntu OS? I do not know if Proxmox implements any limitations to accessing the /proc filesystem, which is where exclude_spawns_of filter gets the required information from.

Other than that, I'll need to verify this filter's functionality. Since it was a third party contribution to Snoopy, I don't really know it by heart, so it might take some time.

[alo0]

Thank you @bostjan for your quick response

pve_firewall is not executed by cron but by systemd. So I don't think the issue is related to cron. Btw it is cron in proxmox as in debian.

$ ps -edf
UID PID PPID C STIME TTY TIME CMD
root 1 0 0 16:33 ? 00:00:00 /sbin/init
...
root 1562 1 0 16:33 ? 00:00:06 pve-firewall
...

$ cat /proc/1562/stat
1562 (pve-firewall) S 1 1562 1562 0 -1 1077936448 1324185 1573899 0 52 233 445 789 522 20 0 1 0 2045 281223168 22096 18446744073709551615 94198446292992 94198447882293 140728523162560 0 0 0 0 4224 81927 1 0 0 17 2 0 0 0 0 0 94198449616168 94198449685092 94198475902976 140728523169539 140728523169582 140728523169582 140728523169761 0

$ cat /proc/1/stat
1 (systemd) S 0 1 1 0 -1 4194560 14728 627407 139 1480 19 36 1000 238 20 0 1 0 15 168837120 2796 18446744073709551615 94245363113984 94245363946509 140722711673520 0 0 0 671173123 4096 1260 1 0 0 17 1 0 0 0 0 0 94245364332752 94245364633840 94245393481728 140722711678804 140722711678815 140722711678815 140722711678957 0

pstree display the same parent process.
systemd --> pve-firewall

I think we can rule out 1 and 2
about 3, it is still possible except it is executed by systemd
about 4 I won't be able to reproduce it as Proxmox is not available on Ubuntu. Proxmox is a linux distribution on its own.
Nevertheless I will try on a vanilla debian 11 to see if exclude_spawns_of is working as expected.

[bostjan]

Thanks for correcting the cron/pve-firewall inconsistency from my response.

Yeah, I can't see any sane reason why this shouldn't work as expected.

Unfortunately, the filtering implementation (and this filter too) is fairly weak in terms of either tracing or error reporting, so this might be a bit of a challenge to figure out.

BTW, revisiting your Snoopy configuration listed above, I see the only_tty filter being used too. Therefore, I am fairly surprised to see entries with tty:(none) in your log content. Something smells off here. Can you try using just the exclude_spawns_of filter? Maybe the issue is actually in the processing of a sequence of filters, and not in the exclude_spawns_of filter itself.

[bostjan]

Note to self: there are no tests for verifying the correctness of processing the filter chain. Fix it.

[alo0]

Tested with a fresh debian and exclude_spawns_of is working perfectly.
Next step will be to try on a freshly installed Proxmox.

[alo0]

Tested on a vbox with freshly installed proxmox 7 over debian 11
=> exclude_spawns_of work is working perfectly

Next step will be to reinstall my OVH server using the proxmox template and test again...

[bostjan]

Interesting. Looking forward to your next update.

Anyhow, I am not 100% sure what's going on with that TTY-related filter I mentioned above. But if I ignore that, the most likely culprit is probably a somehow limited access to the /proc/<PID>/stat content. Unfortunately, I cannot provide any meaningful method of discovery/confirmation for this statement, as Snoopy, in its current state, is really "unwilling" to give meaningful error messaging regarding this.

PS: Once you figure out the reproduction scenario, and if it is possible from your side (i.e. the system is set up for testing purposes only, unrelated to anything else, and publicly accessible), it might be easier for me to simply use your system to analyse the issue & potentially figure out a fix, than reproducing the issue on my side. Once applicable, if that is an option, let me know.

[alo0]

I am sorry to say that I can't reproduce the issue anymore.
Since last time, I

1. Flush out the iptables and switch off and on the PVE firewall
2. upgraded several packages (as proposed by the distro)
   It seems one or both of these operations solved the problem and now everything is working correctly.

Unless the problem appear again, I won't be able to provide you more insights.

Thank again for the support.

[bostjan]

Thank you for the update.