Best log message to detect boot/reboot

[Maverickcdn]

Until the day Asus or RMerlin add a WAN up date/time value in nvram or tmp file Ive been working on a way to try and calc WAN uptime from log messages (ie wan-event connected, wan: finish adding multi routes, Initial clock set messages)

Wondering what would be the best message in the logs to search for to detect boot/reboot (pre NTP sync) date/time.

I know about the boot date in rc '#define RC_BUILDTIME 1525496688 // May 5 05:04:48 GMT 2018' but depending on configured TZ this can change (ie. My boot date/time is May 4 @23:05 MDT -6 as first messages after klogd is started)

Its either searching the logs for currently "Linux version" and pulling the date/time, or should I write a function to pull TZ from nvram and calculate from RC_BUILDTIME what date/time klogd all syslog messages would be pre NTP sync?

First 10 lines from my AC86 boot seq.

MavMAIN|>/jffs/scripts| cat /tmp/syslog.log-1 | grep 'May  4' | head -n 10
May  4 23:05:05 syslogd started: BusyBox v1.25.1
May  4 23:05:05 syslogd: using server 10.1.1.11:514
May  4 23:05:05 kernel: klogd started: BusyBox v1.25.1 (2022-03-25 10:24:27 EDT)
May  4 23:05:05 kernel: Booting Linux on physical CPU 0x0
May  4 23:05:05 kernel: Linux version 4.1.27 (merlin@ubuntu-dev) (gcc version 5.3.0 (Buildroot 2016.02) ) #2 SMP PREEMPT Fri Mar 25 11:09:05 EDT 2022
May  4 23:05:05 kernel: CPU: AArch64 Processor [420f1000] revision 0
May  4 23:05:05 kernel: Detected VIPT I-cache on CPU0
May  4 23:05:05 kernel: alternatives: enabling workaround for ARM erratum 845719
May  4 23:05:05 kernel: On node 0 totalpages: 123904
May  4 23:05:05 kernel:   DMA zone: 1792 pages used for memmap

# Try to detect default boot date/time as differs based on set timezone
boot_string='Linux version'
F_boot_date() {
    fnd_boot=$(grep "$boot_string" /tmp/syslog.log-1 2>/dev/null | head -n1)
    [ -z "$fnd_boot" ] && fnd_boot=$(grep "$boot_string" /tmp/syslog.log 2>/dev/null | head -n1)
    [ -z "$fnd_boot" ] && logger -st "wanuptime[$$]" "ERROR - could not detect router boot date" && F_printf "Couldn't locate $boot_string ,did you reset logs?"
    boot_mth=$(echo "$fnd_boot" | awk '{print $1}') ;boot_day=$(echo "$fnd_boot" | awk '{print $2}')
    boot_hr=$(echo "$fnd_boot" | awk '{print $3}' | cut -d':' -f1) ;boot_min=$(echo "$fnd_boot" | awk '{print $3}' | cut -d':' -f2)
    [ "$boot_min" -ne 0 ] && boot_low=$((boot_min - 1)) ;boot_high=$((boot_min + 5))   # 6 minute window incase NTP takes long to sync
}

This is necessary to filter search results that are from boot/reboot not a true WAN up/down event. Whatever route it is, it needs to work across all models from FW 384.15+

Anyone got any ideas?

 

[ColinTaylor]

This is necessary to filter search results that are from boot/reboot not a true WAN up/down event.

Sorry, I'm not following. You want the WAN uptime but not if it's caused by a boot/reboot? In other words, the WAN uptime since the last abnormal WAN event. Correct?

So are you asking how to calculate the (abnormal) WAN uptime, or how to detect the firmware build date?

EDIT: If it's any help the build date hasn't changed since prior to 384.15, so at the moment it's the same in all versions since then.

 

[Maverickcdn]

Sorry, I'm not following. You want the WAN uptime but not if it's caused by a boot/reboot? In other words, the WAN uptime since the last abnormal WAN event. Correct?

No... sorry rushed that post before leaving work, would like to calculate WAN uptime regardless if boot/reboot or just a disconnect/reconnect, issue is first two preferred search methods usually happen before NTP has sync'd on boot/reboot and I need the script to know if its found a legitimate date/time

WAN uptime is calculated from date/time in logs from 1 of 3 methods in preferential order
1) wan-event connected if user has wan-event file in /jffs/scripts
2) wan: finish adding multi routes message (seems to be a universal WAN connected event everyone should have)
3) if above 2 fail to be found or match default boot date/time the script will use last NTP Initial clock set to calc uptime

During boot/reboot the first 2 preferred methods will likely have default boot date/time, and script would calc an incorrect uptime so I need to detect if it is the router default date/time

May  4 23:05:10 custom_script: Running /jffs/scripts/wan-event (args: 0 connected)
May  4 23:05:11 wan: finish adding multi routes
Mar 26 14:26:28 ntpd: Initial clock set

    # if date/time found in logs for wan-event/wan up/ntp sync matches boot default date/time
    # Handle boot/reboot date
    if [ "$fnd_mth" = "$boot_mth" ] && [ "$fnd_day" -eq "$boot_day" ] && [ "$fnd_hr" -eq "$boot_hr" ] && [ "$fnd_min" -ge "$boot_low" ] && [ "$fnd_min" -le "$boot_high" ] ;then
        F_printf "WARNING - Found result is $fnd_mth $fnd_day @ ${fnd_hr}:${fnd_min}"
        F_printf "NOTICE - Detected default boot date/time match"
        if [ "$search" = 'wan' ] ;then
            F_printf "RETRY - Checking for WAN up instead" ;F_sep
            F_find_wan_msg && F_date_format && return 0
        elif [ "$search" = 'wanup' ] ;then
            F_printf "RETRY - Checking for NTP sync instead" ;F_sep
            F_find_ntp && F_date_format && return 0
        elif [ "$search" = 'ntp' ] ;then
            logger -st "wanuptime[$$]" "ERROR - NTP log is $fnd_mth $fnd_day @ ${fnd_hr}:${fnd_min} boot date script cannot process"
        fi
    fi

So my dilemma is, its either down to searching the routers logs for a boot time universal log message that will have the unique boot default date/time in logs for that router so that I can strip out that date/time and compare against... or a function to calculate what that pre-NTP sync date/time would be for that router based on the default RC_BUILDTIME and their TZ... this or something else all together I havent thought about

Hope this is a clearer explanation, let me know if you just want me to post the working script I have (its 200lines)

 

[ColinTaylor]

Can't you just use the wan-event connected script. If the current date/time is sane (e.g. after 2022/1/1) then use that. If not wait for ntp to update it.

 

[ColinTaylor]

If you're worried about the build date changing in future firmware versions you could use nvram get buildinfo. Then by definition if the current system date is prior to this variable the date/time hasn't been set yet.

EDIT: There's also the ntp_ready variable but I can't remember which firmware versions had that.

EDIT 2: Looks like ntp_ready was being used back in 2015 so that seems the easiest thing to check.

 

[Maverickcdn]

I guess one of the biggest issues is the syslog messages don't have a year so the script only has 364d23h59m59s of resolution.

Any date that is found and appears higher than current sync'd day is considered from the previous year... so my May 4 wan-event messages example (really from Mar 26) would calculate as May 4 2021 or far more than 3 days uptime. There is verification that if the log message is older than router uptime it fails. I was trying to validate it in another way. There is the unlikely chance where router uptime is great enough that somebody that runs it and it finds a May 4/5 default date without validating that its a boot date/time the script will consider it prior year and calc the uptime with no errors.

 

[ColinTaylor]

I don't see why you need to scan the syslog at all. Just do it all with a single wan-event script and the date command.

 

[Maverickcdn]

The script is meant to be run on demand and usable on install, it does not write to itself or storage of any data, relies completely on your pre-existing logs. The wan-event is just a preferred search method for last WAN up. If Im not mistaken you need a wan-event file in /jffs/scripts to trigger the log messages for wan-event, if someone uses the uptime script but doesn't have a wan-event they'll hopefully still get a result, that being said the script has a toggle to create wan-event for future use if it doesn't exist. But Im also iffy if my search method 2 term is used for most/all models/connection types.

################################################################################
#                                             _   _                            #
#                                            | | (_)                           #
#            __      ____ _ _ __  _   _ _ __ | |_ _ _ __ ___   ___             #
#            \ \ /\ / / _` | '_ \| | | | '_ \| __| | '_ ` _ \ / _ \            #
#             \ V  V / (_| | | | | |_| | |_) | |_| | | | | | |  __/            #
#              \_/\_/ \__,_|_| |_|\__,_| .__/ \__|_|_| |_| |_|\___|            #
#                                      | |                                     #
#                                      |_|                                     #
#                                                                              #
#                      written by Maverickcdn March 2022                       #
################################################################################
                         v1.0   Tue Mar 29 19:43:41 2022

SEARCHING - for 'wan-event connected' in logs
FAIL - 'wan-event connected' not found in syslog.log checking older syslog.log-1
SUCCESS - Last 'wan-event connected' event found in syslog.log-1
FOUND - May 4 23:05:10 custom_script: Running /jffs/scripts/wan-event (args: 0 c
WARNING - Found result is May 4 @ 23:05
NOTICE - Detected default boot date/time match
RETRY - Checking for WAN up instead
--------------------------------------------------------------------------------
SEARCHING - for WAN up log message in logs
FAIL - WAN up log message not found in syslog.log checking older syslog.log-1
SUCCESS - Last WAN up log message event found in syslog.log-1
FOUND - May 4 23:05:11 wan: finish adding multi routes
WARNING - Found result is May 4 @ 23:05
NOTICE - Detected default boot date/time match
RETRY - Checking for NTP sync instead
--------------------------------------------------------------------------------
SEARCHING - for NTP clock set in logs
FAIL - NTP clock set not found in syslog.log checking older syslog.log-1
SUCCESS - Last NTP clock set event found in syslog.log-1
FOUND - Mar 26 14:26:28 ntpd: Initial clock set
--------------------------------------------------------------------------------
Router uptime                   : 3 day(s) 5 hr(s) 17 min(s) 39 sec(s)
WAN uptime since last log event : 3 day(s) 5 hr(s) 17 min(s) 13 sec(s)

 

[ColinTaylor]

The script is meant to be run on demand and usable on install, it does not write to itself or storage of any data, relies completely on your pre-existing logs. The wan-event is just a preferred search method for last WAN up.

Ah, OK. I completely misunderstood. When you said wan-event was preferred I thought you meant actually running that script.

 

[ColinTaylor]

How about something along these lines:

cat /tmp/syslog.log | awk '/Initial clock set|WAN was restored/ {a=$0} END{print a}'

So scan the input for the last occurrence of "Initial clock set" or "WAN was restored". The assumption being that if the "WAN" message comes after the "clock" message then the correct date/time must have been set.

 

[Maverickcdn]

Ah, OK. I completely misunderstood. When you said wan-event was preferred I thought you meant actually running that script.

No worries.

How about something along these lines:

cat /tmp/syslog.log | awk '/Initial clock set|WAN was restored/ {a=$0} END{print a}'

So scan the input for the last occurrence of "Initial clock set" or "WAN was restored". The assumption being that if the "WAN" message comes after the "clock" message then the correct date/time must have been set.

I had it a very similar way already (compared line # in file).... seemed too simple and I wanted to complicate things

The rabbit holes into methods of writing code still makes my head hurt

 

[Maverickcdn]

Yikes

https://github.com/RMerl/asuswrt-merlin.ng/blob/master/release/src/router/rc/common.c#L1182-L1281

 

[Martinski]

The script is meant to be run on demand and usable on install, it does not write to itself or storage of any data, relies completely on your pre-existing logs. The wan-event is just a preferred search method for last WAN up...

At some point when both the router's uptime & WAN uptime are more than a few days (depending on the amount of network activity and the setting of the "Default message log level" option in "System Log" --> "General Log"), the system logs may no longer contain the specific strings your code is searching for (e.g. "WAN was restored", "wan: finish adding multi routes", "Initial clock set"), so you'll need to have another "external" source of information to calculate WAN uptime at any point and on-demand.

IMO, one solution would be to store the WAN events captured from the "wan-event" script into its own log (e.g. /tmp/var/tmp/wan-events.log") with their corresponding time stamps. This way, you'll have the necessary information available regardless of the contents of the system logs after more than a few days of uptime.

Just my 2 cents.

 

[Maverickcdn]

IMO, one solution would be to store the WAN events captured from the "wan-event" script into its own log (e.g. /tmp/var/tmp/wan-events.log") with their corresponding time stamps

Another valid point.... this was such a simple idea in the beginning... I guess its getting a wan-event install/uninstall function

 

[Martinski]

Another valid point.... this was such a simple idea in the beginning... I guess its getting a wan-event install/uninstall function

BTW, another advantage of having your own "wan-events.log" file with fully timestamped entries is that during & after boot time you will be able to tell quickly which events happened during the reboot cycle *before* NTP syncing (i.e. entries with the fixed built-in boot date/time), and which events have the true date/time, regardless of time zones.

Hypothetical "wan-events.log" entries (assuming your time zone here):

...
2018-May-04 23:05:45 ... /jffs/scripts/wan-event (args: 0 init)
...
2018-May-04 23:05:55 ... /jffs/scripts/wan-event (args: 0 connecting)
...
2018-May-04 23:06:10 ... /jffs/scripts/wan-event (args: 0 connected)
...
...
2022-May-04 23:05:45 ... /jffs/scripts/wan-event (args: 0 init)
...
2022-May-04 23:05:55 ... /jffs/scripts/wan-event (args: 0 connecting)
...
2022-May-04 23:06:15 ... /jffs/scripts/wan-event (args: 0 connected)
...

And this also helps with the edge case where a user just happens to reboot the router on "May 4th" at approximately "11:00 pm" on any subsequent year.

 

[ColinTaylor]

Here's my take on the "syslog only" approach. If instead you wanted to use wan-event to record the time you'd just need to change the wanup_date= line to pull the date from the relevant file.

Note that the forum won't allow me to post the word substr followed immediately by (...) so I've had to insert an ugly space after substr in the code below (not that awk seems to care).

#!/bin/sh

if [ "$(nvram get wan0_state_t)" != "2" ] && [ "$(nvram get wan1_state_t)" != "2" ]; then
   echo "WAN is not up"
   exit
fi

curr_secs="$(date +%s)"

infile="/tmp/syslog.log"
if [ -f /tmp/syslog.log-1 ]; then
   infile="/tmp/syslog.log-1 /tmp/syslog.log"
fi

wanup_date="$(cat $infile | awk '/Initial clock set|WAN was restored/ {a=$0} END{print substr (a,1,15)}')"
if [ -z "$wanup_date" ]; then
   echo "No WAN events detected in syslog"
   exit
fi

wanup_secs="$(/bin/date --date="$wanup_date" -D '%b %e %T' +'%s')"
if [ $wanup_secs -gt $curr_secs ]; then
   last_year="$(( $(date +%Y) - 1 ))"      # Assume last year
   wanup_secs="$(/bin/date --date="$last_year $wanup_date" -D '%Y %b %e %T' +'%s')"
fi

uptime="$((curr_secs-wanup_secs))"

#echo $curr_secs $wanup_secs $uptime
days="$((uptime/86400))"
hours="$((uptime/3600%24))"
minutes="$((uptime/60%60))"

echo "WAN uptime = $days days $hours hours $minutes minutes"

# /jffs/scripts/wanuptime.sh
WAN uptime = 2 days 16 hours 26 minutes

EDIT: Fixed typo. Tidied up code.

 

[Martinski]

Here's my take on the "syslog only" approach. If instead you wanted to use wan-event to record the time you'd just need to change the wanup_date= line to pull the date from the relevant file.

Note that regardless of which logs are used (from "wan-event" or "syslog"), you really need to search for all available WAN event entries (e.g. init, connecting, connected, disconnected, stopped, disabled, stopping, etc.) to determine the most recent WAN state so that the appropriate action is taken.

For instance, if for some reason (e.g. internet outage, ISP updating F/W to your modem) the most recently reported WAN state/event in the logs is "stopped" or "disconnected" you don't want to output the wrong/misleading WAN uptime based simply on the last found "WAN was restored" or "connected" message which precedes the current "disconnected" or "stopped" state. IOW, the most recently known/reported WAN event/state (however unlikely the scenario) must take precedence in determining what the true WAN uptime is at any point.

 

[Maverickcdn]

Errrr.... anyone have more details on this?

https://www.snbforums.com/threads/wan-start-script-also-run-on-wan-stop.61295/post-543219

Mar 30 02:19 was my last wan-event connected

MavMAIN|>/tmp| l | grep wan0
-rw-rw-rw-    1 master   root           458 Mar 30 02:19 wan0_bound.env

MavMAIN|>/tmp| cat wan0_bound.env
HOME=/
TERM=vt100
PATH=/sbin:/bin:/usr/sbin:/usr/bin:/opt/sbin:/opt/bin
LD_LIBRARY_PATH=/lib:/usr/lib:/lib/aarch64
SHELL=/bin/sh
USER=root
TMOUT=0
ENV=/etc/profile
TZ=MST7DST,M3.2.0/2,M11.1.0/2
interface=eth0
ip=1xx.xxx.xxx.xxx
subnet=255.255.252.0
mask=22
router=1xx.xxx.xxx.xxx
dns=x.x.x.x x.x.x.x
hostname=MYHOSTNAME
domain=PROVIDERDOMAIN
broadcast=255.255.255.255
lease=117180
serverid=x.x.x.x
opt53=05
opt58=0000783c
opt59=0001755c

 

[ColinTaylor]

Note that regardless of which logs are used (from "wan-event" or "syslog"), you really need to search for all available WAN event entries (e.g. init, connecting, connected, disconnected, stopped, disabled, stopping, etc.) to determine the most recent WAN state so that the appropriate action is taken.

For instance, if for some reason (e.g. internet outage, ISP updating F/W to your modem) the most recently reported WAN state/event in the logs is "stopped" or "disconnected" you don't want to output the wrong/misleading WAN uptime based simply on the last found "WAN was restored" or "connected" message which precedes the current "disconnected" or "stopped" state. IOW, the most recently known/reported WAN event/state (however unlikely the scenario) must take precedence in determining what the true WAN uptime is at any point.

Thanks for pointing this out. I've updated my script in post #16 accordingly.

 

[ColinTaylor]

Errrr.... anyone have more details on this?

https://www.snbforums.com/threads/wan-start-script-also-run-on-wan-stop.61295/post-543219

Mar 30 02:19 was my last wan-event connected

MavMAIN|>/tmp| l | grep wan0
-rw-rw-rw-    1 master   root           458 Mar 30 02:19 wan0_bound.env

MavMAIN|>/tmp| cat wan0_bound.env
HOME=/
TERM=vt100
PATH=/sbin:/bin:/usr/sbin:/usr/bin:/opt/sbin:/opt/bin
LD_LIBRARY_PATH=/lib:/usr/lib:/lib/aarch64
SHELL=/bin/sh
USER=root
TMOUT=0
ENV=/etc/profile
TZ=MST7DST,M3.2.0/2,M11.1.0/2
interface=eth0
ip=1xx.xxx.xxx.xxx
subnet=255.255.252.0
mask=22
router=1xx.xxx.xxx.xxx
dns=x.x.x.x x.x.x.x
hostname=MYHOSTNAME
domain=PROVIDERDOMAIN
broadcast=255.255.255.255
lease=117180
serverid=x.x.x.x
opt53=05
opt58=0000783c
opt59=0001755c

wan0_bound.env comes from udhcpc IIRC.
EDIT: Found it: https://github.com/RMerl/asuswrt-me...f8d6f63e8/release/src/router/rc/udhcpc.c#L345

I don't have /tmp/WAN0_state on my router.
EDIT: It appears to be created by the user script in post #4. I don't know why the script's author didn't recognise his own log file.