Scribe scribe - syslog-ng and logrotate installer

[kernol]

Got the first skynet summary in the log since time-reap change - [23:00hrs] - will let you know in the morning whether it kept going overnight.

@elorimer - your suggestion spot on - hourly summary now working because of time-reap set to 2 seconds instead of default 60.

Nov 12 23:00:02 RT-AC86U-8178 Skynet: [#] 127680 IPs (+1) -- 1684 Ranges Banned (+0) || 45 Inbound -- 0 Outbound Connections Blocked! [save] [2s]
Nov 13 00:00:03 RT-AC86U-8178 Skynet: [#] 127680 IPs (+0) -- 1684 Ranges Banned (+0) || 149 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Nov 13 01:00:03 RT-AC86U-8178 Skynet: [#] 127680 IPs (+0) -- 1684 Ranges Banned (+0) || 270 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Nov 13 02:00:02 RT-AC86U-8178 Skynet: [#] 127680 IPs (+0) -- 1684 Ranges Banned (+0) || 381 Inbound -- 0 Outbound Connections Blocked! [save] [2s]
Nov 13 03:00:02 RT-AC86U-8178 Skynet: [#] 127680 IPs (+0) -- 1684 Ranges Banned (+0) || 523 Inbound -- 0 Outbound Connections Blocked! [save] [2s]
Nov 13 04:00:03 RT-AC86U-8178 Skynet: [#] 127680 IPs (+0) -- 1684 Ranges Banned (+0) || 643 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Nov 13 05:00:03 RT-AC86U-8178 Skynet: [#] 127680 IPs (+0) -- 1684 Ranges Banned (+0) || 765 Inbound -- 0 Outbound Connections Blocked! [save] [3s]

 

[kernol]

Taking this in a slightly different direction. I am not sure I follow why for skynet we need hourly summaries in the first place, and why we need to purge the logs in skynet. If we ran the cron daily instead of hourly, what do we lose?

And then, if we wanted to purge the logs, why not use logrotate? I can see the skynet log getting very large and bogging down uiScribe's display, but we could run logrotate hourly, or for that matter exclude the messages that will get purged hourly and rotate them off.

Thinking about this only because I have a guess that the ax88 might run the hourly save in less than a second, so even time-reap(1) will be too long.

Your logic on using logrotate for skynet seems sound to me.
I have however noticed that, since changing time-reap to 2 seconds - the "event.log" in skynet's own log folder no longer gets populated with the hourly summary line?

 

[cmkelley]

Taking this in a slightly different direction. I am not sure I follow why for skynet we need hourly summaries in the first place, and why we need to purge the logs in skynet. If we ran the cron daily instead of hourly, what do we lose?

And then, if we wanted to purge the logs, why not use logrotate? I can see the skynet log getting very large and bogging down uiScribe's display, but we could run logrotate hourly, or for that matter exclude the messages that will get purged hourly and rotate them off.

Thinking about this only because I have a guess that the ax88 might run the hourly save in less than a second, so even time-reap(1) will be too long.

The first thing to remember is Skynet HAS to work with the standard syslogd - us syslog-ng users are a "nice to have" as I'm sure we're a tiny minority of Skynet users.. The reasons for scraping the log and leaving the hourly summaries are almost certainly part of that - move the skynet logs to their own file for analysis, but leave the hourly status in the log as evidence it ran. There is no reason for Adamm to have 2 different log parsing routines, one for syslogd, and one for syslog-ng. I'm personally really, really please he went out of his way to enable us syslog-ng users to have the log in a different place.

I'm kinda guessing in very very dim light here, but I think a too-long time_reap depends almost exclusively on the rate of incoming messages. I don't follow your reasoning of how a faster router would have a shorter "too long".

At any rate, in an attempt to be more scientific about it, I used an awk string (that BB won't let me even paste in a "code" block) to generate a list of just the incoming message times into excel, and then calculated the time between messages. I looked at the average, sample standard deviation, min, max, mode, and a historgram. And I surrender.

time_reap(2) is probably as reasonable as any number between about 1 and 6. The average for me was 14 seconds for all day yesterday, but the sample standard deviation was also 14 seconds. The histogram showed the most common time difference is (surprise, surprise) zero. And it's a pretty steep descent from there. I was surprised to see the maximum interval was over 2 minutes.

So I'll be updating GitHub to time_reap(2), and probably code in a hack to add time_reap(2) to everyone's Skynet filter if it exists in /opt/etc/syslog-ng.d since those aren't automatically updated. I think that means I have to make syslog-ng 3.23 the minimum required now.

 

[kernol]

Your logic on using logrotate for skynet seems sound to me.
I have however noticed that, since changing time-reap to 2 seconds - the "event.log" in skynet's own log folder no longer gets populated with the hourly summary line?

Pleased to confirm that a reboot of the router gathered the hourly summaries and placed them in the event.log in the skynet folder.
So everything is now working as designed [with the time-reap setting at 2 seconds].

I agree with @cmkelley post above about keeping the full functionality of syslogd for those not using scribe - however I think @elorimer was suggesting that logrotate.d functionality could be deployed in skynet as a means of controlling and rotating its own logs - whether scribe deployed or not?

I do appreciate the hourly summaries in skynet.

 

[cmkelley]

Pleased to confirm that a reboot of the router gathered the hourly summaries and placed them in the event.log in the skynet folder.
So everything is now working as designed [with the time-reap setting at 2 seconds].

I agree with @cmkelley post above about keeping the full functionality of syslogd for those not using scribe - however I think @elorimer was suggesting that logrotate.d functionality could be deployed in skynet as a means of controlling and rotating its own logs - whether scribe deployed or not?

I do appreciate the hourly summaries in skynet.

Getting into Skynet functionality here, but Skynet doesn't rotate the log, it puts all of the entries into 1 file for statistics generation - at least, that's what the skynet.log file appears to do.

 

[cmkelley]

Just pushed v2.2_1.

Turns out I already did code it (intentionally or otherwise) to automatically update the Skynet filter when updating scribe, so everyone running 2.2_0 and hasn't already fixed the Skynet filter to time_reap(2) should download this update and it will fix the Skynet filter for you. time_reap(60) clearly isn't working correctly, I'm beginning to be less than convinced that time_reap(60) accurately replicates the pre-syslog-ng v3.23 behaviour.

And, scribe now requires syslog-ng 3.23 or higher. :-(

EDIT: FAIL!!! No, it doesn't automatically update the Skynet filter. You need to tell scribe to update the filter files either during upgrade or using 'uf' from the menu, then copy the skynet file from /opt/share/syslog-ng/examples to /opt/etc/syslog-ng.d

cp /opt/share/syslog-ng/examples/skynet /opt/etc/syslog-ng.d/skynet

Sorry, next on my list is a mechanism to ask about changes to the files in /opt/etc/syslog-ng.d. I'm considering always forcing updates to /opt/share/syslog-ng/examples and /opt/share/logrotate/examples instead of asking, but I will always ask before overwriting anything in /opt/etc/syslog-ng.d or /opt/etc/logrotate.d.

 

[kernol]

Just pushed v2.2_1.

Turns out I already did code it (intentionally or otherwise) to automatically update the Skynet filter when updating scribe, so everyone running 2.2_0 and hasn't already fixed the Skynet filter to time_reap(2) should download this update and it will fix the Skynet filter for you. time_reap(60) clearly isn't working correctly, I'm beginning to be less than convinced that time_reap(60) accurately replicates the pre-syslog-ng v3.23 behaviour.

And, scribe now requires syslog-ng 3.23 or higher. :-(

Ran the v2.2_1 update - and note that the new skynet filter - time_reap(2) - exists in examples - but is not auto-copied to opt/etc/syslog-ng.d/
Not sure if that is intentional - but users need to copy it there manually as it stands.

 

[elorimer]

I'm kinda guessing in very very dim light here, but I think a too-long time_reap depends almost exclusively on the rate of incoming messages. I don't follow your reasoning of how a faster router would have a shorter "too long".

I take your point. It is entirely a question of whether a message arrives within the time-reap interval before the sed rename occurs, regardless of how long the Purge_Logs function takes. The evidence is that the hourly message is skipped.

Impressive statistical sleuthing!

The syslog-ng folks suggest starting a new log every hour (adding the HOUR macro to the name), so syslog-ng is never writing to the log skynet is operating on. I don't think we are going to go there.

EDIT: Putting this here for historical reference: there is also a destination definition of pseudofile(), which opens a file and immediately closes it. It doesn't work for us (don't ask, trust me).

 

[bitmonster]

running Merlin with Diversion and Skynet happily running. Tried installing this and got an error at the end.... any thoughts?

Also, I just set up Visual Syslog for Windows but nothing is showing. I did get a whole heap of errors starting up that various /appdata configs couldn't be read though (I guess I'll have to follow that up separately). But should this automatically be sending log data via port 514?

uiScribe: Welcome to uiScribe v1.1.0, a script by JackYaz

uiScribe: Checking your router meets the requirements for uiScribe

uiScribe: uiScribe installed successfully!


checking syslog-ng daemon ... alive.

checking system for necessary scribe hooks ...

checking S01syslog-ng ... present.
checking service-event ... present.
checking post-mount ... present.
checking unmount ... present.
checking logrotate cron job ... present.
checking directory links ... present.

checking syslog-ng configuration ...

syslog-ng.conf version check ... in sync.
syslog-ng.conf syntax check ... okay!

scribe installed version: v2.2_1 (master)
scribe GitHub version: v2.2_1 (master)
scribe is up to date!



scribe not installed, command "install" not valid!

 

[elorimer]

But should this automatically be sending log data via port 514?

No. If you look in the /opt/etc/syslog-ng.conf file you might see a destination definition that is commented out:

#destination log_server {
#    udp("xxx.xxx.xxx.xxx" port(514));
#};

So that needs to be un-commented out, with your local log server IP inserted.
Then you will need a configuration file in /opt/etc/syslog-ng.d that contains the instruction to send messages to that destination:

log {
    source(src);
    destination(log_server);
};

Note that syslog-ng processes these configuration files in alphabetic order, and scribe is generally built around the idea that each message will be tested against the configuration files, and if they meet a filter, will be sent to the appropriate log and processing of the message will stop. If it meets no filter, it drops to the messages file. This is done by including a flags(final) instruction in each log instruction. So you will want the above configuration file named something like "0logserver", so it will be processed first, to send each message to the log server, and then continue on with processing.

Also, it may suit you to use the built-in logging to port 514 instead of scribe.

 

[elorimer]

I did get a whole heap of errors starting up that various /appdata configs couldn't be read though (I guess I'll have to follow that up separately).

From the other thread I guess you got this working?

 

[elorimer]

The problem is, it can't be closed and a new one created, so it sits empty. Not sure why it goes completely empty, but that may be down to the way Skynet does the close and re-open or maybe the sed operation.

It is suggested by the syslog-ng folks that what is needed is the SIGHUP message like what we use for logrotate:

    /usr/bin/killall -HUP syslog-ng

The idea is that when "firewall save" runs the sed command on syslog-0.log, syslog-ng continues to log to the file formerly known as syslog-0.log, while sed has created a new file with that name. So syslog-ng has to be told to close the old file and reopen to the new file.

That means the hourly cron job for firewall save would need to be a separate script, that first calls firewall save, then sends the SIGHUP message. Or, change the skynet code to send that if syslog-ng is installed. Probably too much to ask @Adamm .

 

[cmkelley]

It is suggested by the syslog-ng folks that what is needed is the SIGHUP message like what we use for logrotate:

    /usr/bin/killall -HUP syslog-ng

The idea is that when "firewall save" runs the sed command on syslog-0.log, syslog-ng continues to log to the file formerly known as syslog-0.log, while sed has created a new file with that name. So syslog-ng has to be told to close the old file and reopen to the new file.

That means the hourly cron job for firewall save would need to be a separate script, that first calls firewall save, then sends the SIGHUP message. Or, change the skynet code to send that if syslog-ng is installed. Probably too much to ask @Adamm .

And as you discovered, by using time_reap(2) it's unnecessary - at most around 2 seconds of messages may be lost. I suppose if you're in an environment where you're getting 10's or 100's of blocks a second, it could be a problem, but in that environment I daresay your router would be useless anyways, I don't think these routers are designed to withstand a DDOS attack.

 

[cmkelley]

Note that syslog-ng processes these configuration files in alphabetic order, and scribe is generally built around the idea that each message will be tested against the configuration files, and if they meet a filter, will be sent to the appropriate log filter and processing of the message will stop. If it meets no filter, it drops to the messages file. This is done by including a flags(final) instruction in each log instruction. So you will want the above configuration file named something like "0logserver", so it will be processed first, to send each message to the log server, and then continue on with processing.

(smacks forehead) Why didn't I think of that?!?

Excellent, I will add an A00remote file (I think I determined with logrotate that's how to ensure it's the first read) to the examples folder in share for people to copy if they want to use a remote log server as well.

Also, for others, note that the above solution will send EVERY log to the remote server, including (if you have an 86U) all the dcd crashes. I think I'll add

#destination(log_server) #uncomment this line to send this log to the remote log server setup in syslog-ng.conf

to all the syslog-ng files in syslog-ng.d and the example files as well with an explanation that un-commenting that line in individual files will allow fine control over which logs go to the remote server.

 

[elorimer]

That looks more elegant than what I did to limit what I was sending to loggly, by reversing the filters:

### Syslog-ng Logging Directives for Loggly.com ###
filter f_loggly1 { not filter("f_pixelserv"); };
filter f_loggly2 { not filter("f_skynet"); };
template LogglyFormat { template("<${PRI}>1 ${ISODATE} ${HOST} ${PROGRAM} ${PID} ${MSGID} [**token** tag=\"56U\" ] $MSG\n");
    template_escape(no);
};
destination d_loggly {
    tcp("logs-01.loggly.com" port(514) template(LogglyFormat));
};
log { 
    source(src); 
    filter(f_loggly1);
    filter(f_loggly2);
    destination(d_loggly); 
};
### END Syslog-ng Logging Directives for Loggly.com ###

 

[bitmonster]

Also, it may suit you to use the built-in logging to port 514 instead of scribe.

Except I couldn't that to work and Scribe already is a huge improvement.

I will configure it for sending messages and see how I go.

From the other thread I guess you got this working?

WRT to Scribe, seems to be, unless that installation issue above means anything.

 

[cmkelley]

running Merlin with Diversion and Skynet happily running. Tried installing this and got an error at the end.... any thoughts?

Also, I just set up Visual Syslog for Windows but nothing is showing. I did get a whole heap of errors starting up that various /appdata configs couldn't be read though (I guess I'll have to follow that up separately). But should this automatically be sending log data via port 514?

uiScribe: Welcome to uiScribe v1.1.0, a script by JackYaz

uiScribe: Checking your router meets the requirements for uiScribe

uiScribe: uiScribe installed successfully!


checking syslog-ng daemon ... alive.

checking system for necessary scribe hooks ...

checking S01syslog-ng ... present.
checking service-event ... present.
checking post-mount ... present.
checking unmount ... present.
checking logrotate cron job ... present.
checking directory links ... present.

checking syslog-ng configuration ...

syslog-ng.conf version check ... in sync.
syslog-ng.conf syntax check ... okay!

scribe installed version: v2.2_1 (master)
scribe GitHub version: v2.2_1 (master)
scribe is up to date!



scribe not installed, command "install" not valid!

Scribe seems to be saying it's installed properly, don't know why it kicked that error, probably a logic error I added along the way when I revamped the re-install code for 2.2_0.

Sure way to check is execute "scribe status". If that doesn't throw any error, scribe is set up properly.

Sorry for the delay responding, I thought I had earlier today.

EDIT: Yep, found the logic error. Harmless. It's installed fine.

 

[bitmonster]

Ah thanks yeah seems to be working fine. Now I will try to set it up to pipe logs back to my PC for live analysis.

 

[cmkelley]

v2.2_2 is out ...
* Mainly fixes the bug (logic error) discovered by @bitmonster that it would erroneously report scribe not installed immediately after installing. It was installing fine, but a flag was not being set correctly.
* Removed the prompt to update filters if scribe update is declined. It just seemed illogical.

If you are using Skynet, and you have not done so already, please copy the updated syslog-ng skynet filter from the examples directory to the syslog-ng.d directory. time_reap(2) must be set in the syslog-ng skynet filter for Skynet logging and statistics generation to work correctly. As RMerlin would say "(out of my control)".

cp /opt/share/syslog-ng/examples/skynet /opt/etc/syslog-ng.d/skynet

Eventually there will be a mechanism to update the syslog-ng.d files when you upgrade, but it has to be a bit more careful and ask on a one-at-a-time basis, so life needs to calm down a bit before I can start coding that.

 

[Goobi]

I got a rather large log file that I would like to rotate so it does not choke http when viewing syslog.

The log file is /opt/var/openvpn.log and is currently 22MBs. How would I go about keeping this file around 4 MBs? I know it would have to do with a filter, but not versed enough to create one.

Any suggestions would be appreciated!