Scribe scribe - syslog-ng and logrotate installer

[cmkelley]

Okay, as a test I only copied the new 'diversion' file to the /opt/etc/syslog-ng.d/ directory.

No log file created in the /opt/var/log/ directory. I force updated Diversion, but still, nothing shows up.

'scribe status' at least shows everything still working.

Diversion doesn't log unless you tell it to. Select ds from the menu, then use 1 to enable logging. The manual should be consulted for the settings of the options.

As @Butterfly Bones mentioned, they skynet and firewall filters are not to be used together. It's more like skynet and not-skynet.

Log files aren't created until there's something to log to them. So if there are no openvpn events. then openvpn.log won't appear.

@Butterfly Bones, the log-append line in the custom config section shouldn't be used when using the openvpn filter in syslog-ng. That bypasses the system logging daemon (i.e. syslog-ng).

 

[Butterfly Bones]

@Butterfly Bones, the log-append line in the custom config section shouldn't be used when using the openvpn filter in syslog-ng. That bypasses the system logging daemon (i.e. syslog-ng).

Ah ha! I never looked that close, and I have had the log-append in the VPN client since day one. Now that you say this and I look closely, I am getting duplicate messages (note the difference in timestamp).

May  4 10:45:15 RT-AC86U-4608 ovpn-server1[3700]: OpenVPN 2.4.7 arm-buildroot-linux-gnueabi [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on May  2 2019
May  4 10:45:15 RT-AC86U-4608 ovpn-server1[3700]: library versions: OpenSSL 1.1.1b  26 Feb 2019, LZO 2.08
Sat May  4 10:45:15 2019 OpenVPN 2.4.7 arm-buildroot-linux-gnueabi [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on May  2 2019
Sat May  4 10:45:15 2019 library versions: OpenSSL 1.1.1b  26 Feb 2019, LZO 2.08

 

[L&LD]

Diversion doesn't log unless you tell it to. Select ds from the menu, then use 1 to enable logging. The manual should be consulted for the settings of the options.

As @Butterfly Bones mentioned, they skynet and firewall filters are not to be used together. It's more like skynet and not-skynet.

Log files aren't created until there's something to log to them. So if there are no openvpn events. then openvpn.log won't appear.

@Butterfly Bones, the log-append line in the custom config section shouldn't be used when using the openvpn filter in syslog-ng. That bypasses the system logging daemon (i.e. syslog-ng).

Thank you! I will look into the Diversion settings and have just now removed firewall from /opt/etc/syslog-ng.d/.

 

[cmkelley]

Thank you! I will look into the Diversion settings and have just now removed firewall from /opt/etc/syslog-ng.d/.

Hmmm, after playing with that some, it just affects the dnsmasq logging. You can make that go crazy.

 

[L&LD]

Hmmm, after playing with that some, it just affects the dnsmasq logging. You can make that go crazy.

Just to be clear, the Diversion settings, correct?

 

[cmkelley]

Just to be clear, the Diversion settings, correct?

Yes, sorry, ds on the Diversion menu appears to only increase the dnsmasq logging.

 

[elorimer]

My suggestion about pixelserv: if it is running ok, you don't need to enable logging beyond 1 to get the stat from its web server. If, and only if, you want to scrape the more detailed stats from broken connections via email (that script isn't here) then enable logging at 2, and use the pixelserv filter to get all of it out of messages.

My suggestion about diversion: don't run that filter. Leave the very few messages in messages as a sign of life.

I use the openvpn filter to scrape out the spurious efforts from the log, and skynet to get the last hours (temporary) messages out of messages. But that's it, very minimal.

 

[cmkelley]

Stick a fork in it, it's released. v1.0_0 is on GitHub.

Notable change from the last Beta is I removed the check-syntax command. "scribe status" does that anyways.

Added a README in /opt/share/syslog-ng/examples describing the filters contained therein.

And if you really can't stand the banner when running scribe, set the environment variable "SCRIBE_LOGO" to "nologo" and it will suppress the banner.

 

[Goobi]

Stick a fork in it, it's released. v1.0_0 is on GitHub.

Notable change from the last Beta is I removed the check-syntax command. "scribe status" does that anyways.

Added a README in /opt/share/syslog-ng/examples describing the filters contained therein.

And if you really can't stand the banner when running scribe, set the environment variable "SCRIBE_LOGO" to "nologo" and it will suppress the banner.

Just tried updating and it seems like it is having issues access the package:

 

[cmkelley]

Just tried updating and it seems like it is having issues access the package:

You need to whitelist "codeload.github.com" in Diversion.

 

[Martineau]

Just a quick question if I may?

Can you please explain your design decision to place your script in '/jffs/scripts/service-event'?

It appears for any service request such as

service restart_dnsmasq

or

service restart_httpd

your script executes

RT-AC68U service-event[25400_***DEBUG]: + /jffs/scripts/scribe kill-logger nologo dnsmasq

RT-AC68U service-event[29919_***DEBUG]: + /jffs/scripts/scribe kill-logger nologo httpd

Does 'scribe kill-logger' need to run for every service event?

 

[elorimer]

Does 'scribe kill-logger' need to run for every service event?

To butt in, I think this is something on the list to be reexamined after the dust settles on 384.11. Something seemed to be restarting klogd on a service event, and early betas seemed to start it on every service event. Later betas, and I think the final, are more parsimonious. It also is something that I think was affecting the HND routers; my 87U hasn't restarted a service in weeks, so I wasn't seeing the same behavior anyway.

 

[Martineau]

To butt in, I think this is something on the list to be reexamined after the dust settles on 384.11. Something seemed to be restarting klogd on a service event, and early betas seemed to start it on every service event. Later betas, and I think the final, are more parsimonious. It also is something that I think was affecting the HND routers; my 87U hasn't restarted a service in weeks, so I wasn't seeing the same behavior anyway.

Thanks for the feedback - so for 'scribe' environments, this is deemed a work-around, although passing an inappropriate arg to scribe is very untidy!

I fully concur, relying on a totally random (unrelated) service-event (which on 'quiet' systems may be very infrequent) to fix 3rd-party script environments seems doomed to fail.

NOTE: My service-event script is based on the openvpn-event template (with if-then-else logic) so appending such lines onto the end of the script is (in my environment) inapt.

 

[elorimer]

so for 'scribe' environments, this is deemed a work-around, although passing an inappropriate arg to scribe is very untidy!

Not so fast; you make me regret butting in. There is also the question of backward compatibility with pre 384.11, the difference in the kernels in use and how klogd operates, syslog-ng's handling of kmsg, and @Cam's concern that klogd may do more than deliver messages from kernel space to user space. It didn't make a lot of sense to delve into that until 384.11 settled, and now we can.

Also, I think @cmkelley's work here helped inform the final version of 384.11; it also got us a much better understanding of syslog-ng in a Merlin environment. We'd been doing it wrong.

 

[cmkelley]

Just a quick question if I may?

Can you please explain your design decision to place your script in '/jffs/scripts/service-event'?

It appears for any service request such as

service restart_dnsmasq

or

service restart_httpd

your script executes

RT-AC68U service-event[25400_***DEBUG]: + /jffs/scripts/scribe kill-logger nologo dnsmasq

RT-AC68U service-event[29919_***DEBUG]: + /jffs/scripts/scribe kill-logger nologo httpd

Does 'scribe kill-logger' need to run for every service event?

Well, it loads the script, which then checks to see if the service being called is either "logger" or "time" (both of which are known to restart syslogd & klogd). If the service is neither of the two, it exists. If it is one of the two, then I drop into the routine to kill syslogd & klogd. That's why I pass the service along. A couple things drove this decision:

1. The script writers have a gentleperson's agreement to only add single lines to the firmware scripts in /jffs/scripts to call our scripts, which means either do it this way or with a single-line if-then statement
2. The possibility that in later versions of the firmware, other services may restart syslogd & klogd, so rather than have to update the line in service-start, I'd only have to change scribe
3. @Jack Yaz does it that way (sorry for throwing you under the bus Jack!)

But yes, you are correct, scribe runs every time service-event is called.

FYI, my current service-event:

#!/bin/sh

# Called before a service event is called (e.g. restart_httpd, restart_wireless, etc...).
# First argument is the event (typically stop, start or restart), second argument is the
# target (wireless, httpd, etc...). This is a blocking script, meaning that it will
# prevent the execution of the event itself until the script either completes or times out.

logger -t "SCRIPT_$( basename $0 )" "started [$@]"
printf "$( date ) \taction: $1 \ttarget: $2 \t(service-event)\n" >> /opt/var/log/services.log

/jffs/scripts/entware-service "$1" "$2" & # service ACTION_TARGET for Entware

/jffs/scripts/scribe kill-logger nologo "$2" & # added by scribe

/jffs/scripts/YazFi bounceclients "$1" "$2" & # YazFi Guest Networks

/jffs/scripts/ntpmerlin generate "$1" "$2" & # ntpMerlin

/jffs/scripts/connmon generate "$1" "$2" & # connmon

/jffs/scripts/uiDivStats generate "$1" "$2" & # uiDivStats

#eof

Lots of stuff gets called at every service event.

 

[Jack Yaz]

1. @Jack Yaz does it that way (sorry for throwing you under the bus Jack!)

While I would prefer to evaluate which service is called in service-event, the agreed approach is that scripts should add just a single line to any "system" scripts.

So we're both sticking to the community scripter guidelines

 

[cmkelley]

To butt in, I think this is something on the list to be reexamined after the dust settles on 384.11. Something seemed to be restarting klogd on a service event, and early betas seemed to start it on every service event. Later betas, and I think the final, are more parsimonious. It also is something that I think was affecting the HND routers; my 87U hasn't restarted a service in weeks, so I wasn't seeing the same behavior anyway.

To be blunt, no.

What restarts syslogd and klogd hasn't changed in a long time, I just didn't understand Merlin when he tried to tell me that "time" restarted them in addition to "logger". When called with kill-logger, scribe checks the argument passed with it to see if it is one of the known events that restart them. If it isn't then it terminates. I'm always doing something to my router, so I can't comment on the frequency of service events. The only thing affecting HND vs non-HND routers was syslog-ng expanding the system() source.

 

[cmkelley]

Not so fast; you make me regret butting in. There is also the question of backward compatibility with pre 384.11, the difference in the kernels in use and how klogd operates, syslog-ng's handling of kmsg, and @Cam's concern that klogd may do more than deliver messages from kernel space to user space. It didn't make a lot of sense to delve into that until 384.11 settled, and now we can.

Also, I think @cmkelley's work here helped inform the final version of 384.11; it also got us a much better understanding of syslog-ng in a Merlin environment. We'd been doing it wrong.

As far as I'm concerned, the way it works now is the way it's going to stay unless the script writers mafia (kidding guys, kidding!) or RMerlin convince me otherwise. I honestly don't have the personal bandwidth to try to further optimize the system() / klogd / kmsg logging issue, unless someone can demonstrate that klogd does something that interrogating /proc/kmsg doesn't. Everything I've read leads me to believe that klogd just passes messages from /proc/kmsg to the system logging daemon.

I maintain backward compatibility by not using service-event-end. If I'm feeling REALLY adventurous someday I might include a check on which firmware is in use and put the call in service-event-end if 384.11 or above.

All I did for 384.11 is find an obscure bug where service-event-end wasn't being called when the webgui initiated a "restart time" service call. It probably wouldn't have affected anyone for months if not years.

 

[RMerlin]

All I did for 384.11 is find an obscure bug where service-event-end wasn't being called when the webgui initiated a "restart time" service call. It probably wouldn't have affected anyone for months if not years.

That's not what the bug was. The bug was service-event-end was not called if httpd chained multiple events in one single request (i.e. restart_dnsmasq;restart_firewall for example would have skipped it).

That was fixed by moving the script execution within the inner loop, so as rc splits the request into multiple events, each event will call service-event-end with its specific event.

 

[cmkelley]

That's not what the bug was. The bug was service-event-end was not called if httpd chained multiple events in one single request (i.e. restart_dnsmasq;restart_firewall for example would have skipped it).

That was fixed by moving the script execution within the inner loop, so as rc splits the request into multiple events, each event will call service-event-end with its specific event.

Ahh, see, I'm not even smart enough to know what the bug was.