a2o/snoopy

Please help. Sockets to syslog-ng not working

Dr-Bone opened this issue · 5 comments

Dr-Bone commented

Checklist before I submit this issue report

I confirm

Issue description - Environment basics

Key Value Comments
Architecture: x86_64
Linux distribution: debian
Distribution version: buster (10)
Snoopy version: 2.4.13
Snoopy config file was used: yes
Snoopy threading support enabled: no at least I did not enable it on purpose, running default in this regard

Issue description - How was Snoopy installed

first installed snoopy from debian repos, then the latest version using install-snoopy.sh. (no luck with either)

Issue description - Describe the problem you are having

On my system I've snoopy, journald and syslog-ng (for central logging) running.
Currently snoopy uses devlog to send log lines to journald and journald forwards them to syslog-ng.
The problem is that snoopy is "flooding" the journal and makes it rotate far sooner then desired as well as hard to read.
I currently try to resolve that by having snoopy send its logs directly to syslog-ng.
Using the file /var/log/auth.log is not an option as this would mean that this file would need to be world read/writable.
I tried using the socket file between journald and syslog-ng (/run/systemd/journald/syslog) without success
I tried having syslog-ng create socket files (stream as well as dgram) and configured those in snoopy, also without success.

Its entirely possible I'm on the wrong path here, please let me know whats the right way in this situation.
(Goal: have snoopy logs in syslog-ng but not in journal)

Steps to reproduce

AGAIN: this is potentially not a bug but just me doing something wrong/misunderstanding it!

spin up a debian buster container
install syslog-ng (rsyslog is replaced in this step)
(replace the symlink /etc/systemd/system/syslog.service to point to syslog-ng)
configure syslog-ng to write AUTH and AUTHPRIV to /var/log/auth.log for example
configure a socket (unix-dgram or unix-stream) as source in syslog-ng config (e.g. /run/snoopy.sock)
configure snoopy to use this socket

Expected result

snoopy logs in /var/log/auth.log

Actual result

no snoopy logs in /var/log/auth.log

bostjan commented

Works for me, looks like a configuration issue on your end.

My test:
In a debian:buster LXC container, after installing, configuring and restarting syslog-ng and installing Snoopy (2.4.13, via the install script), here is the output (slightly redacted for readability):

root@t-debian-buster:/etc/syslog-ng# bash   # Enter a new shell, to make sure the /etc/ld.so.preload content is picked up
root@t-debian-buster:/etc/syslog-ng# cat /etc/syslog-ng/syslog-ng.conf

@version: 3.19

options { chain_hostnames(off); flush_lines(0); use_dns(no); use_fqdn(no);
	  dns_cache(no); owner("root"); group("adm"); perm(0640);
	  stats_freq(0); bad_hostname("^gconfd$");
};

source s_snoopy {
    internal();
    unix-dgram("/run/snoopy.sock");
};

destination d_all {
    file("/var/log/syslog-ng.log");
};

log { source(s_snoopy); destination(d_all); };

root@t-debian-buster:/etc/syslog-ng# cat /etc/snoopy.ini | grep -v '^;'
[snoopy]
output = socket:/run/snoopy.sock

root@t-debian-buster:/etc/syslog-ng# tail -f /var/log/syslog-ng.log 
Apr 14 18:46:03 t-debian-buster syslog-ng[4735]: syslog-ng starting up; version='3.19.1'
Apr 14 18:49:58 t-debian-buster [uid:0 sid:99 tty:(unknown) cwd:/etc/syslog-ng filename:/bin/cat]: cat /etc/syslog-ng/syslog-ng.conf
Apr 14 18:50:05 t-debian-buster [uid:0 sid:99 tty:(none) cwd:/etc/syslog-ng filename:/bin/grep]: grep -v ^;
Apr 14 18:50:05 t-debian-buster [uid:0 sid:99 tty:(unknown) cwd:/etc/syslog-ng filename:/bin/cat]: cat /etc/snoopy.ini
Apr 14 18:50:11 t-debian-buster [uid:0 sid:99 tty:(unknown) cwd:/etc/syslog-ng filename:/usr/bin/tail]: tail -f /var/log/syslog-ng.log
^C
root@t-debian-buster:/etc/syslog-ng#
Dr-Bone commented

wow thank you so much for your efforts and the quick reply!
That means the direction was the right one, thanks for confirming that.
I know I did not spawn a new bash after upgrading snoopy. But I doubt the functionality is broken in the old version. That leaves me with a configuration issue on my side. I'm currently a bit puzzled what I did wrong. (everything works when the logs travel through journald)
Will go ahead and will take a look at it with a fresh mind tomorrow...

bostjan commented

That additional spawning of bash really depends on where you're coming from, but in my particular case (as the initial bash was started before Snoopy was installed), it was actually needed. I could also have just re-entered the LXC and the result would be the same.

I'd suggest using strace -f -p BASH-PID on two ends here:

  • on a bash that you're using to test stuff out with (you'll need to strace it from another console/bash), to confirm you're actually seeing Snoopy sending data to the target socket. You should see something like this (among many other things):
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7efccac147d0) = 11749
strace: Process 11749 attached
[pid 11668] setpgid(11749, 11749 <unfinished ...>
...
[pid 11749] openat(AT_FDCWD, "/etc/snoopy.ini", O_RDONLY) = 3
[pid 11749] fstat(3, {st_mode=S_IFREG|0644, st_size=8524, ...}) = 0
[pid 11749] read(3, ";;; REQUIRED Section\n;\n[snoopy]\n"..., 4096) = 4096
[pid 11749] read(3, "ollows the colon,\n; - filter may"..., 4096) = 4096
[pid 11749] read(3, "\n; Example:\n;syslog_ident = \"my-"..., 4096) = 332
[pid 11749] read(3, "", 4096)           = 0
[pid 11749] close(3)                    = 0
...
[pid 11749] socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3
[pid 11749] connect(3, {sa_family=AF_UNIX, sun_path="/run/snoopy.sock"}, 18) = 0
[pid 11749] sendto(3, "[uid:0 sid:11668 tty:(unknown) c"..., 72, MSG_DONTWAIT|MSG_NOSIGNAL, NULL, 0) = 72
[pid 11749] close(3)                    = 0
[pid 11749] execve("/bin/echo", ["/bin/echo", "adsf"], 0x5598bb48ea50 /* 19 vars */) = 0
  • then run strace -s 128 -f -p SYSLOG-NG-PID on the syslog-ng, and you should see syslog-ng receiving the message:
[pid 11832] recvmsg(11, {msg_name=0x7fe125ef8320, msg_namelen=128->0, msg_iov=[{iov_base="[uid:0 sid:11668 tty:(unknown) cwd:/ filename:/bin/echo]: /bin/echo adsf", iov_len=65536}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, cmsg_data={pid=11835, uid=0, gid=0}}], msg_controllen=32, msg_flags=0}, 0) = 72
  • and also writing the message to a file:
[pid 11832] writev(14, [{iov_base="Apr 14 19:47:19 t-debian-buster [uid:0 sid:11668 tty:(unknown) cwd:/ filename:/bin/echo]: /bin/echo adsf\n", iov_len=105}], 1) = 105

I hope this helps. Good luck!

Dr-Bone commented

I couldn't resist. I can confirm; its working as you wrote above.
Afterwards it's always obvious why something did not work, isn't it?
So the problem was that my filter was filtering for the logging facility "AUTH" and "AUTHPRIV". But by using a socket, neither the program nor the facility is set, resulting in the default facility and an empty program variable...

solution in my case was following line for the source socket in syslog-ng config:
unix-dgram("/run/snoopy.sock" program-override("snoopy") default-facility("auth"));

At this point the only thing left for me to do is to apologize for wasting your time and to thank you for your awesome help!
There are many expensive commercial supports out there which do not deliver as precise or fast as you do.
Awesome! Thank you very much and stay healthy!

bostjan commented

Ha, good one! :)

Thanks for sharing the root cause, much appreciated, maybe it will help someone else in the future.

Thanks, stay safe yourself too.

  • 👍1