Scribe scribe - syslog-ng and logrotate installer

[Butterfly Bones]

That is why I am going to reinstall scribe and not redirect Skynet logs for now, to see what happens. I'm not sure if or how this will help troubleshoot whatever causes missing hourly reports. That can be pursued later.

What is the quote from H.L. Mencken again??

 

[joe scian]

So this was the only line I had in skynet-0.log after reinstalling.

- Apr 16 15:00:08 RT-AC5300 Skynet[13782]: [#] 146106 IPs (+0) -- 1760 Ranges Banned (+0) || 119 Inbound -- 0 Outbound Connections Blocked! [save] [7s]

I had to restart Scribe to get it to update all Blocked entries. The openvpn.log file has not been created after i moved openvpn from examples to opt/etc/syslog-ng.d/. After connecting to my OpenVPN server I cannot see any ovpn-server1 entries in messages as well. And no openvpn.log file in opt/var/log

still getting these error messages:-

a    TAGS=.source.src#\x0a    FACILITY=kern#\x0a    FACILITY_NUM=0#\x0a    LEVEL=warning#\x0a    LEVEL_NUM=4#\x0a    PRI=4#\x0a    PRIORITY=warning#\x0a    FULLHOST=RT-AC5300#\x0a    FULLHOST_FROM=RT-AC5300#\x0a    HOST=RT-AC5300#\x0a    HOST_FROM=RT-AC5300#\x0a    LOGHOST=RT-AC5300.#\x0a    MSGHDR=kernel: #\x0a    MSGID=#\x0a    MSGONLY=REJECT IN=br0 OUT=wl0.1 SRC=192.168.2.245 DST=192.168.3.186 LEN=60 TOS=0x00 PREC=0x00 TTL=63 ID=18564 DF PROTO=TCP SPT=35196 DPT=55443 SEQ=3826383029 ACK=0 WINDOW=65535 RES=0x00 SYN URGP=0 OPT (020405B40402080A0345B0310000000001030306) #\x0a    MSG=REJECT IN=br0 OUT=wl0.1 SRC=192.168.2.245 DST=192.168.3.186 LEN=60 TOS=0x00 PREC=0x00 TTL=63 ID=18564 DF PROTO=TCP SPT=35196 DPT=55443 SEQ=3826383029 ACK=0 WINDOW=65535 RES=0x00 SYN URGP=0 OPT (020405B40402080A0345B0310000000001030306) #\x0a    MESSAGE=REJECT IN=br0 OUT=wl0.1 SRC=192.168.2.245 DST=192.168.3.186 LEN=60 TOS=0x00 PREC=0x00 TTL=63 ID=18564 DF PROTO=TCP SPT=35196'
[2019-04-16T10:06:35.000452] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T10:06:36.010407] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T10:06:37.020356] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T10:06:38.020386] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T10:06:39.030355] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T10:06:40.030363] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T10:06:41.030366] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T10:06:42.040368] Follow mode file still does not exist; filename='/var/lib/logrotate.status'

[2019-04-16T10:06:19.921171] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T10:06:20.930385] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T10:06:21.940371] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2[2019-04-16T10:06:43.050388] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T10:06:43.393541] Incoming log entry; line='PROTO=TCP SPT=53114 DPT=55443 SEQ=3661446808 ACK=0 WINDOW=65535 RES=0x00 SYN URGP=0 OPT (020405B40402080A162623620000000001030306) '
[2019-04-16T10:06:43.394087] Outgoing message; message='Apr 16 10:06:43 RT-AC5300 kernel: PROTO=TCP SPT=53114 DPT=55443 SEQ=3661446808 ACK=0 WINDOW=65535 RES=0x00 SYN URGP=0 OPT (020405B40402080A162623620000000001030306) \x0a'
[2019-04-16T10:06:43.394355] Outgoing message; message='================================================\x0a    PROGRAM=kernel#\x0a    PID=#\x0a    BSDTAG=5A#\x0a    TAG=05#\x0a    TAGS=.source.src#\x0a    FACILITY=kern#\x0a    FACILITY_NUM=0#\x0a    LEVEL=notice#\x0a    LEVEL_NUM=5#\x0a    PRI=5#\x0a    PRIORITY=notice#\x0a    FULLHOST=RT-AC5300#\x0a    FULLHOST_FROM=RT-AC5300#\x0a    HOST=RT-AC5300#\x0a    HOST_FROM=RT-AC5300#\x0a    LOGHOST=RT-AC5300.#\x0a    MSGHDR=kernel: #\x0a    MSGID=#\x0a    MSGONLY=PROTO=TCP SPT=53114 DPT=55443 SEQ=3661446808 ACK=0 WINDOW=65535 RES=0x00 SYN URGP=0 OPT (020405B40402080A162623620000000001030306) #\x0a    MSG=PROTO=TCP SPT=53114 DPT=55443 SEQ=3661446808 ACK=0 WINDOW=65535 RES=0x00 SYN URGP=0 OPT (020405B40402080A162623620000000001030306) #\x0a    MESSAGE=PROTO=TCP SPT=53114 DPT=55443 SEQ=3661446808 ACK=0 WINDOW=65535 RES=0x00 SYN URGP=0 OPT (020405B40402080A162623620000000001030306) #\x0a    SOURCE=src#\x0a    SOURCEIP=127.0.0.1#\x0a    SOURCE_IP=#\x0a    SEQNUM=6#\x0a    UNIXTIME=1555409203#\x0a    FULLDAT

OK so I left it overnight come back this morning and the openvpn.log file has been created and last nights openvpn log entries are all there - no problem. So maybe I didnt wait long enough ? who knows i waited over an hour for that file to be created - but its all happening as it should for now. Thanks to all.

 

[joe scian]

Hi elorimer here is output -d

Another thing you could do is run logrotate manually and see what happens:

/opt/sbin/logrotate -d /opt/etc/logrotate.conf

Using -d will just print debug messages without actually running; -v will run and give you the messages.

joescian@RT-AC5300:/tmp/home/root# /opt/sbin/logrotate -d /opt/etc/logrotate.con
f
WARNING: logrotate in debug mode does nothing except printing debug messages!  Consider using verbose mode (-v) instead if this is not what you want.

reading config file /opt/etc/logrotate.conf
including /opt/etc/logrotate.d
reading config file A00global
reading config file crash
reading config file logrotate
reading config file messages
reading config file syslogng
Reading state from file: /var/lib/logrotate.status
Allocating hash table for state file, size 64 entries
Creating new state
Creating new state
Creating new state
Creating new state

Handling 4 logs

rotating pattern: /opt/var/log/crash.log  after 1 days (4 rotations)
empty log files are not rotated, only log files >= 4194304 bytes are rotated, old logs are removed
considering log /opt/var/log/crash.log
  log /opt/var/log/crash.log does not exist -- skipping
not running postrotate script, since no logs were rotated

rotating pattern: /opt/var/log/logrotate.log  weekly (4 rotations)
empty log files are not rotated, only log files >= 262144 bytes are rotated, old logs are removed
considering log /opt/var/log/logrotate.log
  Now: 2019-04-16 22:31
  Last rotated at 2019-04-17 00:00
  log does not need rotating (log has been rotated at 2019-4-17 0:0, that is not week ago yet)
  log does not need rotating ('minsize' directive is used and the log size is smaller than the minsize value)
not running postrotate script, since no logs were rotated

rotating pattern: /opt/var/log/messages  after 1 days (9 rotations)
empty log files are not rotated, only log files >= 1048576 bytes are rotated, old logs are removed
considering log /opt/var/log/messages
  Now: 2019-04-16 22:31
  Last rotated at 2019-04-17 00:00
  log needs rotating
rotating log /opt/var/log/messages, log->rotateCount is 9
dateext suffix '-20190416'
glob pattern '-[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9]'
glob finding logs to compress failed
glob finding old rotated logs failed
renaming /opt/var/log/messages to /opt/var/log/messages-20190416
creating new /opt/var/log/messages mode = 0600 uid = 0 gid = 0
running postrotate script
running script with args /opt/var/log/messages  (null): "
        /usr/bin/killall -HUP syslog-ng
"

rotating pattern: /opt/var/log/syslog-ng.log  weekly (4 rotations)
empty log files are not rotated, old logs are removed
considering log /opt/var/log/syslog-ng.log
  Now: 2019-04-16 22:31
  Last rotated at 2019-04-17 00:00
  log does not need rotating (log has been rotated at 2019-4-17 0:0, that is not week ago yet)
not running postrotate script, since no logs were rotated
joescian@RT-AC5300:/tmp/home/root#
joescian@RT-AC5300:/tmp/home/root#
joescian@RT-AC5300:/tmp/home/root#

 

[joe scian]

-v output

/opt/sbin/logrotate -v /opt/etc/logrotate.con
f
reading config file /opt/etc/logrotate.conf
including /opt/etc/logrotate.d
reading config file A00global
reading config file crash
reading config file logrotate
reading config file messages
reading config file syslogng
Reading state from file: /var/lib/logrotate.status
Allocating hash table for state file, size 64 entries
Creating new state
Creating new state
Creating new state
Creating new state

Handling 4 logs

rotating pattern: /opt/var/log/crash.log  after 1 days (4 rotations)
empty log files are not rotated, only log files >= 4194304 bytes are rotated, old logs are removed
considering log /opt/var/log/crash.log
  log /opt/var/log/crash.log does not exist -- skipping
not running postrotate script, since no logs were rotated

rotating pattern: /opt/var/log/logrotate.log  weekly (4 rotations)
empty log files are not rotated, only log files >= 262144 bytes are rotated, old logs are removed
considering log /opt/var/log/logrotate.log
  Now: 2019-04-16 22:38
  Last rotated at 2019-04-17 00:00
  log does not need rotating (log has been rotated at 2019-4-17 0:0, that is not week ago yet)
  log does not need rotating ('minsize' directive is used and the log size is smaller than the minsize value)
not running postrotate script, since no logs were rotated

rotating pattern: /opt/var/log/messages  after 1 days (9 rotations)
empty log files are not rotated, only log files >= 1048576 bytes are rotated, old logs are removed
considering log /opt/var/log/messages
  Now: 2019-04-16 22:38
  Last rotated at 2019-04-17 00:00
  log needs rotating
rotating log /opt/var/log/messages, log->rotateCount is 9
dateext suffix '-20190416'
glob pattern '-[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9]'
glob finding logs to compress failed
glob finding old rotated logs failed
renaming /opt/var/log/messages to /opt/var/log/messages-20190416
creating new /opt/var/log/messages mode = 0600 uid = 0 gid = 0
running postrotate script

rotating pattern: /opt/var/log/syslog-ng.log  weekly (4 rotations)
empty log files are not rotated, old logs are removed
considering log /opt/var/log/syslog-ng.log
  Now: 2019-04-16 22:38
  Last rotated at 2019-04-17 00:00
  log does not need rotating (log has been rotated at 2019-4-17 0:0, that is not week ago yet)
not running postrotate script, since no logs were rotated
joescian@RT-AC5300:/tmp/home/root#

 

[elorimer]

@joe scian: I don't see any errors, and I would have thought there would have been when it read the logrotate.status file. Stumped.

 

[joe scian]

I think I may have solved the issue - I had forgotten to move 2 files from examples logrotate - even though I had moved the two files from syslog-ng examples- the two files were openvpn and pixelserv. Now that I moved those two examples to syslog-ng.d i reran the command -d

joescian@RT-AC5300:/tmp/home/root# /opt/sbin/logrotate -d /opt/etc/logrotate.con
f
WARNING: logrotate in debug mode does nothing except printing debug messages!  Consider using verbose mode (-v) instead if this is not what you want.

reading config file /opt/etc/logrotate.conf
including /opt/etc/logrotate.d
reading config file A00global
reading config file crash
reading config file logrotate
reading config file messages
reading config file openvpn
reading config file pixelserv
reading config file syslogng
Reading state from file: /var/lib/logrotate.status
Allocating hash table for state file, size 64 entries
Creating new state
Creating new state
Creating new state
Creating new state

Handling 6 logs

rotating pattern: /opt/var/log/crash.log  after 1 days (4 rotations)
empty log files are not rotated, only log files >= 4194304 bytes are rotated, old logs are removed
considering log /opt/var/log/crash.log
  log /opt/var/log/crash.log does not exist -- skipping
not running postrotate script, since no logs were rotated

rotating pattern: /opt/var/log/logrotate.log  weekly (4 rotations)
empty log files are not rotated, only log files >= 262144 bytes are rotated, old logs are removed
considering log /opt/var/log/logrotate.log
  Now: 2019-04-16 22:44
  Last rotated at 2019-04-17 00:00
  log does not need rotating (log has been rotated at 2019-4-17 0:0, that is not week ago yet)
  log does not need rotating ('minsize' directive is used and the log size is smaller than the minsize value)
not running postrotate script, since no logs were rotated

rotating pattern: /opt/var/log/messages  after 1 days (9 rotations)
empty log files are not rotated, only log files >= 1048576 bytes are rotated, old logs are removed
considering log /opt/var/log/messages
  Now: 2019-04-16 22:44
  Last rotated at 2019-04-16 22:38
  log does not need rotating (log has been already rotated)
not running postrotate script, since no logs were rotated

rotating pattern: /opt/var/log/openvpn.log  monthly (9 rotations)
empty log files are not rotated, old logs are removed
considering log /opt/var/log/openvpn.log
Creating new state
  Now: 2019-04-16 22:44
  Last rotated at 2019-04-16 22:00
  log does not need rotating (log has been already rotated)
not running postrotate script, since no logs were rotated

rotating pattern: /opt/var/log/pixelserv.log  weekly (9 rotations)
empty log files are not rotated, old logs are removed
considering log /opt/var/log/pixelserv.log
  log /opt/var/log/pixelserv.log does not exist -- skipping
Creating new state
not running postrotate script, since no logs were rotated

rotating pattern: /opt/var/log/syslog-ng.log  weekly (4 rotations)
empty log files are not rotated, old logs are removed
considering log /opt/var/log/syslog-ng.log
  Now: 2019-04-16 22:44
  Last rotated at 2019-04-17 00:00
  log does not need rotating (log has been rotated at 2019-4-17 0:0, that is not week ago yet)
not running postrotate script, since no logs were rotated
joescian@RT-AC5300:/tmp/home/root#
joescian@RT-AC5300:/tmp/home/root# /opt/sbin/logrotate -d /opt/etc/logrotate.con
f
WARNING: logrotate in debug mode does nothing except printing debug messages!  Consider using verbose mode (-v) instead if this is not what you want.

reading config file /opt/etc/logrotate.conf
including /opt/etc/logrotate.d
reading config file A00global
reading config file crash
reading config file logrotate
reading config file messages
reading config file openvpn
reading config file pixelserv
reading config file syslogng
Reading state from file: /var/lib/logrotate.status
Allocating hash table for state file, size 64 entries
Creating new state
Creating new state
Creating new state
Creating new state

Handling 6 logs

rotating pattern: /opt/var/log/crash.log  after 1 days (4 rotations)
empty log files are not rotated, only log files >= 4194304 bytes are rotated, old logs are removed
considering log /opt/var/log/crash.log
  log /opt/var/log/crash.log does not exist -- skipping
not running postrotate script, since no logs were rotated

rotating pattern: /opt/var/log/logrotate.log  weekly (4 rotations)
empty log files are not rotated, only log files >= 262144 bytes are rotated, old logs are removed
considering log /opt/var/log/logrotate.log
  Now: 2019-04-16 22:49
  Last rotated at 2019-04-17 00:00
  log does not need rotating (log has been rotated at 2019-4-17 0:0, that is not week ago yet)
  log does not need rotating ('minsize' directive is used and the log size is smaller than the minsize value)
not running postrotate script, since no logs were rotated

rotating pattern: /opt/var/log/messages  after 1 days (9 rotations)
empty log files are not rotated, only log files >= 1048576 bytes are rotated, old logs are removed
considering log /opt/var/log/messages
  Now: 2019-04-16 22:49
  Last rotated at 2019-04-16 22:38
  log does not need rotating (log has been already rotated)
not running postrotate script, since no logs were rotated

rotating pattern: /opt/var/log/openvpn.log  monthly (9 rotations)
empty log files are not rotated, old logs are removed
considering log /opt/var/log/openvpn.log
Creating new state
  Now: 2019-04-16 22:49
  Last rotated at 2019-04-16 22:00
  log does not need rotating (log has been already rotated)
not running postrotate script, since no logs were rotated

rotating pattern: /opt/var/log/pixelserv.log  weekly (9 rotations)
empty log files are not rotated, old logs are removed
considering log /opt/var/log/pixelserv.log
  log /opt/var/log/pixelserv.log does not exist -- skipping
Creating new state
not running postrotate script, since no logs were rotated

rotating pattern: /opt/var/log/syslog-ng.log  weekly (4 rotations)
empty log files are not rotated, old logs are removed
considering log /opt/var/log/syslog-ng.log
  Now: 2019-04-16 22:49
  Last rotated at 2019-04-17 00:00
  log does not need rotating (log has been rotated at 2019-4-17 0:0, that is not week ago yet)
not running postrotate script, since no logs were rotated
joescian@RT-AC5300:/tmp/home/root#

 

[joe scian]

Everything is working as should be - I reran syslog-ng -Fevd and those error messages below are nolonger there. Yippee - Thanks elorimer - even these messages no longer there -
glob finding logs to compress failed
glob finding old rotated logs failed

[2019-04-16T10:06:41.030366] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T10:06:42.040368] Follow mode file still does not exist; filename='/var/lib/logrotate.status'

 

[cmkelley]

after running that command i get these entries at bottom:-

2019-04-16T04:51:33.295819] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T04:51:34.305798] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T04:51:35.305801] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T04:51:36.305805] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T04:51:37.315799] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T04:51:38.315820] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T04:51:39.325794] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T04:51:40.325826] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T04:51:41.335800] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T04:51:42.335855] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T04:51:43.345797] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T04:51:44.345827] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T04:51:45.355813] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T04:51:46.365798] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T04:51:47.365839] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T04:51:48.375795] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T04:51:49.375800] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T04:51:50.385802] Follow mode file still does not exist; filename='/var/lib/logrotate.status'
[2019-04-16T04:51:51.385834] Follow mode file still does not exist; filename='/var/lib/logrotate.status'

everything else working fine

/var/lib/logrotate.status is created by logrotate when it runs (I actually discovered this by accident). So on a fresh install, logrotate hasn't run yet, it runs at 5 minutes after midnight. But after the first night, logrotate.status will be there and it won't complain. The "error" isn't hurting anything, it's just saying that one of the files it's supposed to source (/var/lib/logrotate.status) doesn't exist. That said, I don't know why it isn't similarly complaining about logrotate.daily. That shouldn't exist yet either, and might not for a long time, it doesn't seem to populate unless there's an error of some sourt.

I'll have a think about running logrotate once right after it's installed.

 

[elorimer]

OK so I left it overnight come back this morning and the openvpn.log file has been created and last nights openvpn log entries are all there - no problem. So maybe I didnt wait long enough ? who knows i waited over an hour for that file to be created - but its all happening as it should for now. T

By chance were you using winscp to check? I find it is necessary to refresh the directories, and if I'm looking at a file, refresh the file to see new files/messages.

 

[joe scian]

By chance were you using winscp to check? I find it is necessary to refresh the directories, and if I'm looking at a file, refresh the file to see new files/messages.

yes I was using winscp - latest version to check. Will be aware of that in the future

 

[Butterfly Bones]

Here are my observations of installing and configuring Scribe 0.9_1 yesterday after about 24 hours without it. I used the temporary disable Skynet before install. Install was smooth, I had downloaded the new filter files from GitHub first and used those to update my own to match the new scheme. First thing I noticed is that I had no webGUI syslog entries at all, none over a 5 hour span. Here is the result of "cat /opt/var/log/messages" ( deleted all entries prior to install).

Apr 16 14:13:26 kernel: klogd: exiting
Apr 16 14:13:26 syslogd exiting
Apr 16 14:27:18 RT-AC86U-4608 rc_service[23687]: service 23687:notify_rc restart_firewall
Apr 16 14:27:18 RT-AC86U-4608 custom_script[1]: Running /jffs/scripts/service-event (args: restart firewall) - max timeout = 120s
Apr 16 14:27:18 RT-AC86U-4608 nat[1]: apply nat rules (/tmp/nat_rules_eth0_eth0)
Apr 16 14:27:18 RT-AC86U-4608 custom_script[1]: Running /jffs/scripts/nat-start
Apr 16 14:27:18 RT-AC86U-4608 (install_stubby.sh)[23782]: 23777 Starting Script Execution (checkipv6)
Apr 16 14:27:18 RT-AC86U-4608 custom_script[1]: Running /jffs/scripts/firewall-start (args: eth0)
Apr 16 14:32:33 RT-AC86U-4608 kernel:
Apr 16 14:32:33 RT-AC86U-4608 kernel:
Apr 16 14:48:55 RT-AC86U-4608 kernel:
Apr 16 14:48:56 RT-AC86U-4608 kernel:
Apr 16 15:07:31 RT-AC86U-4608 kernel:
Apr 16 15:07:31 RT-AC86U-4608 kernel:
Apr 16 15:26:53 RT-AC86U-4608 kernel:
Apr 16 15:26:53 RT-AC86U-4608 kernel:
Apr 16 15:43:00 RT-AC86U-4608 kernel:
Apr 16 15:43:00 RT-AC86U-4608 kernel:
Apr 16 16:05:20 RT-AC86U-4608 kernel:
Apr 16 16:05:21 RT-AC86U-4608 kernel:
Apr 16 16:10:33 RT-AC86U-4608 kernel:
Apr 16 16:10:33 RT-AC86U-4608 kernel:
Apr 16 16:15:49 RT-AC86U-4608 kernel:
Apr 16 16:15:49 RT-AC86U-4608 kernel:
Apr 16 16:18:26 RT-AC86U-4608 kernel:
Apr 16 16:18:26 RT-AC86U-4608 kernel:
Apr 16 16:42:13 RT-AC86U-4608 kernel:
Apr 16 16:42:13 RT-AC86U-4608 kernel:
Apr 16 17:03:18 RT-AC86U-4608 kernel:
Apr 16 17:03:18 RT-AC86U-4608 kernel:
Apr 16 17:31:28 RT-AC86U-4608 kernel:
Apr 16 17:31:28 RT-AC86U-4608 kernel:
Apr 16 17:37:39 RT-AC86U-4608 kernel:
Apr 16 17:37:39 RT-AC86U-4608 kernel:
Apr 16 18:03:01 RT-AC86U-4608 kernel:
Apr 16 18:03:01 RT-AC86U-4608 kernel:
Apr 16 18:25:12 RT-AC86U-4608 kernel:
Apr 16 18:25:12 RT-AC86U-4608 kernel:
Apr 16 18:47:55 RT-AC86U-4608 kernel:
Apr 16 18:47:55 RT-AC86U-4608 kernel:
Apr 16 19:03:53 RT-AC86U-4608 kernel:
Apr 16 19:03:53 RT-AC86U-4608 kernel:
Apr 16 19:22:00 RT-AC86U-4608 kernel:
Apr 16 19:22:00 RT-AC86U-4608 kernel:
Apr 16 19:26:34 RT-AC86U-4608 kernel:
Apr 16 19:26:34 RT-AC86U-4608 kernel:
Apr 16 19:27:25 RT-AC86U-4608 kernel:
Apr 16 19:27:25 RT-AC86U-4608 kernel:
Apr 16 19:50:32 RT-AC86U-4608 kernel:
Apr 16 19:50:32 RT-AC86U-4608 kernel:

Is this because of this in v.0.9_0 changelog that I see nothing after "kernel:"?

• related, the source kernel directive has been removed from all syslog-ng files.

The main issue for me is Skynet. As stated I temporarily halted it, in settings and checked the syslog location setting and changed it back from "/opt/var/log/skynet-0.log" to "/tmp/syslog". As I stated earlier, this was an attempt to leave Skynet logs alone and only scrape most other syslog entries with syslog-ng. Bottom line it did not work. Skynet logging of skynet.log and events.log in "/mnt/<USB_name>/skynet/" stopped. Here is what I saw in the events.log, all stopped after install of Scribe.

Apr 16 00:00:03 Skynet: [#] 139383 IPs (+0) -- 1710 Ranges Banned (+0) || 1772 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 16 01:00:03 Skynet: [#] 139383 IPs (+0) -- 1710 Ranges Banned (+0) || 1890 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 16 02:00:03 Skynet: [#] 139383 IPs (+0) -- 1710 Ranges Banned (+0) || 2019 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 16 03:00:03 Skynet: [#] 139383 IPs (+0) -- 1710 Ranges Banned (+0) || 2163 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 16 03:25:22 Skynet: [#] 147960 IPs (+8577) -- 1764 Ranges Banned (+54) || 2216 Inbound -- 0 Outbound Connections Blocked! [banmalware] [21s]
Apr 16 04:00:03 Skynet: [#] 147960 IPs (+0) -- 1764 Ranges Banned (+0) || 2274 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 16 05:00:03 Skynet: [#] 147960 IPs (+0) -- 1764 Ranges Banned (+0) || 2376 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 16 06:00:03 Skynet: [#] 147960 IPs (+0) -- 1764 Ranges Banned (+0) || 2537 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 16 07:00:03 Skynet: [#] 147960 IPs (+0) -- 1764 Ranges Banned (+0) || 2651 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 16 08:00:03 Skynet: [#] 147960 IPs (+0) -- 1764 Ranges Banned (+0) || 2768 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 16 09:00:03 Skynet: [#] 147960 IPs (+0) -- 1764 Ranges Banned (+0) || 2908 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 16 10:00:38 Skynet: [#] 147960 IPs (+0) -- 1764 Ranges Banned (+0) || 3013 Inbound -- 0 Outbound Connections Blocked! [stats] [2s]
Apr 16 11:00:03 Skynet: [#] 147960 IPs (+0) -- 1764 Ranges Banned (+0) || 3129 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 16 12:00:03 Skynet: [#] 147960 IPs (+0) -- 1764 Ranges Banned (+0) || 3252 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 16 13:00:03 Skynet: [#] 147960 IPs (+0) -- 1764 Ranges Banned (+0) || 3375 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 16 14:00:03 Skynet: [#] 147960 IPs (+0) -- 1764 Ranges Banned (+0) || 3498 Inbound -- 0 Outbound Connections Blocked! [save] [3s]

Like joe scian I got the errors running logrotate manually, I know now from the above post by cmkelley that it is understandable so I will not post the captures of those results.

Bottom line for me is the Skynet logging issue, and as I understand that does not occur for others? I know in the past there were many problems getting the syslog-ng by kvic (and ntpd by kvic as well), on the RT-AC86U with the HND chipset. I uninstalled scribe last night to get Skynet logging back.

Apr 16 13:00:03 Skynet: [#] 147960 IPs (+0) -- 1764 Ranges Banned (+0) || 3375 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 16 14:00:03 Skynet: [#] 147960 IPs (+0) -- 1764 Ranges Banned (+0) || 3498 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
===> uninstall scribe and reboot
Apr 16 20:00:05 Skynet: [#] 149020 IPs (+0) -- 1831 Ranges Banned (+0) || 1 Inbound -- 0 Outbound Connections Blocked! [start] [25s]
Apr 16 21:00:03 Skynet: [#] 149020 IPs (+0) -- 1831 Ranges Banned (+0) || 16 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 16 22:00:04 Skynet: [#] 149020 IPs (+0) -- 1831 Ranges Banned (+0) || 136 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 16 23:00:03 Skynet: [#] 149020 IPs (+0) -- 1831 Ranges Banned (+0) || 261 Inbound -- 0 Outbound Connections Blocked! [save] [2s]
Apr 17 00:00:03 Skynet: [#] 149020 IPs (+0) -- 1831 Ranges Banned (+0) || 358 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 17 01:00:03 Skynet: [#] 149020 IPs (+0) -- 1831 Ranges Banned (+0) || 475 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 17 02:00:03 Skynet: [#] 149020 IPs (+0) -- 1831 Ranges Banned (+0) || 579 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 17 02:25:22 Skynet: [#] 150849 IPs (+1829) -- 1791 Ranges Banned (-40) || 613 Inbound -- 0 Outbound Connections Blocked! [banmalware] [22s]

This is not a primary issue for Scribe development and testing. I'm trying to figure out a method to keep at least minimal Skynet logging and use Scribe because I really want to use it for log segregation and to continue to contribute to testing. If someone has suggestions, they would be welcome. Don't let solving my issue get in the way of more important Scribe troubleshooting and progress. Thanks!

 

[elorimer]

@Butterfly Bones, I have the sense you are fighting this too hard. If you let scribe do its thing, you should end up in the right place.

1. Uninstall scribe. Check to see that the /opt/etc/init.d/S01syslog-ng and rc.func.syslog-ng files are gone. Check to see the /opt/etc/logrotate.d and /syslog-ng.d directories are gone. Delete the logs in /opt/var/log EXCEPT for the Dnsmasq logs. Killall syslog-ng.
2. Now, copy the curl instruction from post 1 and install scribe. This is to insure you start with the corrected 0.9.1.
3. run "pidof syslog-ng". You should get two numbers. Run "pidof klogd" and "pidof syslogd"; neither should return a number.
4. In firewall settings, make sure that the custom location is now /opt/var/log/syslog-o.
5. From examples, copy the skynet and openvpn configs back to /opt/etc/syslog-ng.d. Make sure they do not have a kernel source. I don't think you need to bother with logrotate until you've got the rest working.
6. In s01syslog-ng, see that the only source statement that isn't commented out is the src {system(); internal();} statement.
7. Scribe restart. Repeat #3.

Here is the sequence of how the skynet log statements work (I think):

1. Iptables uses the kernel logger to generate its BLOCKED statements. Those go to the /proc/kmsg file. Syslog-ng picks those up using the system() function, adds the timestamp and the host, and then they fall to the skynet config, where they are sent to syslog-o and further processing of that message stops. Other kernel or system log messages are picked up, don't hit one of the separate configs, and get written to /opt/var/log/messages. That message file is symlinked to /tmp/syslog, which appears in the webgui. If skynet is pointed to /tmp/syslog for any reason, this breaks, and almost everything about skynet stats breaks, because what happens next doesn't happen.
2. Hourly, cron runs the /jffs/scripts/firewall save command. That runs the Purge_Logs function in skynet, which takes all the Blocked messages and copies them to the /skynet/skynet.log file and the events.log file. Then it deletes all of those messages from the syslog-0 file. Then, it runs stats, because anytime a command is run, stats is run. Stats reads the skynet.log file, and then prints that hourly stats line to the system logger using the function Print_Log. That message gets picked up by the system() function, and then is sent by syslog-ng to the skynet-0 file. (I confess I'm having a hard time understanding exactly how and what Purge_Logs is doing here, because of the tildes and the !d stuff, and how Print_Log gets called). If you've changed the skynet log location, Purge_Logs will run on the file it reads from the symlink to messages, which doesn't have any skynet messages, and then destroy the symlink, which means the webui doesn't ever see messages again, even though syslog-ng is still running. It also means no lines are written to the skynet.log file and events.log file, and no stats are there to be generated. That will continue until you do scribe restart, which will through a bit of cleverness by @cmkelley, notice that the symlink is gone and reform it. But at the hour it will get broken again, because it doesn't change the skynet setting.

I am not getting an hourly stat message either, but I think that is because one isn't being generated by skynet, not anything to do with this. I'm not sure why.

 

[tomsk]

I haven't had Skynet installed on my router for some time, but i remember having the issue with the destructive sed when the purging was done on tmp/syslog. My solution was just to point Syslog at /opt/var/log/messages instead by changing the relevant lines in the skynet code. From what i can recall it seemed to work.
If Skynet is purging the messages log anyway is there any need to create a separate log for the blocked and dropped messages?

 

[Jack Yaz]

I do wonder if Skynet could leverage the readlink command to be clever with where it operates with sed

@Adamm would the above work?

 

[Butterfly Bones]

I haven't had Skynet installed on my router for some time, but i remember having the issue with the destructive sed when the purging was done on tmp/syslog. My solution was just to point Syslog at /opt/var/log/messages instead by changing the relevant lines in the skynet code. From what i can recall it seemed to work.
If Skynet is purging the messages log anyway is there any need to create a separate log for the blocked and dropped messages?

Yes, that was the issue back a year or so, and that is why @cmkelley worked with @Adamm to enable a custom log location in Skynet, to change from /tmp/syslog.log to /opt/var/log/skynet-0.log.

I get the /opt/var/log/skynet-0.log correctly and use tail to watch it when I want. I don't really care about the stats (event.log) either, but running different reports is broken with the change in skynet logging to /opt/var/log/. These are the ones I use, but with scribe and redirection skynet logs, then they don't work for me.

( sh /jffs/scripts/firewall stats search malware 8.8.8.8 ) Search Malwarelists For Specified IP
( sh /jffs/scripts/firewall stats search manualbans ) Search For All Manual Bans
( sh /jffs/scripts/firewall stats search device reports ) Search Previous Hourly Report History

I use the first and last extensively to ban those rogues that are hitting me continually (I suspect they are working the entire Charter / Spectrum range, not just my IP). I've tried banning ranges and countries, but those take out too many sites that I use or devices on my network use and do not function correctly if blocked. I'm still fine tuning. The middle one I do not use as often. Even if it requires some workarounds on my part to get that info our of redirected skynet-0 log, I can work with that.

@Butterfly Bones, I have the sense you are fighting this too hard. If you let scribe do its thing, you should end up in the right place.

Ha, you got that right! Story of my life, right there.

Thanks for those suggested steps, I will follow them closely and see.

 

[elorimer]

If Skynet is purging the messages log anyway is there any need to create a separate log for the blocked and dropped messages?

I think it would work fine if skynet was pointed to messages instead of its own file, but for the annoyance of an hours worth of BLOCKED messages in the webgui and the hourly stats file. But the hourly stats file could easily be sifted out of the log on its own.

@cmkelley chose to do it this way so I'm honoring his effort.

 

[elorimer]

but running different reports is broken with the change in skynet logging to /opt/var/log/

I'm not following how this happens. The only thing scribe is changing is the syslogloc pointer in skynet, and that only shows up in the Purge_Log function. All the rest of the work operates on the skynetlog and skynetevents pointers.

 

[tomsk]

I think it would work fine if skynet was pointed to messages instead of its own file, but for the annoyance of an hours worth of BLOCKED messages in the webgui and the hourly stats file. But the hourly stats file could easily be sifted out of the log on its own.

@cmkelley chose to do it this way so I'm honoring his effort.

Yeah certainly sifting them to a separate log gets rid of the deluge of webgui messages ( which is one of the happy side effects of using syslog-ng anyway) ... it just seems like a double effort. I think since you worked out what was causing the garbling, either way should produce a good result.

 

[Butterfly Bones]

I'm not following how this happens. The only thing scribe is changing is the syslogloc pointer in skynet, and that only shows up in the Purge_Log function. All the rest of the work operates on the skynetlog and skynetevents pointers.

Makes no sense to me based on that info either. I have reinstalled and ran all the checks you suggested above and all passed and is running as expected, scraping syslog entries to their own logs.

 Restarting syslog-ng ...
 Shutting down syslog-ng...              done.
 Starting syslog-ng...              done.
      Checking syslog-ng daemon... alive.
    Checking logrotate cron job... alive.
         scribe installed version: v0.9_1
            scribe GitHub version: v0.9_1
username@RT-AC86U-4608:/tmp/home/root# pidof syslog-ng
30254 30253
username@RT-AC86U-4608:/tmp/home/root# pidof klogd
username@RT-AC86U-4608:/tmp/home/root# pidof syslogd

Here is what I see, all these captured at about the same time. Note the synet.log and events.log times show they have stopped.

cat /mnt/SNB/skynet/skynet.log

Apr 17 10:54:58 kernel: [BLOCKED - INBOUND] IN=eth0 OUT= MAC=88:d7:f6:1d:46:08:00:01:5c:6d:22:46:08:00 SRC=107.170.194.191 DST=71.93.53.239 LEN=40 TOS=0x00 PREC=0x00 TTL=244 ID=54321 PROTO=TCP SPT=42685 DPT=6066 SEQ=3082961209 ACK=0 WINDOW=65535 RES=0x00 SYN URGP=0 MARK=0x8000000
Apr 17 10:55:02 kernel: [BLOCKED - INBOUND] IN=eth0 OUT= MAC=88:d7:f6:1d:46:08:00:01:5c:6d:22:46:08:00 SRC=124.166.240.130 DST=71.93.53.239 LEN=44 TOS=0x00 PREC=0x00 TTL=236 ID=13086 PROTO=TCP SPT=54192 DPT=9001 SEQ=2154112472 ACK=0 WINDOW=1024 RES=0x00 SYN URGP=0 OPT (020405B4) MARK=0x8000000
Apr 17 10:55:21 kernel: [BLOCKED - INBOUND] IN=eth0 OUT= MAC=88:d7:f6:1d:46:08:00:01:5c:6d:22:46:08:00 SRC=89.248.174.193 DST=71.93.53.239 LEN=40 TOS=0x00 PREC=0x00 TTL=237 ID=54321 PROTO=TCP SPT=51409 DPT=17148 SEQ=4241925164 ACK=0 WINDOW=65535 RES=0x00 SYN URGP=0 MARK=0x8000000
Apr 17 10:55:27 kernel: [BLOCKED - INBOUND] IN=eth0 OUT= MAC=88:d7:f6:1d:46:08:00:01:5c:6d:22:46:08:00 SRC=185.176.26.101 DST=71.93.53.239 LEN=40 TOS=0x00 PREC=0x00 TTL=238 ID=37229 PROTO=TCP SPT=51629 DPT=14977 SEQ=522886659 ACK=0 WINDOW=1024 RES=0x00 SYN URGP=0 MARK=0x8000000
Apr 17 10:55:46 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.229 DST=71.93.53.239 LEN=40 TOS=0x00 PREC=0x00 TTL=241 ID=1590 PROTO=TCP SPT=41408 DPT=10555 SEQ=3715111650 ACK=0 WINDOW=1024 RES=0x00 SYN URGP=0 MARK=0x8000000
Apr 17 10:55:59 kernel: [BLOCKED - INVALID] IN=eth0 OUT= MAC=88:d7:f6:1d:46:08:00:01:5c:6d:22:46:08:00 SRC=41.45.108.147 DST=71.93.53.239 LEN=40 TOS=0x00 PREC=0x00 TTL=41 ID=55024 PROTO=TCP SPT=33039 DPT=2323 SEQ=1197290991 ACK=0 WINDOW=53589 RES=0x00 SYN URGP=0 MARK=0x8000000

cat /mnt/SNB/skynet/events.log

Apr 17 06:00:03 Skynet: [#] 150849 IPs (+0) -- 1791 Ranges Banned (+0) || 974 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 17 06:52:08 Skynet: [#] 150849 IPs (+0) -- 1791 Ranges Banned (+0) || 1072 Inbound -- 0 Outbound Connections Blocked! [stats] [3s]
Apr 17 07:00:03 Skynet: [#] 150849 IPs (+0) -- 1791 Ranges Banned (+0) || 1090 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 17 08:00:03 Skynet: [#] 150849 IPs (+0) -- 1791 Ranges Banned (+0) || 1209 Inbound -- 0 Outbound Connections Blocked! [save] [3s]
Apr 17 09:00:03 Skynet: [#] 150849 IPs (+0) -- 1791 Ranges Banned (+0) || 1327 Inbound -- 0 Outbound Connections Blocked! [save] [3s]

cat /opt/var/log/skynet-0.log

Apr 17 11:48:43 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=92.118.37.61 DST=71.93.53.239 LEN=40 TOS=0x00 PREC=0x00 TTL=237 ID=31473 PROTO=TCP SPT=50400 DPT=8489 SEQ=2505076279 ACK=0 WINDOW=1024 RES=0x00 SYN URGP=0 MARK=0x8000000
Apr 17 11:49:18 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=46.101.105.47 DST=71.93.53.239 LEN=40 TOS=0x00 PREC=0x00 TTL=49 ID=47563 PROTO=TCP SPT=40020 DPT=23 SEQ=1197290991 ACK=0 WINDOW=36622 RES=0x00 SYN URGP=0 MARK=0x8000000
Apr 17 11:49:35 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=217.182.173.8 DST=71.93.53.239 LEN=40 TOS=0x00 PREC=0x00 TTL=236 ID=22766 PROTO=TCP SPT=42123 DPT=443 SEQ=3845418170 ACK=0 WINDOW=1024 RES=0x00 SYN URGP=0 MARK=0x8000000
Apr 17 11:50:15 RT-AC86U-4608 kernel: [BLOCKED - INVALID] IN=eth0 OUT= MAC=88:d7:f6:1d:46:08:00:01:5c:6d:22:46:08:00 SRC=58.209.66.245 DST=71.93.53.239 LEN=40 TOS=0x00 PREC=0x00 TTL=45 ID=50461 PROTO=TCP SPT=6 DPT=5431 SEQ=0 ACK=0 WINDOW=65535 RES=0x00 SYN URGP=0 MARK=0x8000000
Apr 17 11:50:18 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.231 DST=71.93.53.239 LEN=40 TOS=0x00 PREC=0x00 TTL=242 ID=57238 PROTO=TCP SPT=42623 DPT=14141 SEQ=1645927748 ACK=0 WINDOW=1024 RES=0x00 SYN URGP=0 MARK=0x8000000

Now the webGUI is showing exactly what is in /opt/var/log/messages. Yesterday nothing displayed in webGUI after scribe install. I will leave everything alone and research more on getting Skynet debug stats to work for me.

Thanks for the push!

 

[elorimer]

@Butterfly Bones, now that you have free time, perhaps you would describe what you've done with loggly? I haven't dug into it myself but I know you spent some time customizing your charts and I'd like to go to school on what you did.