Scribe scribe - syslog-ng and logrotate installer

[tomsk]

Things have changed, see my post above about find what I found in /opt/var/log/messages. There are a few lines, but the only ones I want are the [save] ones, do I need to use this?

filter f_skynet-h {
 program("Skynet") or
 (message("[save]") type(glob));
};

Now I'm confused .... if that's what's in your /opt/var/log/messages file then it should be mirrored in the GUI

 

[Butterfly Bones]

Now I'm confused .... if that's what's in your /opt/var/log/messages file then it should be mirrored in the GUI

Yes, me too very confused. What I know is that when Skynet writes the hourly report it deletes the syslog-0.log and starts a new one, as seen in a term using tail.

Apr 11 07:20:59 RT-AC86U-4608 kernel: [BLOCKED - INBOUND] IN=eth0 OUT= MAC=88:d7:f6:1d:46:08:00:01:5c:6d:22:46:08:00 SRC=81.22.45.230 DST=[redacted] LEN=40 TOS=0x00 PREC=0x00 TTL=242 ID=46953 PROTO=TCP SPT=52189 DPT=10087 SEQ=83338721 ACK=0 WINDOW=1024 RES=0x00 SYN URGP=0 MARK=0x8000000
tail: /opt/var/log/skynet-0.log has been replaced; following end of new file
Apr 11 07:21:06 RT-AC86U-4608 kernel: [BLOCKED - INBOUND] IN=eth0 OUT= MAC=88:d7:f6:1d:46:08:00:01:5c:6d:22:46:08:00 SRC=193.32.161.55 DST=[redacted] LEN=40 TOS=0x00 PREC=0x00 TTL=235 ID=13196 PROTO=TCP SPT=47800 DPT=3392 SEQ=2452949795 ACK=0 WINDOW=1024 RES=0x00 SYN URGP=0 MARK=0x8000000

My very amateur guess is that when the skynet-0.log is deleted and restarted, for some reason the hourly report goes to /opt/var/log/messages but somehow misses the GUI. Syslog-ng is new, very obtuse (to me), and scripting is really hard for me to comprehend (as you see).

Thanks for the replies and help, very appreciated.

 

[elorimer]

I am toying with the idea that we have this all backwards if we want to fool with the iptables logging. There is something about iptables logging through the kernel, and syslog-ng reading those messages, that is garbling it all, and syslogd isn't having that problem.

So I've reconfigured this not to kill syslogd, and let it continue to write to /tmp/syslog.log. I'm also from the webgui causing those messages to be written to port 514 on the router's own IP. Then I've defined a single source in syslog-ng to accept those messages.

I'm going to play out here in left field for a while.

 

[tomsk]

Yes, me too very confused. What I know is that when Skynet writes the hourly report it deletes the syslog-0.log and starts a new one, as seen in a term using tail.

Apr 11 07:20:59 RT-AC86U-4608 kernel: [BLOCKED - INBOUND] IN=eth0 OUT= MAC=88:d7:f6:1d:46:08:00:01:5c:6d:22:46:08:00 SRC=81.22.45.230 DST=[redacted] LEN=40 TOS=0x00 PREC=0x00 TTL=242 ID=46953 PROTO=TCP SPT=52189 DPT=10087 SEQ=83338721 ACK=0 WINDOW=1024 RES=0x00 SYN URGP=0 MARK=0x8000000
tail: /opt/var/log/skynet-0.log has been replaced; following end of new file
Apr 11 07:21:06 RT-AC86U-4608 kernel: [BLOCKED - INBOUND] IN=eth0 OUT= MAC=88:d7:f6:1d:46:08:00:01:5c:6d:22:46:08:00 SRC=193.32.161.55 DST=[redacted] LEN=40 TOS=0x00 PREC=0x00 TTL=235 ID=13196 PROTO=TCP SPT=47800 DPT=3392 SEQ=2452949795 ACK=0 WINDOW=1024 RES=0x00 SYN URGP=0 MARK=0x8000000

My very amateur guess is that when the skynet-0.log is deleted and restarted, for some reason the hourly report goes to /opt/var/log/messages but somehow misses the GUI. Syslog-ng is new, very obtuse (to me), and scripting is really hard for me to comprehend (as you see).

Thanks for the replies and help, very appreciated.

From what i can remember of the purge command in Skynet, it doesn't delete the file.. haven't looked at the code in a long long time.... i'm guessing that because it's only Skynet messages that go to the skynet-0 log, that when its purged it becomes zero bytes

 

[Butterfly Bones]

From what i can remember of the purge command in Skynet, it doesn't delete the file.. haven't looked at the code in a long long time.... i'm guessing that because it's only Skynet messages that go to the skynet-0 log, that when its purged it becomes zero bytes

It is likely the destructive sed command that does it. That is why @cmkelley got @Adamm to add the feature for a custom location so that when the hour report was done and the syslog cleaned, the symlink from /tmp/syslog to /opt/var/log/messages was not broken. But there is still something going on with /opt/var/log/skynet-0.log at the end / start of an hour.

 

[dave14305]

It is likely the destructive sed command that does it. That is why @cmkelley got @Adamm to add the feature for a custom location so that when the hour report was done and the syslog cleaned, the symlink from /tmp/syslog to /opt/var/log/messages was not broken. But there is still something going on with /opt/var/log/skynet-0.log at the end / start of an hour.

I don't think the custom syslogloc in SkyNet prevents the hourly destructive sed on your /opt/var/log/skynet-0.log file, since that is where SkyNet thinks the syslog is now. It just avoids borking the /tmp/syslog.log softlink.

 

[Butterfly Bones]

I don't think the custom syslogloc in SkyNet prevents the hourly destructive sed on your /opt/var/log/skynet-0.log file, since that is where SkyNet thinks the syslog is now. It just avoids borking the /tmp/syslog.log softlink.

Thanks for that. My statement was really a W.A.G. Trying to learn, understand, and troubleshoot, with my limited knowledge and experience. I need to sit back and observe.

 

[dave14305]

Thanks for that. My statement was really a W.A.G. Trying to learn, understand, and troubleshoot, with my limited knowledge and experience. I need to sit back and observe.

When all is said and done, it's still just a router.

 

[Butterfly Bones]

When all is said and done, it's still just a router.

That defies my "logic".

 

[elorimer]

So I've reconfigured this not to kill syslogd, and let it continue to write to /tmp/syslog.log. I'm also from the webgui causing those messages to be written to port 514 on the router's own IP. Then I've defined a single source in syslog-ng to accept those messages.

After a few hours, with one exception, this seems to be working fine.

My pixelserv and skylog messages are being sifted into their own logs, skynet is scrubbing the skylog file and leaving behind the hourlies, and messages is catching the rest. The exception is the webgui log is now a raw ugly thing filled with all the those.

So yes, syslog-ng is mangling the kernel messages kicked out by skynet.

 

[Cam]

I tried a new tack with klogd. Previously I killed the process and had syslog-ng grab it with:

source kernel { file("/proc/kmsg" program_override("Kernel") flags(kernel)); };

This seemed to work for me to grab all the skynet logs with no issues, until at some point I must have kicked something in the WEBGUI and klogd restarted. Now you could (and I did) always add a "killall klogd" to the /opt/etc/init.d/rc.func.syslog-ng function, but instead I thought why not just let klogd run and stop syslog-ng crashing the party...

The idea being that klogd sends syslog messages to the system as it's supposed to, and syslog-ng will pick them up (in place of syslogd)

So now I am trialling leaving klogd running, and have commented out the kernel source above from my system-ng.conf, to see if klogd sends it's messages to syslog-ng. So far, skynet-0.log looks exactly as it should. "messages" is currently a little thin on content, but does have some "kernel" logs, so seems to be working ok so far.

 

[elorimer]

So now I am trialling leaving klogd running, and have commented out the kernel source above from my system-ng.conf, to see if klogd sends it's messages to syslog-ng. So far, skynet-0.log looks exactly as it should. "messages" is currently a little thin on content, but does have some "kernel" logs, so seems to be working ok so far.

I've done the same. I'm fascinated that kernel messages are coming through. I'll let it run.

 

[elorimer]

This continues to perplex me. I pursued some non-rigorous fooling around.

1. Just reading from /dev/log, I get kernel messages including ungarbled iptables output, scores of messages an hour.

2. I stripped out all the syslog-ng function and boiled it down to one source reading the /proc/kmsg file and writing it to a destination file. I get about 5 to 7 messages per hour this way, mostly garbled, and only from iptables.

3. I added back in the unix-stream source from /dev/log and sent it unfiltered to messages. I changed the /proc/kmsg source to tag it as "direct" (so I could see the difference), and sent that output to messages. I was thinking I would see pairs of messages. What I saw was 5 to 7 "direct" messages per hour this way, ungarbled, and only from iptables, and scores of kernel messages, all garbled, and none seeming to match any of the "direct" messages.

4. Looking at system-ng -Fevd, I can see that the incoming message to syslog-ng and the outgoing message are the same with the timestamp and host added (that is, the message syslog-ng is seeing is garbled).

I'm thinking some system function is hoovering up the /proc/kmsg messages and sending them along to /dev/log. I am also thinking that when syslog-ng is monitoring the /proc/kmsg file it is some how on occasion getting a kernel message, but mostly not, but somehow messing with how "some system function" is hoovering up the messages such that /dev/log gets fragments.

So I'm concluding that it is a mistake--and unnecessary--for syslog-ng to be reading the /proc/kmsg file in the first place. Thoughts?

 

[tomsk]

This continues to perplex me. I pursued some non-rigorous fooling around.

1. Just reading from /dev/log, I get kernel messages including ungarbled iptables output, scores of messages an hour.

2. I stripped out all the syslog-ng function and boiled it down to one source reading the /proc/kmsg file and writing it to a destination file. I get about 5 to 7 messages per hour this way, mostly garbled, and only from iptables.

3. I added back in the unix-stream source from /dev/log and sent it unfiltered to messages. I changed the /proc/kmsg source to tag it as "direct" (so I could see the difference), and sent that output to messages. I was thinking I would see pairs of messages. What I saw was 5 to 7 "direct" messages per hour this way, ungarbled, and only from iptables, and scores of kernel messages, all garbled, and none seeming to match any of the "direct" messages.

4. Looking at system-ng -Fevd, I can see that the incoming message to syslog-ng and the outgoing message are the same with the timestamp and host added (that is, the message syslog-ng is seeing is garbled).

I'm thinking some system function is hoovering up the /proc/kmsg messages and sending them along to /dev/log. I am also thinking that when syslog-ng is monitoring the /proc/kmsg file it is some how on occasion getting a kernel message, but mostly not, but somehow messing with how "some system function" is hoovering up the messages such that /dev/log gets fragments.

So I'm concluding that it is a mistake--and unnecessary--for syslog-ng to be reading the /proc/kmsg file in the first place. Thoughts?

well this is what the syslog-ng FAQs say

Warning
There is problem caused by the ''/proc/kmsg'' implementation of the Linux kernel, namely, when two parallel processes open and try to read from the ''/proc/kmsg'' file.

This special file is the userspace interface for collecting kernel log messages. If there are multiple processes reading ''/proc/kmsg'', a race condition occurs and the process which loses the race essentially deadlocks until the next kernel message is generated, when a new race condition occurs.

If the system logger is blocked and is not processing userspace messages, slowly all system daemons stall while waiting for the system logger to become available again. This includes crucial system components like '''sshd''' or the application handling system logins.

There are two alternative solutions for processing kernel messages on Linux systems:

• using '''klogd''' from the sysklogd package
• reading ''/proc/kmsg'' from syslog-ng natively, without using the '''klogd''' daemon

The second method is recommended.

The solution to this problem is to avoid running multiple userspace components that touch ''/proc/kmsg''. If you configure syslog-ng to read kernel messages, ensure that '''klogd''' is not running. If you want to run '''klogd''', ensure that '''syslog-ng''' does not read ''/proc/kmsg''.
/QUOTE]

 

[elorimer]

and when I killall klogd, I get no more kernel messages from /dev/log, but I get lots now ungarbled from /proc/kmsg.

So klogd is delivering the messages to /dev/log, and following the last sentence of the warning, we can either kill klogd (preferable) and continue reading /proc/kmsg, or we can leave klogd and have syslog-ng not read /proc/kmsg. What scribe is doing (because entware is set up for this) is wrong. So is entware, or at least incomplete. Agreed?

 

[tomsk]

and when I killall klogd, I get no more kernel messages from /dev/log, but I get lots now ungarbled from /proc/kmsg.

So klogd is delivering the messages to /dev/log, and following the last sentence of the warning, we can either kill klogd (preferable) and continue reading /proc/kmsg, or we can leave klogd and have syslog-ng not read /proc/kmsg. What scribe is doing (because entware is set up for this) is wrong. So is entware, or at least incomplete. Agreed?

Agreed... for our purposes ... definitely wrong. not sure which will be the best way to go.... killing off klogd may not be that easy.

 

[Cam]

My system has been running for over a day now with my new setup as per my last post. ie NOT killing klogd, and all is working well.

From my reading /proc/kmsg is basically a special one time read 'file', so if syslog-ng is trying to read it, AND klogd is running you will get the garbled messages. I did have an issue when first testing where klogd got restarted at some point, so seeing as klogd consumes so little mem/cpu, it seems more stable to leave it running (than cron a watchdog type script to kill it) and just not source /proc/kmsg in syslog-ng.

I simply commented out the whole source kernel {} directive in syslog-ng.conf,

#source kernel {
    #file("/proc/kmsg" program_override("Kernel") flags(kernel) keep-timestamp(no));
#};

and

log {
    source(src);
    #source(kernel);
    destination(messages);
};

then sent killall -HUP syslog-ng, and haven't missed a beat since.

Then I commented the source(kernel); line in the log section of each file under /opt/etc/syslog-ng.d/ also.

Should be pretty easy for scribe to make those changes seeing as it installs it's own small syslog-ng.conf file, or use sed on the larger file if selected during install.

Thanks @cmkelley for getting me started on a nice project!

 

[cmkelley]

Yes, me too very confused. What I know is that when Skynet writes the hourly report it deletes the syslog-0.log and starts a new one, as seen in a term using tail.

Skynet doesn't delete syslog-0.og. Add a comment line to it. The next time skynet scrubs it, all that will be left is that comment line.

Apr 11 07:20:59 RT-AC86U-4608 kernel: [BLOCKED - INBOUND] IN=eth0 OUT= MAC=88:d7:f6:1d:46:08:00:01:5c:6d:22:46:08:00 SRC=81.22.45.230 DST=[redacted] LEN=40 TOS=0x00 PREC=0x00 TTL=242 ID=46953 PROTO=TCP SPT=52189 DPT=10087 SEQ=83338721 ACK=0 WINDOW=1024 RES=0x00 SYN URGP=0 MARK=0x8000000
tail: /opt/var/log/skynet-0.log has been replaced; following end of new file
Apr 11 07:21:06 RT-AC86U-4608 kernel: [BLOCKED - INBOUND] IN=eth0 OUT= MAC=88:d7:f6:1d:46:08:00:01:5c:6d:22:46:08:00 SRC=193.32.161.55 DST=[redacted] LEN=40 TOS=0x00 PREC=0x00 TTL=235 ID=13196 PROTO=TCP SPT=47800 DPT=3392 SEQ=2452949795 ACK=0 WINDOW=1024 RES=0x00 SYN URGP=0 MARK=0x8000000

My very amateur guess is that when the skynet-0.log is deleted and restarted, for some reason the hourly report goes to /opt/var/log/messages but somehow misses the GUI. Syslog-ng is new, very obtuse (to me), and scripting is really hard for me to comprehend (as you see).

Thanks for the replies and help, very appreciated.

If syslog.log is still symlinked to messages, it can't miss the GUI. The GUI is literally reading the messages file through the symlink.

 

[cmkelley]

My system has been running for over a day now with my new setup as per my last post. ie NOT killing klogd, and all is working well.

From my reading /proc/kmsg is basically a special one time read 'file', so if syslog-ng is trying to read it, AND klogd is running you will get the garbled messages. I did have an issue when first testing where klogd got restarted at some point, so seeing as klogd consumes so little mem/cpu, it seems more stable to leave it running (than cron a watchdog type script to kill it) and just not source /proc/kmsg in syslog-ng.

I simply commented out the whole source kernel {} directive in syslog-ng.conf,

#source kernel {
    #file("/proc/kmsg" program_override("Kernel") flags(kernel) keep-timestamp(no));
#};

and

log {
    source(src);
    #source(kernel);
    destination(messages);
};

then sent killall -HUP syslog-ng, and haven't missed a beat since.

Then I commented the source(kernel); line in the log section of each file under /opt/etc/syslog-ng.d/ also.

Should be pretty easy for scribe to make those changes seeing as it installs it's own small syslog-ng.conf file, or use sed on the larger file if selected during install.

Thanks @cmkelley for getting me started on a nice project!

So, I'm VERY reluctant to touch the provided syslog-ng.conf file. I'll likely automatically install the non-scl one and have a message about problems with the file provided with the package.

The other way to ensure klogd stays dead is to install a zero-length file at /opt/sbin/klogd - I'm pretty sure the firmware doesn't specify the path to klogd so it would try to run the non-functioning one. I don't know if it starts klogd before mounting the usb, so I'd definitely at least try to kill klogd at the same time I kill syslogd.

I'm pretty torn between letting klogd run and removing the kernel source from syslog-ng.conf or just killing klogd.


Also probably going to require syslog-ng 3.19 or higher since the non-scl file has a 3.19 version stamp anyways. Any fresh install should be getting 3.19 or higher from opkg anyways.

 

[cmkelley]

My system has been running for over a day now with my new setup as per my last post. ie NOT killing klogd, and all is working well.

From my reading /proc/kmsg is basically a special one time read 'file', so if syslog-ng is trying to read it, AND klogd is running you will get the garbled messages. I did have an issue when first testing where klogd got restarted at some point, so seeing as klogd consumes so little mem/cpu, it seems more stable to leave it running (than cron a watchdog type script to kill it) and just not source /proc/kmsg in syslog-ng.

I simply commented out the whole source kernel {} directive in syslog-ng.conf,

#source kernel {
    #file("/proc/kmsg" program_override("Kernel") flags(kernel) keep-timestamp(no));
#};

and

log {
    source(src);
    #source(kernel);
    destination(messages);
};

then sent killall -HUP syslog-ng, and haven't missed a beat since.

Then I commented the source(kernel); line in the log section of each file under /opt/etc/syslog-ng.d/ also.

Should be pretty easy for scribe to make those changes seeing as it installs it's own small syslog-ng.conf file, or use sed on the larger file if selected during install.

Thanks @cmkelley for getting me started on a nice project!

Can you do me a favor? Leave source kernel commented out, and change source src to:

source src {
    system();
    internal();
};

and restart syslog-ng (scribe restart or killall -HUP syslog-ng) see if everything still comes through correctly.