What's new

syslogd and klogd being started from "restart time" service event

  • SNBForums Code of Conduct

    SNBForums is a community for everyone, no matter what their level of experience.

    Please be tolerant and patient of others, especially newcomers. We are all here to share and learn!

    The rules are simple: Be patient, be nice, be helpful or be gone!

cmkelley

Very Senior Member
Turns out not to be a 384.11 problem only ...

I had been counting on syslogd and klogd only being restarted via the "restart logger" service event. However, I have found that they also restart after a "restart time" service event.

This is further complicated by the fact that a "restart time" service event also generates a "dropbear [xxxx]: Early exit: Terminated by signal" log entry. So I don't know if it's the restart time service event or dropbear being terminated that trips the restart without using logger. I suspect the latter but I wouldn't even know how to look in the source to figure this out, nor fix it, obviously. Or maybe restart time is the only one terminating dropbear "early".

Eric, is this a bug in ASUS' code, or "working as designed", or something that can be fixed?
 
Last edited:
Eric, is this a bug in ASUS' code, or "working as designed", or something that can be fixed?

Working as designed. If something causes the time to change (ntp edit, timezone change, etc...), logger services need to be restarted to update.

It was one of the conditions I mentioned ealier when asked what could cause syslog to be restarted.

Code:
        else if (strcmp(script, "time") == 0)
        {
                if(action & RC_SERVICE_STOP) {
#ifdef RTCONFIG_NTPD
                        stop_ntpd();
#endif
                        stop_hour_monitor_service();
                        stop_telnetd();
#ifdef RTCONFIG_SSH
                        stop_sshd();
#endif
                        stop_logger();
                        //stop_httpd();
                }
 
Last edited:
Working as designed. If something causes the time to change (ntp edit, timezone change, etc...), logger services need to be restarted to update.

It was one of the conditions I mentioned ealier when asked what could cause syslog to be restarted.
Right, but there is no service event "restart logger" happening - it's starting both of them without triggering a service event. I think that's my confusion, I evidently misunderstood you, I was thinking that restarting klogd and syslogd would always be done through a "restart logger" service event. Phooey, that's going to make it much harder to determine that they've been restarted. :-(
 
Right, but there is no service event "restart logger" happening - it's starting both of them without triggering a service event. I think that's my confusion, I evidently misunderstood you, I was thinking that restarting klogd and syslogd would always be done through a "restart logger" service event. Phooey, that's going to make it much harder to determine that they've been restarted. :-(

Intercept "restart_time" events through a service-event-end script (introduced with 384.11).
 
Intercept "restart_time" events through a service-event-end script (introduced with 384.11).
One minor problem: service-event-end doesn't run if "restart_time" was triggered by a webui event. :(

To recreate:
  • create a service-event-end script that leaves some indicator that it has run
  • on administration -> system tab, press "Apply"
  • note you will lose your ssh connection
  • log back in
  • your indicator will not be present
Note that typing "service restart_time" at the command line will still drop the ssh connection (ssh is time-sensitive, right?) but that the indicator for running service-event-end WILL be there.

(tested only on AC3200, I haven't put the beta on my AC86U yet)
 
One minor problem: service-event-end doesn't run if "restart_time" was triggered by a webui event. :(

To recreate:
  • create a service-event-end script that leaves some indicator that it has run
  • on administration -> system tab, press "Apply"
  • note you will lose your ssh connection
  • log back in
  • your indicator will not be present
Note that typing "service restart_time" at the command line will still drop the ssh connection (ssh is time-sensitive, right?) but that the indicator for running service-event-end WILL be there.

(tested only on AC3200, I haven't put the beta on my AC86U yet)
Tested on my AC86U with service-event-end in /jffs/configs (chmod 755 )
EDIT - Just saw it stopped syslog-ng, restart worked.
Code:
#!/bin/sh
#/jffs/configs/service-event-end
logger "your service-event-end script has been executed"
sleep 2s
done
logger "your service-event-end script has been executed"
yes, kicked out of SSH
result (I deleted many lines of BLOCKED - IN and dcd crashes - left blank lines, there were many) MANY events restarted!
Code:
Apr 27 20:06:05 RT-AC86U-4608 rc_service[20367]: httpds 20367:notify_rc restart_time;restart_upnp;restart_leds;restart_usb_idle;restart_bhblock;
Apr 27 20:06:05 RT-AC86U-4608 custom_script[1]: Running /jffs/scripts/service-event (args: restart time)
Apr 27 20:06:06 RT-AC86U-4608 ntpd[1]: Started ntpd
Apr 27 20:06:06 syslogd started: BusyBox v1.25.1
Apr 27 20:06:06 kernel: klogd started: BusyBox v1.25.1 (2019-04-26 17:10:49 EDT)
Apr 27 20:06:06 kernel: [BLOCKED - INBOUND] IN=eth0 OUT= MAC=88:d7:f6:1d:46:08:00:01:5c:6d:22:46:08:00 SRC=185.176.27.98 DST=71.93.53.239 LEN=40 TOS=0x00 PREC=0x00 TTL=238 ID=35395 PROTO=TCP SPT=48136 DPT=39988 SEQ=1921852312 ACK=0 WINDOW=1024 RES=0x00 SYN URGP=0 MARK=0x8000000

Apr 27 20:06:06 kernel: dcd[28707]: unhandled level 3 translation fault (11) at 0x00000000, esr 0x92000007

Apr 27 20:06:06 kernel: [BLOCKED - INBOUND]

Apr 27 20:06:06 kernel: dcd[3008]: unhandled level 3 translation fault (11) at 0x00000000, esr 0x92000007

Apr 27 20:06:06 kernel: [BLOCKED - INBOUND]

Apr 27 20:06:06 kernel: dcd[7859]: unhandled level 3 translation fault (11) at 0x00000000, esr 0x92000007

Apr 27 20:06:06 kernel: [BLOCKED - INBOUND]

Apr 27 20:06:06 kernel: dcd[11064]: unhandled level 3 translation fault (11) at 0x00000000, esr 0x92000007

Apr 27 20:06:06 kernel: [BLOCKED - INBOUND]

Apr 27 20:06:06 kernel: dcd[15018]: unhandled level 3 translation fault (11) at 0x00000000, esr 0x92000007

Apr 27 20:06:06 kernel: [BLOCKED - INBOUND]

Apr 27 20:06:06 dropbear[24721]: Running in background
Apr 27 20:06:06 nat: apply nat rules (/tmp/nat_rules_eth0_eth0)
Apr 27 20:06:06 custom_script: Running /jffs/scripts/nat-start
Apr 27 20:06:06 rc_service: service 24759:notify_rc restart_dnsmasq
Apr 27 20:06:06 rc_service: waitting "restart_time;restart_upnp;restart_leds;restart_usb_idle;restart_bhblock;" via httpds ...
Apr 27 20:06:06 custom_script: Running /jffs/scripts/firewall-start (args: eth0)
Apr 27 20:06:06 custom_script: Running /jffs/scripts/service-event (args: restart upnp)
Apr 27 20:06:06 hour_monitor: daemon is starting
Apr 27 20:06:06 hour_monitor: daemon terminates
Apr 27 20:06:06 custom_script: Running /jffs/scripts/service-event (args: restart leds)
Apr 27 20:06:06 custom_script: Running /jffs/scripts/service-event (args: restart usb_idle)
Apr 27 20:06:06 custom_script: Running /jffs/scripts/service-event (args: restart bhblock)
Apr 27 20:06:06 Skynet: [%] Startup Initiated... ( skynetloc=/tmp/mnt/SNB/skynet )
Apr 27 20:06:07 custom_script: Running /jffs/scripts/service-event (args: restart dnsmasq)
Apr 27 20:06:07 custom_config: Appending content of /jffs/configs/dnsmasq.conf.add.
Apr 27 20:06:07 custom_script: Running /jffs/scripts/dnsmasq.postconf (args: /etc/dnsmasq.conf)
Apr 27 20:06:07 rc_service: service 25296:notify_rc restart_dnsmasq
Apr 27 20:06:07 rc_service: waitting "restart_dnsmasq" via  ...
Apr 27 20:06:08 Diversion: restarted Dnsmasq to apply settings, from /jffs/scripts/dnsmasq.postconf
Apr 27 20:06:08 rc_service: watchdog 811:notify_rc start_dnsmasq
Apr 27 20:06:08 rc_service: waitting "restart_dnsmasq" via  ...
Apr 27 20:06:09 custom_script: Running /jffs/scripts/service-event (args: start dnsmasq)
Apr 27 20:06:10 custom_config: Appending content of /jffs/configs/dnsmasq.conf.add.
Apr 27 20:06:10 custom_script: Running /jffs/scripts/dnsmasq.postconf (args: /etc/dnsmasq.conf)
Apr 27 20:06:11 Diversion: restarted Dnsmasq to apply settings, from /jffs/scripts/dnsmasq.postconf
Apr 27 20:06:12 custom_script: Running /jffs/scripts/service-event (args: restart dnsmasq)
Apr 27 20:06:13 custom_config: Appending content of /jffs/configs/dnsmasq.conf.add.
Apr 27 20:06:13 custom_script: Running /jffs/scripts/dnsmasq.postconf (args: /etc/dnsmasq.conf)
Apr 27 20:06:14 Diversion: restarted Dnsmasq to apply settings, from /jffs/scripts/dnsmasq.postconf

Apr 27 20:06:18 kernel: [BLOCKED - INBOUND]

Apr 27 20:06:23 kernel: DROP IN=

Apr 27 20:06:27 Skynet: [#] 136816 IPs (+0) -- 1602 Ranges Banned (+0) |.......[start] [21s]

Apr 27 20:06:35 kernel: [BLOCKED - INBOUND]
EDIT 2 - appears that klogd and syslogd restarted and then exited when I restarted syslog-ng via "scribe restart"
Code:
Apr 27 20:08:42 kernel: klogd: exiting
Apr 27 20:08:42 syslogd exiting
Apr 27 20:08:43 RT-AC86U-4608 [redacted][27104]: Started syslog-ng from .
 
Last edited:
Ummm, it needs to be in /jffs/scripts/ not /jffs/configs :)
I went from this by RMerlin post #1 in the 384.11 beta available thread:
  • Custom config/script changes: added service-event-end (run at the end of an rc service event, same parameter as service-event), stubby.postconf/add support (for customizing the DNS Privacy configuration). pre-mount will now receive the filesystem as a second argument.
I'll test tomorrow morning in /jffs/scrips/.
I am going to bed, I've been up since 4:00 a.m.volunteered at feed stop for Wildflower Century today.
 
One minor problem: service-event-end doesn't run if "restart_time" was triggered by a webui event. :(

Not sure why, all httpd events should normally be handled by handle_notifications().
 
Not sure why, all httpd events should normally be handled by handle_notifications().
I'll give the beta a go on my 86U in the morning and see if I can duplicate it there as well.
 
How often does this happen? Perhaps a path is like FreshJR's QOS script to do a nightly persistence check.
 
It appears to be much worse than I thought. :(

The system log function seem to be getting blocked when a webgui event restarts syslogd and klogd Even restarting scribe isn't fixing it. And it's definitely not limited to 384.11 ...

I'm gonna go ride a bike and clear my head on this one.
 
Syslog-ng keeps running, and the symlink stays intact. Not sure where syslogd is going, but klogd then interferes again with syslog-ng picking up kernel messages.

I put this in service-event instead of kill_logger:
Code:
  [ -n "$(pidof klogd)" ] && killall klogd
 [ -n "$(pidof syslogd)" ] && killall syslogd
Then I stopped the local ntpd in the webgui and messages has this:
Code:
Apr 28 15:02:04 rc_service: httpd 250:notify_rc restart_time;restart_upnp;restart_leds;restart_usb_idle;restart_bhblock;restart_dnsmasq;
Apr 28 15:02:04 custom_script: Running /jffs/scripts/service-event (args: restart time)
Apr 28 15:02:04 kernel: klogd: exiting
Apr 28 15:02:04 syslogd exiting
Apr 28 15:02:04 syslogd started: BusyBox v1.25.1
Apr 28 15:02:04 kernel: klogd started: BusyBox v1.25.1 (2019-04-26 18:02:01 EDT)
Apr 28 15:02:04 dropbear[8764]: Running in background
Apr 28 15:02:04 nat: apply nat rules (/tmp/nat_rules_eth0_eth0)
Apr 28 15:02:04 custom_script: Running /jffs/scripts/nat-start
Apr 28 15:02:05 custom_script: Running /jffs/scripts/firewall-start (args: eth0)
Apr 28 15:02:05 custom_script: Running /jffs/scripts/service-event (args: restart upnp)
Apr 28 15:02:05 miniupnpd[8806]: HTTP listening on port 44221
Apr 28 15:02:05 miniupnpd[8806]: Listening for NAT-PMP/PCP traffic on port 5351
Apr 28 15:02:05 kernel: klogd: exiting
Apr 28 15:02:05 syslogd exiting
Then I started it again:
Code:
Apr 28 15:03:54 syslogd started: BusyBox v1.25.1
Apr 28 15:03:54 kernel: klogd started: BusyBox v1.25.1 (2019-04-26 18:02:01 EDT)
Apr 28 15:03:54 dropbear[10664]: Running in background
Apr 28 15:03:54 miniupnpd[8841]: shutting down MiniUPnPd
Apr 28 15:03:54 nat: apply nat rules (/tmp/nat_rules_eth0_eth0)
Apr 28 15:03:54 custom_script: Running /jffs/scripts/nat-start
Apr 28 15:03:55 custom_script: Running /jffs/scripts/firewall-start (args: eth0)
Apr 28 15:03:55 custom_script: Running /jffs/scripts/service-event (args: restart upnp)
Apr 28 15:03:55 miniupnpd[10707]: HTTP listening on port 37973
Apr 28 15:03:55 miniupnpd[10707]: Listening for NAT-PMP/PCP traffic on port 5351
Apr 28 15:03:55 kernel: klogd: exiting
Apr 28 15:03:55 syslogd exiting
Is it that simple?

Renamed service-event as service-event-end and that didn't work. Changed it back and it worked as before.
 
Last edited:
Syslog-ng keeps running, and the symlink stays intact. Not sure where syslogd is going, but klogd then interferes again with syslog-ng picking up kernel messages.

I put this in service-event instead of kill_logger:
Code:
  [ -n "$(pidof klogd)" ] && killall klogd
 [ -n "$(pidof syslogd)" ] && killall syslogd
Then I stopped the local ntpd in the webgui and messages has this:
Code:
Apr 28 15:02:04 rc_service: httpd 250:notify_rc restart_time;restart_upnp;restart_leds;restart_usb_idle;restart_bhblock;restart_dnsmasq;
Apr 28 15:02:04 custom_script: Running /jffs/scripts/service-event (args: restart time)
Apr 28 15:02:04 kernel: klogd: exiting
Apr 28 15:02:04 syslogd exiting
Apr 28 15:02:04 syslogd started: BusyBox v1.25.1
Apr 28 15:02:04 kernel: klogd started: BusyBox v1.25.1 (2019-04-26 18:02:01 EDT)
Apr 28 15:02:04 dropbear[8764]: Running in background
Apr 28 15:02:04 nat: apply nat rules (/tmp/nat_rules_eth0_eth0)
Apr 28 15:02:04 custom_script: Running /jffs/scripts/nat-start
Apr 28 15:02:05 custom_script: Running /jffs/scripts/firewall-start (args: eth0)
Apr 28 15:02:05 custom_script: Running /jffs/scripts/service-event (args: restart upnp)
Apr 28 15:02:05 miniupnpd[8806]: HTTP listening on port 44221
Apr 28 15:02:05 miniupnpd[8806]: Listening for NAT-PMP/PCP traffic on port 5351
Apr 28 15:02:05 kernel: klogd: exiting
Apr 28 15:02:05 syslogd exiting
Then I started it again:
Code:
Apr 28 15:03:54 syslogd started: BusyBox v1.25.1
Apr 28 15:03:54 kernel: klogd started: BusyBox v1.25.1 (2019-04-26 18:02:01 EDT)
Apr 28 15:03:54 dropbear[10664]: Running in background
Apr 28 15:03:54 miniupnpd[8841]: shutting down MiniUPnPd
Apr 28 15:03:54 nat: apply nat rules (/tmp/nat_rules_eth0_eth0)
Apr 28 15:03:54 custom_script: Running /jffs/scripts/nat-start
Apr 28 15:03:55 custom_script: Running /jffs/scripts/firewall-start (args: eth0)
Apr 28 15:03:55 custom_script: Running /jffs/scripts/service-event (args: restart upnp)
Apr 28 15:03:55 miniupnpd[10707]: HTTP listening on port 37973
Apr 28 15:03:55 miniupnpd[10707]: Listening for NAT-PMP/PCP traffic on port 5351
Apr 28 15:03:55 kernel: klogd: exiting
Apr 28 15:03:55 syslogd exiting
Is it that simple?

Renamed service-event as service-event-end and that didn't work. Changed it back and it worked as before.
I think it's not that simple, because I think you're going to find you don't have any more log messages after syslogd exiting. :(
 
Maybe, but I can't tell. I don't get many things into messages now in the first place. But I'm still getting tons of (ungarbled) messages into my pixelserv and skynet logs. Syslog-ng is still running.
 
Maybe, but I can't tell. I don't get many things into messages now in the first place. But I'm still getting tons of (ungarbled) messages into my pixelserv and skynet logs. Syslog-ng is still running.
easy check, "service restart_httpd". If you get nothing new in messages, it's not talking to the messages file.
 
Code:
Apr 28 17:58:59 RT-AC87R rc_service[30117]: service 30117:notify_rc restart_httpd
Apr 28 17:58:59 RT-AC87R custom_script[1]: Running /jffs/scripts/service-event (args: restart httpd)
Apr 28 17:58:59 RT-AC87R RT-AC87R[1]: start httpd:80
 
Code:
Apr 28 17:58:59 RT-AC87R rc_service[30117]: service 30117:notify_rc restart_httpd
Apr 28 17:58:59 RT-AC87R custom_script[1]: Running /jffs/scripts/service-event (args: restart httpd)
Apr 28 17:58:59 RT-AC87R RT-AC87R[1]: start httpd:80
So what you're doing is basically looking for syslogd and klogd any time service-event is run, regardless of why. But that doesn't make much sense because on my router I can see that syslogd and klogd aren't running, but the messages file is still blocked.
 
Yes. I was thinking it was faster than loading the whole scribe script for the kill_logger function. There is still a second in there where I might miss a logged message, but I can't figure out where syslogd or klogd would be sending it if /tmp/syslog.log is a symlink to messages, and since the symlink and running of syslog-ng seem to stay intact after the initial start, better to get them out of the way soonest. Since normally I'm not applying changes to webgui I can go a long time before the issue occurs.

Still can't figure out why service-event-end doesn't run though. That seems like the right place.
 

Similar threads

Latest threads

Sign Up For SNBForums Daily Digest

Get an update of what's new every day delivered to your mailbox. Sign up here!
Top