Scribe Log entry fragments in Scribe

[TheStork]

I‘ve noticed that my log (using Scribe) under ‘system messages’ category is full of strange entries that look like incomplete log lines. I think they might be part of entries that should fall under Skynet’s log entries for inbound blocks, but it seems they are missed from that and partly chopped in the process. Below are a couple of examples of these log fragments, including one complete inbound block entry that should probably sit under Skynet rather than the system messages category.
Any ideas what is causing that and how to fix? Thanks.

(It‘s on an AC88U on 384.19 firmware)

 

[elorimer]

I‘ve noticed that my log (using Scribe) under ‘system messages’ category is full of strange entries that look like incomplete log lines. I think they might be part of entries that should fall under Skynet’s log entries for inbound blocks, but it seems they are missed from that and partly chopped in the process. Below are a couple of examples of these log fragments, including one complete inbound block entry that should probably sit under Skynet rather than the system messages category.
Any ideas what is causing that and how to fix? Thanks.

(It‘s on an AC88U on 384.19 firmware)

View attachment 26802

I remember this problem but not the solution; I can't search the scribe thread but I think it must be somewhere in there. Perhaps our old friend time-reap(2).

Are all your scripts and configuration files up to date? @Adamm and @cmkelley spent a good deal of time making skynet and scribe work together and this shouldn't be happening.

 

[TheStork]

Are all your scripts and configuration files up to date? @Adamm and @cmkelley spent a good deal of time making skynet and scribe work together and this shouldn't be happening.

Thanks. Yes, all scripts are up to date; already checked with amtm. The first things I tried when I spotted it (days ago, on two separate AC88U routers) was to check that all add-on scripts were up to date, and rebooted the router.

 

[elorimer]

So, what does your skynet config file look like in /opt/etc/syslog-ng.d, and your /opt/etc/syslog-ng.conf?

 

[TheStork]

So, what does your skynet config file look like in /opt/etc/syslog-ng.d, and your /opt/etc/syslog-ng.conf?

Skynet config in syslog-ng.d looks like this:

# this MUST BE the file configured in Skynet as the syslog.log location
# DO NOT use /tmp/syslog.log or /opt/var/log/messages here!
destination d_skynet {
    file("/opt/var/log/skynet-0.log");
};

# logs everything from Skynet to /opt/var/log/skynet-0.log
filter f_skynet {
    program("Skynet") or
    message("BLOCKED -") or
    message("DROP IN=");
};

# final flag stops processing of messages matching the f_skynet filter
log {
    source(src);
    filter(f_skynet);
    destination(d_skynet);
    flags(final);
};

#eof

And syslog-ng.conf looks like this:

#############################################################################
# syslog-ng.conf customized for scribe on Asuswrt-Merlin firmware
# compare to /opt/share/syslog-ng/examples/syslog-ng.conf-opkg for differences from Entware distribution
#
# syslog-ng documentation: https://www.syslog-ng.com/technical-documents/doc/syslog-ng-open-source-edition/3.27/administration-guide
#
# Release notes: https://github.com/syslog-ng/syslog-ng/releases

@version: 3.27
#@include "scl.conf" # uncomment this line to for additional functionality, see syslog-ng documentation
@include "/opt/etc/syslog-ng.d/" # Put any customization files in this directory

options {
    chain_hostnames(no); # Enable or disable the chained hostname format.
    create_dirs(yes);
    keep_hostname(yes); # Enable or disable hostname rewriting.
    log_fifo_size(256); # The number of messages that the output queue can store.
    log_msg_size(16384); # Maximum length of a message in bytes.
    stats_freq(21600); # The period between two STATS messages sent by syslog-ng, containing statistics about dropped logs in seconds; 0 disables. (21,600 seconds = 6 hours)
    flush_lines(0); # How many lines are flushed to a destination at a time.
    use_fqdn(no); # Add Fully Qualified Domain Name instead of short hostname.
};

# syslog-ng gets messages from the system, kernel, and syslog-ng (internal)
# DO NOT use system() source; causes issues on HND routers
# so_rcvbuf = maximum number of messages per second * 1024
source src {
    unix-dgram("/dev/log" so_rcvbuf(65536) flags(syslog-protocol));
    file("/proc/kmsg" program_override("kernel") flags(kernel));
    internal();
#    udp(ip(192.168.x.y) port(514)); # uncomment this line to pass all network messages through syslog-ng filters
};

# if you only want to pass network messages through some syslog-ng filters, uncomment the source line below
# then add "soource(net);" to the log statement in any filter you want to pass network messages through
#source net { udp(ip(192.168.x.y) port(514)); };

# set the filename for the default log file - anything not filtered out will end up here
destination messages { file("/opt/var/log/messages"); };

# to send log messages to the local network, uncomment the destination line below
# then add "destination(log_server);" to the log statement in any filter you want to pass network messages through
#destination log_server { udp("192.168.x.y" port(514)); };

log {
    source(src);
#    source(net); # uncomment this and "source net" function above to get udp log messages from local network
    destination(messages);
#    destination(log_server); # uncomment this and "destination log_server" function above to send udp log messages to local network
};

 

[elorimer]

Your syslog-ng.conf file is a little different than mine, and outside of the intentional things I've done I'm not sure why. By way of example there is that odd line: "# then add "soource(net);...".

But I don't see anything wrong in those two files.

Two ideas here. One is to be sure skynet is set for the log to be the custom location in /opt/var/log/.

Second is to be sure syslog-ng is starting correctly by running in terminal "syslog-ng -Fevd". I have a dim recollection that some of these fragments were because syslogd and klogd were still running.

 

[TheStork]

Two ideas here. One is to be sure skynet is set for the log to be the custom location in /opt/var/log/.

Second is to be sure syslog-ng is starting correctly by running in terminal "syslog-ng -Fevd". I have a dim recollection that some of these fragments were because syslogd and klogd were still running.

The conf files have not been manually edited by me, so they should be as per what the installation creates.
Skynet’s syslog appears to be in the right location, with the print debug info including:
Syslog Location; (/opt/var/log/skynet-0.log) (/tmp/syslog.log-1)

Running the "syslog-ng -Fevd" command gives a lot of output, but includes what looks to be the erroneous fragments as incoming messages, e.g. like:

[2020-10-12T18:59:48.307521] Incoming log entry; line='DF PROTO=UDP SPT=6881 DPT=6881 LEN=109 '
[2020-10-12T18:59:48.308146] Initializing destination file writer; template='/opt/var/log/messages', filename='/opt/var/'
[2020-10-12T18:59:48.308591] Outgoing message; message='Oct 12 18:59:48 RT-AC88U-9928 kernel: DF PROTO=UDP SPT=6881 DPT='

 

[elorimer]

That second line of the output looks wrong to me; I think it should end with "filename='/opt/var/log/messages'. But that isn't the problem, because syslog-ng is reading the fragment, not finding it matching anything it opens a file to send it to messages, and then outputs that message with host identified and the time cleaned up. I'm just as stumped as before.

You should have a file called "/opt/etc/init.d/rc.func.syslog-ng", and it should begin (after the shebang) with something like this:

kill_logger (){
    # kill any/all running klogd and/or syslogd
    [ -n "$( pidof klogd )" ] && killall klogd
    [ -n "$( pidof syslogd )" ] && killall syslogd

    # if syslog-ng was stopped by scribe, messages will be symlink to syslog.log
    [ -L /opt/var/log/messages ] && rm -f /opt/var/log/messages

    # webGUI System Log = /tmp/syslog.log
    if [ ! -L "/tmp/syslog.log" ]
    then
        cat /tmp/syslog.log > /opt/var/log/startup
        rm -f /tmp/syslog.log /tmp/syslog.log-1
        ln -s /opt/var/log/messages /tmp/syslog.log
        echo "### Top of Log File ###" >> /tmp/syslog.log-1
    fi

    # make /jffs/syslog.log and log-1 directories if not already
    # prevents system log saver from writing to jffs
    if [ ! -d "/jffs/syslog.log" ] || [ ! -d "/jffs/syslog.log-1" ]
    then
        rm -rf /jffs/syslog.log /jffs/syslog.log-1
        mkdir /jffs/syslog.log /jffs/syslog.log-1
    fi
    sleep 2
}

Just to double check, your /opt/etc/init.d/S01syslog-ng file should look like this

#!/bin/sh

ENABLED=yes
PROCS=syslog-ng
ARGS=""
PREARGS=""
DESC=$PROCS
PATH=/opt/sbin:/opt/bin:/opt/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin

. /opt/etc/init.d/rc.func.syslog-ng # added by scribe

. /opt/etc/init.d/rc.func

Mine's a little different, but the important part is killing klogd and syslogd. I'm assuming you have that, and that if you run top you don't have either running.

 

[TheStork]

Thanks.
My rc.func.syslog-ng is very similar to the one you posted, with the only two differences being:

• In the first if-then statement under 'kill_logger', my first line inside it is 'cat /tmp/syslog.log >> /opt/var/log/messages', while yours was 'cat /tmp/syslog.log >> /opt/var/log/startup'.
• Mine does not have the 'sleep 2' in the end like yours does.

My S01syslog-ng looked exactly as the one you posted.

When I run top, I do not have either klogd or syslogd running.

 

[elorimer]

I'm stumped and pained. This is where I would tear everything down in a nuclear factory reset.

As I said, mine is a little different, and you've noted how. I do this a little different because I pour the initial messages back into syslog-ng to get a linear startup and send them to other places. None of those differences explain why your experience is different.

I am (We are?) in a slight bit of a void zone. The last documentation I've seen is for 3.26, and github is up to 3.29 but our version seems to be 3.27. The .conf file all of us show is at .27; I think that is something in scribe that is doing it, and there is a note that .27 changes time-reap significantly, but I don't know what that is.

I will follow you on this, so please persist.

 

[cmkelley]

I‘ve noticed that my log (using Scribe) under ‘system messages’ category is full of strange entries that look like incomplete log lines. I think they might be part of entries that should fall under Skynet’s log entries for inbound blocks, but it seems they are missed from that and partly chopped in the process. Below are a couple of examples of these log fragments, including one complete inbound block entry that should probably sit under Skynet rather than the system messages category.
Any ideas what is causing that and how to fix? Thanks.

(It‘s on an AC88U on 384.19 firmware)

View attachment 26802

I've not updated to 384.19 yet, and I'm not sure when I will. That said, unless 384.19 changed something, you should see your hostname between the time and "kernel:". The fact that you don't have that suggests syslogd is parsing the messages, not syslog-ng. Instead of looking at top, simply running

scribe status

will tell you if it's all working or not. That's a good place to start.

I honestly don't recall if I did encounter this or if I did what the fix was. I've been away from this for a while, and will unfortunately continue to be due to other more pressing issues. I also don't have my testing router anymore, it's been rehomed to my father's house and is running stock since it's an AC3200.

@elorimer your syslog-ng.conf is different because scribe doesn't overwrite your customized syslog-ng.conf when it updates, and I've tweaked it since you edited yours. Also, "soource" is a typo, should be "source". No, it wasn't .27 that changed time-reap. My code that updates the version in syslog-ng.conf and the links to the latest version of the documentation, etc., wasn't smart enough to not leave the version that changed time-reap alone. In the latest version, I've removed that line,

 

[TheStork]

Thanks @cmkelley.
My Scribe status looks ok:

You are right that most of the log entries do indeed have the host name between time and ‘kernel’. I think the original log entries I posted didn’t, and a little further down from them in the log there were ‘klogd exiting’ and ‘syslogd exiting’ messages, after which the host name appeared in subsequent log entries. But the Skynet log fragments also continued to appear, albeit with the host name in the log, e.g.:
Oct 13 08:47:21 RT-AC88U-9928 kernel: PROTO=UDP SPT=6881 DPT=18183 LEN=109
Oct 13 08:49:37 RT-AC88U-9928 kernel: SPT=45949 DPT=23 SEQ=1453674881 ACK=0 WINDOW=52493 RES=0x00 SYN URGP=0 OPT

 

[TheStork]

Another observation: my Skynet log entries and the log fragments seem to have a time stamp that is in UTC, while other log entries (e.g. OpenVPN) are in local time zone (which for me is British Summer Time for now). So the log entries strangely jump around by a one hour offset, depending on type of log entry.

Not sure if that is related to the Skynet log fragments, but that does not appear to be quite right either.

 

[elorimer]

I can't fathom what is going on with your setup. In your original post, your log messages seem to have translated time but no host, which look like they would have been generated by the regular syslog, not syslog-ng.

But in your post two up, the log entries have a host, which indicates they were processed by syslog-ng.

We saw these fragments in the log early on, but they have been scrubbed out satisfactorily by all accounts. So I'm left with the recommendation to do a nuclear reset and start all over.

 

[TheStork]

I uninstalled uiScribe, uninstalled Scribe, forced a reinstall of Skynet, rebooted, and then reinstalled Scribe (and uiScribe). That seems to have fixed the issue.