Menu
What's new
By:
Filters Better Search

Scribe /usr/bin/logger messages don't make it to the log file - intermittent issue

  • 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!

B

bibikalka

Senior Member
I am running Scribe with Entware.

Sometimes my cron job messages don't make it to the "messages" file for stretches of time, then it's all fine again for a while. Here is an example of a cron job that I want to output to messages every 15 min:

Code: 
cru a temp "*/15 * * * * /jffs/scripts/temp_check  2>&1 | tr -d '\n' | /usr/bin/logger -t Temp"

I tried to fix this with a couple of reboots for a couple of days, still no go, nothing changes. But yesterday night something happens at 22:39+, a bunch of messages in the log appear, and it suddenly starts working again, no reboot. See this chunk of the log at that time. Any possible clues what might be happening?

Code: 
Nov  4 21:29:51 RT-AC86U-9988 kernel: bcm_mcast_mld_add:833 mc_fdb->rep_list ffffffc0035d9ea8 next ffffffc0034c4c20 prev ffffffc0034c4c20 rep_entry->list ffffffc0034c4c20 next ffffffc0035d9ea8 prev ffffffc0035d9ea8
Nov  4 22:00:16 RT-AC86U-9988 kernel: __do_user_fault: 38 callbacks suppressed
Nov  4 22:38:28 RT-AC86U-9988 kernel: eth0 (Int switch port: 3) (Logical Port: 3) Link DOWN.
Nov  4 22:38:28 RT-AC86U-9988 kernel: ===> Activate Deep Green Mode
Nov  4 22:38:50 RT-AC86U-9988 kernel: eth0 (Int switch port: 3) (Logical Port: 3) Link UP 1000 mbps full duplex
Nov  4 22:38:50 RT-AC86U-9988 kernel: <=== Deactivate Deep Green Mode
Nov  4 22:38:53 RT-AC86U-9988 kernel: eth0 (Int switch port: 3) (Logical Port: 3) Link DOWN.
Nov  4 22:38:53 RT-AC86U-9988 kernel: ===> Activate Deep Green Mode
Nov  4 22:39:21 RT-AC86U-9988 kernel: eth0 (Int switch port: 3) (Logical Port: 3) Link UP 1000 mbps full duplex
Nov  4 22:39:21 RT-AC86U-9988 kernel: <=== Deactivate Deep Green Mode
Nov  4 22:39:30 RT-AC86U-9988 admin: Started syslog-ng from .
Nov  4 22:39:30 RT-AC86U-9988 uiScribe: Mounting WebUI page for uiScribe
Nov  4 22:39:30 RT-AC86U-9988 uiScribe: Mounted uiScribe WebUI page as Main_LogStatus_Content.asp
Nov  4 22:39:32 RT-AC86U-9988 WAN_Connection: WAN was restored.
Nov  4 22:39:32 RT-AC86U-9988 miniupnpd[13662]: HTTP listening on port 55864
Nov  4 22:39:32 RT-AC86U-9988 miniupnpd[13662]: Listening for NAT-PMP/PCP traffic on port 5351
Nov  4 22:39:37 RT-AC86U-9988 kernel: The For ALL DEVICES flag of Prof 1 has been set to ENABLE
Nov  4 22:39:37 RT-AC86U-9988 kernel: Successfully alloc ctrie: state num=34, mem=680
Nov  4 22:39:37 RT-AC86U-9988 BWDPI: fun bitmap = 53f
Nov  4 22:39:39 RT-AC86U-9988 custom_script: Running /jffs/scripts/firewall-start (args: eth0)
Nov  4 22:39:39 RT-AC86U-9988 miniupnpd[13662]: SendNATPMPPublicAddressChangeNotification: cannot get public IP address, stopping
Nov  4 22:39:39 RT-AC86U-9988 rc_service: udhcpc_wan 13162:notify_rc stop_samba
Nov  4 22:39:39 RT-AC86U-9988 custom_script: Running /jffs/scripts/service-event (args: stop samba)
Nov  4 22:39:39 RT-AC86U-9988 rc_service: udhcpc_wan 13162:notify_rc start_samba
Nov  4 22:39:39 RT-AC86U-9988 rc_service: waitting "stop_samba" via udhcpc_wan ...
Nov  4 22:39:39 RT-AC86U-9988 wsdd2[11920]: Terminated received.
Nov  4 22:39:39 RT-AC86U-9988 wsdd2[11920]: terminating.
Nov  4 22:39:39 RT-AC86U-9988 Samba_Server: smb daemon is stopped
Nov  4 22:39:41 syslogd started: BusyBox v1.25.1
Nov  4 22:39:41 kernel: klogd started: BusyBox v1.25.1 (2023-09-04 11:48:39 EDT)
Nov  4 22:39:41 kernel: klogd: exiting
Nov  4 22:39:41 syslogd exiting
Nov  4 22:39:43 RT-AC86U-9988 uiScribe: Mounting WebUI page for uiScribe
Nov  4 22:39:43 RT-AC86U-9988 uiScribe: Mounted uiScribe WebUI page as Main_LogStatus_Content.asp
Nov  4 22:39:44 RT-AC86U-9988 admin: Started taildns from .
Nov  4 22:40:12 RT-AC86U-9988 wsdd2[14652]: error: wsdd-mcast-v4: wsd_send_soap_msg: send
Nov  4 22:40:12 RT-AC86U-9988 DualWAN: skip single wan wan_led_control - WANRED off
Nov  4 22:40:15 RT-AC86U-9988 wsdd2[14652]: error: wsdd-mcast-v4: wsd_send_soap_msg: send
Nov  4 22:40:15 RT-AC86U-9988 custom_script: Running /jffs/scripts/firewall-start (args: eth0)
Nov  4 22:40:15 RT-AC86U-9988 wan: finish adding multi routes
Nov  4 22:40:15 RT-AC86U-9988 miniupnpd[13662]: shutting down MiniUPnPd
Nov  4 22:40:18 RT-AC86U-9988 custom_config: Appending content of /jffs/configs/dnsmasq.conf.add.
Nov  4 22:40:18 RT-AC86U-9988 custom_script: Running /jffs/scripts/dnsmasq.postconf (args: /etc/dnsmasq.conf)
Nov  4 22:40:18 RT-AC86U-9988 Diversion: created br0:ad_blocking_excl for 192.168.1.16
Nov  4 22:40:18 RT-AC86U-9988 dnsmasq[17417]: started, version 2.89 cachesize 150
Nov  4 22:40:18 RT-AC86U-9988 dnsmasq[17417]: compile time options: IPv6 GNU-getopt no-RTC no-DBus no-UBus no-i18n no-IDN DHCP DHCPv6 no-Lua TFTP no-conntrack ipset no-nftset no-auth cryptohash DNSSEC no-ID loop-detect no-inotify no-dumpfile
Nov  4 22:40:18 RT-AC86U-9988 dnsmasq[17417]: read /etc/hosts - 22 names
Nov  4 22:40:18 RT-AC86U-9988 dnsmasq[17417]: using nameserver 172.16.1.254#53
Nov  4 22:40:18 RT-AC86U-9988 dnsmasq[17417]: using nameserver 172.16.1.254#53 for domain attlocal.net
Nov  4 22:40:18 RT-AC86U-9988 dnsmasq[17417]: using nameserver 172.16.1.254#53
Nov  4 22:40:18 RT-AC86U-9988 dnsmasq[17417]: using nameserver 172.16.1.254#53 for domain attlocal.net
Nov  4 22:40:18 RT-AC86U-9988 Diversion: started separate Dnsmasq instance for ad-blocking exclusion on IP 192.168.1.16
Nov  4 22:40:18 RT-AC86U-9988 Diversion: restarted Dnsmasq to apply settings
Nov  4 22:40:18 RT-AC86U-9988 (dnsmasq.postconf): Updating /etc/dnsmasq.conf for unbound.....
Nov  4 22:40:19 RT-AC86U-9988 uiDivStats: dnsmasq has restarted, restarting taildns
Nov  4 22:40:19 RT-AC86U-9988 custom_script: Running /jffs/scripts/service-event (args: start logger)
Nov  4 22:40:19 syslogd started: BusyBox v1.25.1
Nov  4 22:40:19 kernel: klogd started: BusyBox v1.25.1 (2023-09-04 11:48:39 EDT)
Nov  4 22:40:19 admin: Started syslog-ng from .
Nov  4 22:40:19 kernel: klogd: exiting
Nov  4 22:40:19 syslogd exiting
Nov  4 22:40:26 RT-AC86U-9988 kernel: The For ALL DEVICES flag of Prof 1 has been set to ENABLE
Nov  4 22:40:26 RT-AC86U-9988 kernel: Successfully alloc ctrie: state num=34, mem=680
Nov  4 22:40:30 syslogd started: BusyBox v1.25.1
Nov  4 22:40:30 kernel: klogd started: BusyBox v1.25.1 (2023-09-04 11:48:39 EDT)
Nov  4 22:40:30 kernel: DROP IN=eth0 OUT=eth0 MAC=XX:XX SRC=149.154.175.58 DST=172.16.1.72 LEN=157 TOS=0x00 PREC=0x00 TTL=51 ID=48962 DF PROTO=TCP SPT=443 DPT=45364 SEQ=1958022929 ACK=3668774973 WINDOW=761 RES=0x00 ACK PSH URGP=0 OPT (0101080AC9BFFA5503D93191) MARK=0x8000000
Nov  4 22:40:30 kernel: klogd: exiting
Nov  4 22:40:30 syslogd exiting
Nov  4 22:40:32 RT-AC86U-9988 uiScribe: Mounting WebUI page for uiScribe
Nov  4 22:40:32 RT-AC86U-9988 uiScribe: Mounted uiScribe WebUI page as Main_LogStatus_Content.asp
Nov  4 22:40:34 RT-AC86U-9988 admin: Started taildns from .
Nov  4 22:40:36 RT-AC86U-9988 rc_service: service 21729:notify_rc restart_dnsmasq
Nov  4 22:40:36 RT-AC86U-9988 custom_script: Running /jffs/scripts/service-event (args: restart dnsmasq)
Nov  4 22:40:29 RT-AC86U-9988 dnsmasq[20449]: started, version 2.89 cachesize 150
Nov  4 22:40:36 RT-AC86U-9988 dnsmasq[20449]: overflow: 7 log entries lost
Nov  4 22:40:36 RT-AC86U-9988 custom_config: Appending content of /jffs/configs/dnsmasq.conf.add.
Nov  4 22:40:36 RT-AC86U-9988 custom_script: Running /jffs/scripts/dnsmasq.postconf (args: /etc/dnsmasq.conf)
Nov  4 22:40:37 RT-AC86U-9988 Diversion: created br0:ad_blocking_excl for 192.168.1.16
Nov  4 22:40:37 RT-AC86U-9988 dnsmasq[22177]: started, version 2.89 cachesize 150
Nov  4 22:40:37 RT-AC86U-9988 dnsmasq[22177]: compile time options: IPv6 GNU-getopt no-RTC no-DBus no-UBus no-i18n no-IDN DHCP DHCPv6 no-Lua TFTP no-conntrack ipset no-nftset no-auth cryptohash DNSSEC no-ID loop-detect no-inotify no-dumpfile
Nov  4 22:40:37 RT-AC86U-9988 dnsmasq[22177]: read /etc/hosts - 22 names
Nov  4 22:40:37 RT-AC86U-9988 dnsmasq[22177]: using nameserver 172.16.1.254#53
Nov  4 22:40:37 RT-AC86U-9988 dnsmasq[22177]: using nameserver 172.16.1.254#53 for domain attlocal.net
Nov  4 22:40:37 RT-AC86U-9988 dnsmasq[22177]: using nameserver 172.16.1.254#53
Nov  4 22:40:37 RT-AC86U-9988 dnsmasq[22177]: using nameserver 172.16.1.254#53 for domain attlocal.net
Nov  4 22:40:37 RT-AC86U-9988 Diversion: started separate Dnsmasq instance for ad-blocking exclusion on IP 192.168.1.16
Nov  4 22:40:37 RT-AC86U-9988 Diversion: restarted Dnsmasq to apply settings
Nov  4 22:40:37 RT-AC86U-9988 (dnsmasq.postconf): Updating /etc/dnsmasq.conf for unbound.....
Nov  4 22:40:37 RT-AC86U-9988 uiDivStats: dnsmasq has restarted, restarting taildns
Nov  4 22:40:40 RT-AC86U-9988 admin: Started taildns from .
Nov  4 22:45:00 RT-AC86U-9988 Temp: 50.3 39.5 48.5 ; Mem free: 61460 KB; Swap used: 30296 KB; sda1 wrote: 2284.56 MB
Nov  4 22:57:00 RT-AC86U-9988 (unbound_log.sh): 4134 Processed 0 reply_domains...
Nov  4 22:57:00 RT-AC86U-9988 (unbound_log.sh): 4134 Processed 0 nx_domains...
Nov  4 22:57:00 RT-AC86U-9988 (unbound_log.sh): 4134 Processed 0 RPZ events...
Nov  4 23:00:00 RT-AC86U-9988 Temp: 50.8 39.5 48.5 ; Mem free: 54052 KB; Swap used: 30292 KB; sda1 wrote: 2300.42 MB
Nov  4 23:00:00 RT-AC86U-9988 uiDivStats: Starting stat update
Nov  4 23:00:13 RT-AC86U-9988 uiDivStats: Stats updated successfully
Nov  4 23:15:00 RT-AC86U-9988 Temp: 50.8 39.5 48.5 ; Mem free: 30976 KB; Swap used: 30712 KB; sda1 wrote: 2321.21 MB
 
bibikalka said:
I am running Scribe with Entware.

Sometimes my cron job messages don't make it to the "messages" file for stretches of time, then it's all fine again for a while. Here is an example of a cron job that I want to output to messages every 15 min:

Code: 
cru a temp "*/15 * * * * /jffs/scripts/temp_check  2>&1 | tr -d '\n' | /usr/bin/logger -t Temp"

I tried to fix this with a couple of reboots for a couple of days, still no go, nothing changes. But yesterday night something happens at 22:39+, a bunch of messages in the log appear, and it suddenly starts working again, no reboot. See this chunk of the log at that time. Any possible clues what might be happening?

Code: 
Nov  4 21:29:51 RT-AC86U-9988 kernel: bcm_mcast_mld_add:833 mc_fdb->rep_list ffffffc0035d9ea8 next ffffffc0034c4c20 prev ffffffc0034c4c20 rep_entry->list ffffffc0034c4c20 next ffffffc0035d9ea8 prev ffffffc0035d9ea8
Nov  4 22:00:16 RT-AC86U-9988 kernel: __do_user_fault: 38 callbacks suppressed
Nov  4 22:38:28 RT-AC86U-9988 kernel: eth0 (Int switch port: 3) (Logical Port: 3) Link DOWN.
Nov  4 22:38:28 RT-AC86U-9988 kernel: ===> Activate Deep Green Mode
Nov  4 22:38:50 RT-AC86U-9988 kernel: eth0 (Int switch port: 3) (Logical Port: 3) Link UP 1000 mbps full duplex
Nov  4 22:38:50 RT-AC86U-9988 kernel: <=== Deactivate Deep Green Mode
Nov  4 22:38:53 RT-AC86U-9988 kernel: eth0 (Int switch port: 3) (Logical Port: 3) Link DOWN.
Nov  4 22:38:53 RT-AC86U-9988 kernel: ===> Activate Deep Green Mode
Nov  4 22:39:21 RT-AC86U-9988 kernel: eth0 (Int switch port: 3) (Logical Port: 3) Link UP 1000 mbps full duplex
Nov  4 22:39:21 RT-AC86U-9988 kernel: <=== Deactivate Deep Green Mode
Nov  4 22:39:30 RT-AC86U-9988 admin: Started syslog-ng from .
Nov  4 22:39:30 RT-AC86U-9988 uiScribe: Mounting WebUI page for uiScribe
Nov  4 22:39:30 RT-AC86U-9988 uiScribe: Mounted uiScribe WebUI page as Main_LogStatus_Content.asp
Nov  4 22:39:32 RT-AC86U-9988 WAN_Connection: WAN was restored.
Nov  4 22:39:32 RT-AC86U-9988 miniupnpd[13662]: HTTP listening on port 55864
Nov  4 22:39:32 RT-AC86U-9988 miniupnpd[13662]: Listening for NAT-PMP/PCP traffic on port 5351
Nov  4 22:39:37 RT-AC86U-9988 kernel: The For ALL DEVICES flag of Prof 1 has been set to ENABLE
Nov  4 22:39:37 RT-AC86U-9988 kernel: Successfully alloc ctrie: state num=34, mem=680
Nov  4 22:39:37 RT-AC86U-9988 BWDPI: fun bitmap = 53f
Nov  4 22:39:39 RT-AC86U-9988 custom_script: Running /jffs/scripts/firewall-start (args: eth0)
Nov  4 22:39:39 RT-AC86U-9988 miniupnpd[13662]: SendNATPMPPublicAddressChangeNotification: cannot get public IP address, stopping
Nov  4 22:39:39 RT-AC86U-9988 rc_service: udhcpc_wan 13162:notify_rc stop_samba
Nov  4 22:39:39 RT-AC86U-9988 custom_script: Running /jffs/scripts/service-event (args: stop samba)
Nov  4 22:39:39 RT-AC86U-9988 rc_service: udhcpc_wan 13162:notify_rc start_samba
Nov  4 22:39:39 RT-AC86U-9988 rc_service: waitting "stop_samba" via udhcpc_wan ...
Nov  4 22:39:39 RT-AC86U-9988 wsdd2[11920]: Terminated received.
Nov  4 22:39:39 RT-AC86U-9988 wsdd2[11920]: terminating.
Nov  4 22:39:39 RT-AC86U-9988 Samba_Server: smb daemon is stopped
Nov  4 22:39:41 syslogd started: BusyBox v1.25.1
Nov  4 22:39:41 kernel: klogd started: BusyBox v1.25.1 (2023-09-04 11:48:39 EDT)
Nov  4 22:39:41 kernel: klogd: exiting
Nov  4 22:39:41 syslogd exiting
Nov  4 22:39:43 RT-AC86U-9988 uiScribe: Mounting WebUI page for uiScribe
Nov  4 22:39:43 RT-AC86U-9988 uiScribe: Mounted uiScribe WebUI page as Main_LogStatus_Content.asp
Nov  4 22:39:44 RT-AC86U-9988 admin: Started taildns from .
Nov  4 22:40:12 RT-AC86U-9988 wsdd2[14652]: error: wsdd-mcast-v4: wsd_send_soap_msg: send
Nov  4 22:40:12 RT-AC86U-9988 DualWAN: skip single wan wan_led_control - WANRED off
Nov  4 22:40:15 RT-AC86U-9988 wsdd2[14652]: error: wsdd-mcast-v4: wsd_send_soap_msg: send
Nov  4 22:40:15 RT-AC86U-9988 custom_script: Running /jffs/scripts/firewall-start (args: eth0)
Nov  4 22:40:15 RT-AC86U-9988 wan: finish adding multi routes
Nov  4 22:40:15 RT-AC86U-9988 miniupnpd[13662]: shutting down MiniUPnPd
Nov  4 22:40:18 RT-AC86U-9988 custom_config: Appending content of /jffs/configs/dnsmasq.conf.add.
Nov  4 22:40:18 RT-AC86U-9988 custom_script: Running /jffs/scripts/dnsmasq.postconf (args: /etc/dnsmasq.conf)
Nov  4 22:40:18 RT-AC86U-9988 Diversion: created br0:ad_blocking_excl for 192.168.1.16
Nov  4 22:40:18 RT-AC86U-9988 dnsmasq[17417]: started, version 2.89 cachesize 150
Nov  4 22:40:18 RT-AC86U-9988 dnsmasq[17417]: compile time options: IPv6 GNU-getopt no-RTC no-DBus no-UBus no-i18n no-IDN DHCP DHCPv6 no-Lua TFTP no-conntrack ipset no-nftset no-auth cryptohash DNSSEC no-ID loop-detect no-inotify no-dumpfile
Nov  4 22:40:18 RT-AC86U-9988 dnsmasq[17417]: read /etc/hosts - 22 names
Nov  4 22:40:18 RT-AC86U-9988 dnsmasq[17417]: using nameserver 172.16.1.254#53
Nov  4 22:40:18 RT-AC86U-9988 dnsmasq[17417]: using nameserver 172.16.1.254#53 for domain attlocal.net
Nov  4 22:40:18 RT-AC86U-9988 dnsmasq[17417]: using nameserver 172.16.1.254#53
Nov  4 22:40:18 RT-AC86U-9988 dnsmasq[17417]: using nameserver 172.16.1.254#53 for domain attlocal.net
Nov  4 22:40:18 RT-AC86U-9988 Diversion: started separate Dnsmasq instance for ad-blocking exclusion on IP 192.168.1.16
Nov  4 22:40:18 RT-AC86U-9988 Diversion: restarted Dnsmasq to apply settings
Nov  4 22:40:18 RT-AC86U-9988 (dnsmasq.postconf): Updating /etc/dnsmasq.conf for unbound.....
Nov  4 22:40:19 RT-AC86U-9988 uiDivStats: dnsmasq has restarted, restarting taildns
Nov  4 22:40:19 RT-AC86U-9988 custom_script: Running /jffs/scripts/service-event (args: start logger)
Nov  4 22:40:19 syslogd started: BusyBox v1.25.1
Nov  4 22:40:19 kernel: klogd started: BusyBox v1.25.1 (2023-09-04 11:48:39 EDT)
Nov  4 22:40:19 admin: Started syslog-ng from .
Nov  4 22:40:19 kernel: klogd: exiting
Nov  4 22:40:19 syslogd exiting
Nov  4 22:40:26 RT-AC86U-9988 kernel: The For ALL DEVICES flag of Prof 1 has been set to ENABLE
Nov  4 22:40:26 RT-AC86U-9988 kernel: Successfully alloc ctrie: state num=34, mem=680
Nov  4 22:40:30 syslogd started: BusyBox v1.25.1
Nov  4 22:40:30 kernel: klogd started: BusyBox v1.25.1 (2023-09-04 11:48:39 EDT)
Nov  4 22:40:30 kernel: DROP IN=eth0 OUT=eth0 MAC=XX:XX SRC=149.154.175.58 DST=172.16.1.72 LEN=157 TOS=0x00 PREC=0x00 TTL=51 ID=48962 DF PROTO=TCP SPT=443 DPT=45364 SEQ=1958022929 ACK=3668774973 WINDOW=761 RES=0x00 ACK PSH URGP=0 OPT (0101080AC9BFFA5503D93191) MARK=0x8000000
Nov  4 22:40:30 kernel: klogd: exiting
Nov  4 22:40:30 syslogd exiting
Nov  4 22:40:32 RT-AC86U-9988 uiScribe: Mounting WebUI page for uiScribe
Nov  4 22:40:32 RT-AC86U-9988 uiScribe: Mounted uiScribe WebUI page as Main_LogStatus_Content.asp
Nov  4 22:40:34 RT-AC86U-9988 admin: Started taildns from .
Nov  4 22:40:36 RT-AC86U-9988 rc_service: service 21729:notify_rc restart_dnsmasq
Nov  4 22:40:36 RT-AC86U-9988 custom_script: Running /jffs/scripts/service-event (args: restart dnsmasq)
Nov  4 22:40:29 RT-AC86U-9988 dnsmasq[20449]: started, version 2.89 cachesize 150
Nov  4 22:40:36 RT-AC86U-9988 dnsmasq[20449]: overflow: 7 log entries lost
Nov  4 22:40:36 RT-AC86U-9988 custom_config: Appending content of /jffs/configs/dnsmasq.conf.add.
Nov  4 22:40:36 RT-AC86U-9988 custom_script: Running /jffs/scripts/dnsmasq.postconf (args: /etc/dnsmasq.conf)
Nov  4 22:40:37 RT-AC86U-9988 Diversion: created br0:ad_blocking_excl for 192.168.1.16
Nov  4 22:40:37 RT-AC86U-9988 dnsmasq[22177]: started, version 2.89 cachesize 150
Nov  4 22:40:37 RT-AC86U-9988 dnsmasq[22177]: compile time options: IPv6 GNU-getopt no-RTC no-DBus no-UBus no-i18n no-IDN DHCP DHCPv6 no-Lua TFTP no-conntrack ipset no-nftset no-auth cryptohash DNSSEC no-ID loop-detect no-inotify no-dumpfile
Nov  4 22:40:37 RT-AC86U-9988 dnsmasq[22177]: read /etc/hosts - 22 names
Nov  4 22:40:37 RT-AC86U-9988 dnsmasq[22177]: using nameserver 172.16.1.254#53
Nov  4 22:40:37 RT-AC86U-9988 dnsmasq[22177]: using nameserver 172.16.1.254#53 for domain attlocal.net
Nov  4 22:40:37 RT-AC86U-9988 dnsmasq[22177]: using nameserver 172.16.1.254#53
Nov  4 22:40:37 RT-AC86U-9988 dnsmasq[22177]: using nameserver 172.16.1.254#53 for domain attlocal.net
Nov  4 22:40:37 RT-AC86U-9988 Diversion: started separate Dnsmasq instance for ad-blocking exclusion on IP 192.168.1.16
Nov  4 22:40:37 RT-AC86U-9988 Diversion: restarted Dnsmasq to apply settings
Nov  4 22:40:37 RT-AC86U-9988 (dnsmasq.postconf): Updating /etc/dnsmasq.conf for unbound.....
Nov  4 22:40:37 RT-AC86U-9988 uiDivStats: dnsmasq has restarted, restarting taildns
Nov  4 22:40:40 RT-AC86U-9988 admin: Started taildns from .
Nov  4 22:45:00 RT-AC86U-9988 Temp: 50.3 39.5 48.5 ; Mem free: 61460 KB; Swap used: 30296 KB; sda1 wrote: 2284.56 MB
Nov  4 22:57:00 RT-AC86U-9988 (unbound_log.sh): 4134 Processed 0 reply_domains...
Nov  4 22:57:00 RT-AC86U-9988 (unbound_log.sh): 4134 Processed 0 nx_domains...
Nov  4 22:57:00 RT-AC86U-9988 (unbound_log.sh): 4134 Processed 0 RPZ events...
Nov  4 23:00:00 RT-AC86U-9988 Temp: 50.8 39.5 48.5 ; Mem free: 54052 KB; Swap used: 30292 KB; sda1 wrote: 2300.42 MB
Nov  4 23:00:00 RT-AC86U-9988 uiDivStats: Starting stat update
Nov  4 23:00:13 RT-AC86U-9988 uiDivStats: Stats updated successfully
Nov  4 23:15:00 RT-AC86U-9988 Temp: 50.8 39.5 48.5 ; Mem free: 30976 KB; Swap used: 30712 KB; sda1 wrote: 2321.21 MB
Click to expand...
I noticed something similar while developing the AdGuardHome Auxiliary files with scribe installed. AdGuardHome would not start if I had syslog selected as the default logging location. I would then reboot the router and restart scribe, then AdGuardHome would have no problem starting with syslog selected as the default log location. It appears something is happening that I don't quite understand, but when AdGuardHome cannot load defaults for accessing the syslog it refuses to start altogether.
 
Maybe because scribe converts the syslog file to a directory?
 
elorimer said:
Maybe because scribe converts the syslog file to a directory?
Click to expand...
AdGuardHome is not writing to the "syslog location" directly. It is using GO syslog facilitators to initiate the communications sent to syslog like any other traditional program would. It is failing to initiate communications using the facilitators, so instead it is shutting down automatically. This only happens when the bug issue is present while syslog-ng is running. Once I restart syslog-ng (scribe script) the issue goes away. Syslog-ng starts behaving as the syslog and AdGuardHome GO syslog facilitators start communicating properly with syslog. You are welcome to elaborate more if I am misunderstanding you. I can always select /jffs/syslog.log as the log location if want to, but the entries do not come through properly.
 
Last edited:
I thought maybe you were doing something with log.file. NVM
 
Logging was not working, updated to 386.12_4, it suddenly started working, but with a ~30 min delay after a reboot. Cannot believe it takes that long for post-mount script to get to the scheduling command:

Code: 
> egrep 'ntpd|BusyBox|Temp' messages

Nov 23 13:36:26 ntpd: Started ntpd
Nov 23 13:37:06 ntpd: Initial clock set
Nov 23 13:37:06 rc_service: ntpd_synced 1940:notify_rc restart_diskmon
Nov 23 13:37:24 syslogd started: BusyBox v1.25.1
Nov 23 13:37:24 kernel: klogd started: BusyBox v1.25.1 (2023-11-21 22:37:39 EST)
Nov 23 13:37:24 syslogd started: BusyBox v1.25.1
Nov 23 13:37:24 kernel: klogd started: BusyBox v1.25.1 (2023-11-21 22:37:39 EST)
Nov 23 14:00:00 RT-AC86U-9988 Temp: 48.3 39.0 48.5 ; Mem free: 28160 KB; Swap used: 2556 KB; sda1 wrote: 35.59 MB
Nov 23 14:15:00 RT-AC86U-9988 Temp: 48.8 38.5 48.0 ; Mem free: 31076 KB; Swap used: 4044 KB; sda1 wrote: 59.08 MB
Nov 23 14:30:00 RT-AC86U-9988 Temp: 51.8 40.0 49.0 ; Mem free: 33104 KB; Swap used: 5560 KB; sda1 wrote: 78.53 MB
Nov 23 14:45:01 RT-AC86U-9988 Temp: 49.8 39.0 48.5 ; Mem free: 29248 KB; Swap used: 8292 KB; sda1 wrote: 100.92 MB
...
Nov 24 04:05:19 ntpd: Started ntpd
Nov 24 04:06:08 ntpd: Initial clock set
Nov 24 04:06:08 rc_service: ntpd_synced 1922:notify_rc restart_diskmon
Nov 24 04:06:24 RT-AC86U-9988 admin: Started ntpd from /jffs/scripts/post-mount.
Nov 24 04:06:33 syslogd started: BusyBox v1.25.1
Nov 24 04:06:33 kernel: klogd started: BusyBox v1.25.1 (2023-11-21 22:37:39 EST)
Nov 24 04:45:00 RT-AC86U-9988 Temp: 48.8 38.5 47.5 ; Mem free: 31160 KB; Swap used: 0 KB; sda1 wrote: 44.91 MB
Nov 24 05:00:00 RT-AC86U-9988 Temp: 48.8 38.5 47.5 ; Mem free: 27124 KB; Swap used: 0 KB; sda1 wrote: 63.56 MB
Nov 24 05:15:00 RT-AC86U-9988 Temp: 48.3 39.0 47.5 ; Mem free: 32700 KB; Swap used: 2176 KB; sda1 wrote: 90.33 MB
Nov 24 05:30:00 RT-AC86U-9988 Temp: 47.9 38.5 47.5 ; Mem free: 30076 KB; Swap used: 2172 KB; sda1 wrote: 107.18 MB
...
 
If klogd or syslogd is running, then scribe is dead. Syslog-ng will be trying to poll the sockets at the same time as klogd and syslogd are trying to do the same.
 
bibikalka said:
Logging was not working, updated to 386.12_4, it suddenly started working, but with a ~30 min delay after a reboot. Cannot believe it takes that long for post-mount script to get to the scheduling command:

Code: 
> egrep 'ntpd|BusyBox|Temp' messages

Nov 23 13:36:26 ntpd: Started ntpd
Nov 23 13:37:06 ntpd: Initial clock set
Nov 23 13:37:06 rc_service: ntpd_synced 1940:notify_rc restart_diskmon
Nov 23 13:37:24 syslogd started: BusyBox v1.25.1
Nov 23 13:37:24 kernel: klogd started: BusyBox v1.25.1 (2023-11-21 22:37:39 EST)
Nov 23 13:37:24 syslogd started: BusyBox v1.25.1
Nov 23 13:37:24 kernel: klogd started: BusyBox v1.25.1 (2023-11-21 22:37:39 EST)
Nov 23 14:00:00 RT-AC86U-9988 Temp: 48.3 39.0 48.5 ; Mem free: 28160 KB; Swap used: 2556 KB; sda1 wrote: 35.59 MB
Nov 23 14:15:00 RT-AC86U-9988 Temp: 48.8 38.5 48.0 ; Mem free: 31076 KB; Swap used: 4044 KB; sda1 wrote: 59.08 MB
Nov 23 14:30:00 RT-AC86U-9988 Temp: 51.8 40.0 49.0 ; Mem free: 33104 KB; Swap used: 5560 KB; sda1 wrote: 78.53 MB
Nov 23 14:45:01 RT-AC86U-9988 Temp: 49.8 39.0 48.5 ; Mem free: 29248 KB; Swap used: 8292 KB; sda1 wrote: 100.92 MB
...
Nov 24 04:05:19 ntpd: Started ntpd
Nov 24 04:06:08 ntpd: Initial clock set
Nov 24 04:06:08 rc_service: ntpd_synced 1922:notify_rc restart_diskmon
Nov 24 04:06:24 RT-AC86U-9988 admin: Started ntpd from /jffs/scripts/post-mount.
Nov 24 04:06:33 syslogd started: BusyBox v1.25.1
Nov 24 04:06:33 kernel: klogd started: BusyBox v1.25.1 (2023-11-21 22:37:39 EST)
Nov 24 04:45:00 RT-AC86U-9988 Temp: 48.8 38.5 47.5 ; Mem free: 31160 KB; Swap used: 0 KB; sda1 wrote: 44.91 MB
Nov 24 05:00:00 RT-AC86U-9988 Temp: 48.8 38.5 47.5 ; Mem free: 27124 KB; Swap used: 0 KB; sda1 wrote: 63.56 MB
Nov 24 05:15:00 RT-AC86U-9988 Temp: 48.3 39.0 47.5 ; Mem free: 32700 KB; Swap used: 2176 KB; sda1 wrote: 90.33 MB
Nov 24 05:30:00 RT-AC86U-9988 Temp: 47.9 38.5 47.5 ; Mem free: 30076 KB; Swap used: 2172 KB; sda1 wrote: 107.18 MB
...
Click to expand...
try running option 'lr' within scribe, then post the terminal output here (screen shots preferred). Next run option 'rs' in scribe, post the output here as well.

example of what the output of 'lr' should look like:

1700895972755.png


example of what 'rs' should look like:

1700896032699.png
 
SomeWhereOverTheRainBow said:
try running option 'lr' within scribe, then post the terminal output here (screen shots preferred). Next run option 'rs' in scribe, post the output here as well.

example of what the output of 'lr' should look like:



example of what 'rs' should look like:
Click to expand...
Here is the output, as requested.
 

Attachments

  • scribe2.png
    scribe2.png
    73.8 KB · Views: 39
  • scribe3.png
    scribe3.png
    134.6 KB · Views: 31
bibikalka said:
Here is the output, as requested.
Click to expand...
interesting.... Your scribe is reading from /tmp/syslog.log, instead of /jffs/syslog.log.... Welp, I don't see any errors, but I am not sure /tmp/syslog.log is a persistant place to read logs from since /tmp is a volatile location on our routers.
 
Last edited:
As the script notes, random routers natively write to /tmp/syslog.log instead of /jffs/syslog.log. Scribe on install figures out which and stores it, so that when it exits and restarts the native logger it restores the location. At least I think thats what I recall from the discussion.

And just to be clear, scribe is the installation/management script for syslog-ng. It kills the native syslogd and starts syslog-ng. syslog-ng reads from /dev/log and /proc/ and writes to files typically at /opt/var/log, including messages. It doesn't read from /jffs/syslog.log or /tmp/syslog.log.

I think the OP's problem might be that something is restarting klogd or syslogd while syslog-ng is still running, leading to a race over which is harvesting which messages from the sockets.
 
elorimer said:
As the script notes, random routers natively write to /tmp/syslog.log instead of /jffs/syslog.log. Scribe on install figures out which and stores it, so that when it exits and restarts the native logger it restores the location. At least I think thats what I recall from the discussion.

And just to be clear, scribe is the installation/management script for syslog-ng. It kills the native syslogd and starts syslog-ng. syslog-ng reads from /dev/log and /proc/ and writes to files typically at /opt/var/log, including messages. It doesn't read from /jffs/syslog.log or /tmp/syslog.log.

I think the OP's problem might be that something is restarting klogd or syslogd while syslog-ng is still running, leading to a race over which is harvesting which messages from the sockets.
Click to expand...
I am curious as to what service (or script) is restarting klogd or syslogd. Are there any scheduled maintenance that scribe does with syslog-ng and logrotate where their services may be stopped log enough for klogd or syslogd to creep their way back into existence? I notice when issues like this happens when AGH is running, it causes AGH not to be able to determine the appropriate interpreter (log facilitator) of the sockets. It causes AGH to either not start/ or to completely crash. I am wondering if dnsmasg log-async also has such issues.
 
Last edited:
1. Scribe doesn't do scheduled maintenance. It starts and then gets out of the way until the next rc call.
2. That said, the last update does a lot of work in the beginning to try and kill syslogd and klogd with comments about unknown processes restarting them. So there may be something going on for the scripter to have coded this.
3. Logrotate does do a sighup to restart syslog-ng when it runs nightly. But man, logrotate is so fast it would be odd for something to sidle in there.
4. I know absolute zero about AGH and so I wonder why it has any vulnerability to whether syslogd or syslog-ng is polling /dev or /proc. I don't know that syslog-ng does it different from syslogd; I just know that @kvic recognized ten years ago that both couldn't be running at the same time.
 
elorimer said:
...

I think the OP's problem might be that something is restarting klogd or syslogd while syslog-ng is still running, leading to a race over which is harvesting which messages from the sockets.
Click to expand...
elorimer said:
...
4. I know absolute zero about AGH and so I wonder why it has any vulnerability to whether syslogd or syslog-ng is polling /dev or /proc. I don't know that syslog-ng does it different from syslogd; I just know that @kvic recognized ten years ago that both couldn't be running at the same time.
Click to expand...

What is interesting is that missing logging persisted across reboots, sometimes several of them! This was happening on version 386.12_0. Then it would start working again, and that persisted across several reboots too.

So far 386.12_4 seems to be well behaved, I'll keep observing if the logging disappears for some reason.
 
bibikalka said:
What is interesting is that missing logging persisted across reboots, sometimes several of them! This was happening on version 386.12_0. Then it would start working again, and that persisted across several [software] reboots too.

So far 386.12_4 seems to be well behaved, I'll keep observing if the logging disappears for some reason.
Click to expand...

OK, 12_4 does exactly the same things. Sometimes it works for stretches of times, sometimes the messages are missing. Software reboot does not fix it. But with all asd/dcd micro-crashes it tends to switch on or off by itself after a few days.

Recently it occurred to me that a hard reboot (button push or power jack pulled out) may work differently. Today I tested that - messages were not printed before the reboot. I physically turned off and turned on the router again, and it started printed the messages again.

So hard reboot is the way to go :)
 
Quick update. After setting the cron reboot command to the following, the issue has gone away. Now the output appears to always be there:
Code: 
cru a ScheduledReboot "5 4 * * * /sbin/service 'reboot'"
 
You must log in or register to reply here.

Similar threads

B
Entware Where is Entware started upon reboot?
2
Replies
25
Views
1K
bibikalka
B
W
Is one of my add-ons stopping my WAN connection
Replies
3
Views
1K
ColinTaylor
C
R
Solved RT-AX86U Pro log repeats "WAN_Connection: WAN was restored" while red light keeps on and no Internet connection?
2
Replies
24
Views
3K
Rici
R
T
CakeQOS Cake Stops for No Apparent Reason
Replies
1
Views
1K
TonyK132
T
saison2023
Any way to diagnose further these dnsmasq restart events?
Replies
5
Views
751
saison2023
saison2023
Similar threads
Thread starter Title Forum Replies Date
F Solved Compilation error /opt/bin/ld: cannot find Asuswrt-Merlin AddOns 1

Similar threads

Latest threads

Support SNBForums w/ Amazon

If you'd like to support SNBForums, just use this link and buy anything on Amazon. Thanks!

Sign Up For SNBForums Daily Digest

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

Members online

Total: 886 (members: 17, guests: 869)
Top