unmount script not running on AC86U

[cmkelley]

I'm starting to think that your router isn't actually shutting down at all but just crashing as soon as the shutdown/reboot command is issued.

Well, maybe somewhere in the reboot process ... I set logging to all, added @RMerlin's suggested line to unmount ("date >> /jffs/000debug"), and reinstalled @john9527's logging modified firmware. The 000debug file was not touched, and syslog shows (I may have went overboard on redactions below):

Dec 12 19:28:29 kernel: UBIFS (ubi1:0): UBIFS: mounted UBI device 1, volume 0, name "nvram", R/O mode
Dec 12 19:28:29 kernel: UBIFS (ubi1:0): LEB size: 126976 bytes (124 KiB), min./max. I/O unit sizes: 2048 bytes/2048 bytes
Dec 12 19:28:29 kernel: UBIFS (ubi1:0): FS size: 5840896 bytes (5 MiB, 46 LEBs), journal size 1015809 bytes (0 MiB, 6 LEBs)
Dec 12 19:28:29 kernel: UBIFS (ubi1:0): reserved for root: 275879 bytes (269 KiB)
Dec 12 19:28:29 kernel: UBIFS (ubi1:0): media format: w4/r0 (latest is w4/r0), UUID 700E756D-208E-4C91-B256-B51AA3EDE77F, small LPT
model
Dec 12 19:28:29 kernel: UBIFS (ubi1:0): un-mount UBI device 1
Dec 12 19:28:29 kernel: ubi1: detaching mtd9
Dec 12 19:28:29 kernel: ubi1: mtd9 is detached
Dec 12 19:28:42 roamast: eth6: add client [redacted] to monitor list
Dec 12 19:28:52 roamast: eth6: add client [redacted] to monitor list
Dec 12 19:30:07 roamast: eth6: add client [redacted]] to monitor list
Dec 12 19:32:20 dropbear[3251]: Child connection from [redacted]
Dec 12 19:32:21 dropbear[3251]: Pubkey auth succeeded for '[redacted]' with key sha1!! [redacted]
Dec 12 19:34:25 dropbear[3251]: Exit (lionroot): Exited normally
Dec 12 19:35:00 rc_service: httpd 809:notify_rc reboot
Dec 12 19:35:00 lldpd[935]: removal request for address of [redacted], but no knowledge of it
Dec 12 19:35:00 lldpd[935]: removal request for address of [redacted], but no knowledge of it
Dec 12 19:35:00 lldpd[935]: removal request for address of [redacted], but no knowledge of it
Dec 12 19:35:00 lldpd[935]: removal request for address of [redacted], but no knowledge of it
Dec 12 19:35:00 lldpd[935]: removal request for address of [redacted], but no knowledge of it
Dec 12 19:35:00 iTunes: daemon is stopped
Dec 12 19:35:00 FTP_Server: daemon is stopped
Dec 12 19:35:00 Samba_Server: smb daemon is stopped
Dec 12 19:35:00 Timemachine: daemon is stopped
Dec 12 19:35:00 WEBDAV_Server: daemon is stopped
Dec 12 19:35:00 kernel: usbcore: deregistering interface driver cdc_mbim
Dec 12 19:35:01 kernel: usbcore: deregistering interface driver qmi_wwan
Dec 12 19:35:01 kernel: usbcore: deregistering interface driver huawei_cdc_ncm
Dec 12 19:35:01 kernel: usbcore: deregistering interface driver cdc_wdm
Dec 12 19:35:01 kernel: usbcore: deregistering interface driver cdc_ncm
Dec 12 19:35:01 kernel: usbcore: deregistering interface driver rndis_host
Dec 12 19:35:01 kernel: usbcore: deregistering interface driver cdc_ether
Dec 12 19:35:01 kernel: usbcore: deregistering interface driver ax88179_178a
Dec 12 19:35:01 kernel: usbcore: deregistering interface driver asix
Dec 12 19:35:01 kernel: usbcore: deregistering interface driver cdc_acm
Dec 12 19:35:01 kernel: cdrom: Uniform CD-ROM driver unloaded
Dec 12 19:35:01 kernel: usbcore: deregistering interface driver usblp
Dec 12 19:35:02 Services.Spoof: Services stopped!
=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=
*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*
=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=
May 04 22:05:05 Init.Spoof: Init starting ...
Dec 12 19:35:02 syslogd started: BusyBox v1.25.1
Dec 12 19:35:02 kernel: klogd started: BusyBox v1.25.1 (2018-12-09 14:48:01 MST)
Dec 12 19:35:02 kernel: Booting Linux on physical CPU 0x0
Dec 12 19:35:02 kernel: Linux version 4.1.27 (jbacho@ASUS-AJ082535) (gcc version 5.3.0 (Buildroot 2016.02) ) #2 SMP PREEMPT Sun Dec
9 15:27:25 MST 2018
Dec 12 19:35:02 kernel: CPU: AArch64 Processor [420f1000] revision 0
Dec 12 19:35:02 kernel: Detected VIPT I-cache on CPU0
Dec 12 19:35:02 kernel: alternatives: enabling workaround for ARM erratum 845719
Dec 12 19:35:02 kernel: On node 0 totalpages: 123904
Dec 12 19:35:02 kernel:   DMA zone: 1792 pages used for memmap
Dec 12 19:35:02 kernel:   DMA zone: 0 pages reserved
Dec 12 19:35:02 kernel:   DMA zone: 123904 pages, LIFO batch:31

"Services.Spoof" is created by the last line in my services-stop script, and the 3-line flag and "Init.Spoof" are created by the first lines in my init-start script. Makes finding the reboots easy. Right after the Init.Spoof line it reads the fake-hwclock.save file that I write out in services-stop to bring up the clock to a reasonable timestamp.

 

[cmkelley]

Okay ... since the only way I seem to be able to get my unmount script to run is to do a firmware update, I put my comments back in my unmount script so it would try logger as well as spit out spoofed data into syslog:

#!/bin/sh

Swap=".swap"

echo `date "+%b   %d %T"` "Unmount.Spoof: Unmounting $1 ..."  >> /jffs/syslog.log
/usr/bin/logger -t Unmount "Umounting $1 ..."

SWP="$(find $1/$Swap 2> /dev/null)"
if [ "$SWP" ]; then
        echo `date "+%b   %d %T"` "Swap.Spoof: Shutting down swap $1/$Swap ..."  >> /jffs/syslog.log
        /usr/bin/logger -t Swap "Shutting down swap $1/$Swap ..."
        swapoff $1/$Swap # cleanly close swap
fi

echo `date "+%b   %d %T"` "Swap.Spoof: Swap $1/$Swap closed."  >> /jffs/syslog.log
/usr/bin/logger -t Swap "Swap $1/$Swap closed."

So, when I "upgrade" the firmware (really just rewriting the same firmware), I get ...

Dec 12 20:46:51 dropbear[3174]: Child connection from [redacted]
Dec 12 20:46:51 dropbear[3174]: Pubkey auth succeeded for '[redacted]' with key sha1!! [redacted] from [redacted]
Dec 12 20:48:22 dropbear[3174]: Exit ([redacted]): Exited normally
Dec 12 20:49:40 custom_script: Running /jffs/scripts/unmount (args: /tmp/mnt/usbssd ) - max timeout = 120s
Dec 12 20:49:40 Unmount: Umounting /tmp/mnt/usbssd ...
Dec 12 20:49:40 Swap: Shutting down swap /tmp/mnt/usbssd/.swap ...
Dec 12 20:49:40 Swap: Swap /tmp/mnt/usbssd/.swap closed.
Dec 12 20:49:41 ejusb: USB partition unmounted from /tmp/mnt/usbssd fail. (return -1, Bad file descriptor)
Dec 12 20:49:41 rc_service: ejusb 3297:notify_rc stop_nasapps
Dec 12 20:49:41 avahi-daemon[2036]: Files changed, reloading.
Dec 12 20:49:41 avahi-daemon[2036]: Loading service file /tmp/avahi/services/mt-daap.service.
Dec 12 20:49:41 iTunes: daemon is stopped
Dec 12 20:49:41 FTP_Server: daemon is stopped
Dec 12 20:49:41 avahi-daemon[2036]: Service "RT-AC86U-84E8" (/tmp/avahi/services/mt-daap.service) successfully established.
Dec 12 20:49:42 ejusb: USB partition unmounted from /tmp/mnt/usbssd fail. (return -1, Bad file descriptor)
Dec 12 20:49:42 Samba_Server: smb daemon is stopped
Dec 12 20:49:42 avahi-daemon[2036]: Got SIGTERM, quitting.
Dec 12 20:49:42 avahi-daemon[2036]: Leaving mDNS multicast group on interface br0.IPv4 with address [redacted].
Dec 12 20:49:42 avahi-daemon[2036]: Leaving mDNS multicast group on interface lo.IPv4 with address 127.0.0.1.
Dec 12 20:49:42 avahi-daemon[2036]: avahi-daemon 0.7 exiting.
Dec 12 20:49:42 Timemachine: daemon is stopped
Dec 12 20:49:42 avahi-daemon[3327]: Found user 'nobody' (UID 65534) and group 'nobody' (GID 65534).
Dec 12 20:49:42 avahi-daemon[3327]: Successfully dropped root privileges.
Dec 12 20:49:42 avahi-daemon[3327]: avahi-daemon 0.7 starting up.
Dec 12 20:49:42 avahi-daemon[3327]: WARNING: No NSS support for mDNS detected, consider installing nss-mdns!
Dec 12 20:49:42 avahi-daemon[3327]: No service file found in /tmp/avahi/services.
Dec 12 20:49:42 avahi-daemon[3327]: Loading new alias name RT-AC86U.
Dec 12 20:49:42 avahi-daemon[3327]: Joining mDNS multicast group on interface br0.IPv4 with address [redacted].
Dec 12 20:49:42 avahi-daemon[3327]: New relevant interface br0.IPv4 for mDNS.
Dec 12 20:49:42 avahi-daemon[3327]: Joining mDNS multicast group on interface lo.IPv4 with address 127.0.0.1.
Dec 12 20:49:42 avahi-daemon[3327]: New relevant interface lo.IPv4 for mDNS.
Dec 12 20:49:42 avahi-daemon[3327]: Network interface enumeration completed.
Dec 12 20:49:42 avahi-daemon[3327]: Registering new address record for [redacted] on br0.IPv4.
Dec 12 20:49:42 avahi-daemon[3327]: Registering new address record for [redacted] on br0.IPv4.
Dec 12 20:49:42 avahi-daemon[3327]: Registering new address record for 127.0.0.1 on lo.IPv4.
Dec 12 20:49:43 ejusb: USB partition unmounted from /tmp/mnt/usbssd fail. (return -1, Bad file descriptor)
Dec 12 20:49:43 avahi-daemon[3327]: Server startup complete. Host name is RT-AC86U-84E8.local. Local service cookie is 3838972857.
Dec 12 20:49:43 avahi-daemon[3327]: Alias name "RT-AC86U" successfully established.
Dec 12 20:49:44 ejusb: USB partition unmounted from /tmp/mnt/usbssd fail. (return -1, Bad file descriptor)
Dec 12 20:49:45 ejusb: USB partition unmounted from /tmp/mnt/usbssd fail. (return -1, Bad file descriptor)
Dec 12 20:49:46 ejusb: USB partition unmounted from /tmp/mnt/usbssd fail. (return -1, Bad file descriptor)
Dec 12 20:49:47 ejusb: USB partition unmounted from /tmp/mnt/usbssd fail. (return -1, Bad file descriptor)
Dec 12 20:49:48 ejusb: USB partition unmounted from /tmp/mnt/usbssd fail. (return -1, Bad file descriptor)
Dec 12 20:49:49 ejusb: USB partition unmounted from /tmp/mnt/usbssd fail. (return -1, Bad file descriptor)
Dec 12 20:49:50 ejusb: USB partition unmounted from /tmp/mnt/usbssd fail. (return -1, Bad file descriptor)
Dec 12 20:49:51 ejusb: USB partition unmounted from /tmp/mnt/usbssd fail. (return -1, Bad file descriptor)
Dec 12 20:49:52 ejusb: USB partition unmounted from /tmp/mnt/usbssd fail. (return -1, Bad file descriptor)
Dec 12 20:49:53 ejusb: USB partition unmounted from /tmp/mnt/usbssd fail. (return -1, Bad file descriptor)
Dec 12 20:49:54 ejusb: USB partition unmounted from /tmp/mnt/usbssd fail. (return -1, Bad file descriptor)
Dec 12 20:49:55 ejusb: USB partition unmounted from /tmp/mnt/usbssd fail. (return -1, Bad file descriptor)
Dec 12 20:49:56 ejusb: USB partition unmounted from /tmp/mnt/usbssd fail. (return -1, Bad file descriptor)
Dec 12 20:49:57 ejusb: USB partition unmounted from /tmp/mnt/usbssd fail. (return -1, Bad file descriptor)
=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=
*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*
=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=
May 04 22:05:06 Init.Spoof: Init starting ...
Dec 12 20:45:34 syslogd started: BusyBox v1.25.1
Dec 12 20:45:34 kernel: klogd started: BusyBox v1.25.1 (2018-12-09 14:48:01 MST)
Dec 12 20:45:34 kernel: Booting Linux on physical CPU 0x0
Dec 12 20:45:34 kernel: Linux version 4.1.27 (jbacho@ASUS-AJ082535) (gcc version 5.3.0 (Buildroot 2016.02) ) #2 SMP PREEMPT Sun Dec 9 15:27:25 MST 2018

No clue why I didn't get the fail announcements before. Maybe I didn't save the changes to the logging levels? Whatever. Of note, I formatted the drive on the router with mkfs.ext4. The drive previously had OpenBSD on it. Maybe I should have zero'd the drive first?

Neat that avahi-daemon decides it needs to restart itself ...

Meh, bedtime.

 

[john9527]

@cmkelley OK....thanks for the syslog. This is interesting....

the key code sequence here is

1. if the usb is disabled or there are no usbdrives, shut down any open usb apps, check by running unmount script and unmount any partitions, and remove usb support
2. run services_stop
3. shut down all the other services except for usb
4. come back and shut down any open usb apps, run unmount script and force unmount any partitions and remove usb support
5. stop the logger
6. SIGTERM the main process and reboot

So it looks like @ColinTaylor was almost right. Based on missing log entries, it looks like the router is crashing in step (3). Leading candidates right now is that the router is crashing when stopping mastiff or the bwdpi engine.
I'll generate another build with some diagnostic logging to try and narrow down what's crashing.

 

[preacher65]

If this helps to know, I've started following this thread because my AC86U is exhibiting the same behaviour - unmount script doesn't seem to run on reboot. After reading here I have now tried touching a file from unmount as well as writing to syslog, but it only happens if I unmount from the GUI, not on reboot. I could help with testing at the weekend if you need anyone else, otherwise I'm following with interest!

 

[cmkelley]

@john9527, syslog dump from your RT-AC86U_384.8_2lg3 firmware, starting when I exit from an SSH session. Still not executing unmount script:

Dec 14 09:40:18 dropbear[4473]: Exit ([redacted]): Exited normally
Dec 14 09:40:26 rc_service: httpd 812:notify_rc reboot
Dec 14 09:40:26 lldpd[938]: removal request for address of [redacted], but no knowledge of it
Dec 14 09:40:26 lldpd[938]: removal request for address of [redacted], but no knowledge of it
Dec 14 09:40:26 lldpd[938]: removal request for address of [redacted], but no knowledge of it
Dec 14 09:40:26 lldpd[938]: removal request for address of [redacted], but no knowledge of it
Dec 14 09:40:26 lldpd[938]: removal request for address of [redacted], but no knowledge of it
Dec 14 09:40:27 iTunes: daemon is stopped
Dec 14 09:40:27 FTP_Server: daemon is stopped
Dec 14 09:40:27 Samba_Server: smb daemon is stopped
Dec 14 09:40:27 Timemachine: daemon is stopped
Dec 14 09:40:27 WEBDAV_Server: daemon is stopped
Dec 14 09:40:27 kernel: usbcore: deregistering interface driver cdc_mbim
Dec 14 09:40:27 kernel: usbcore: deregistering interface driver qmi_wwan
Dec 14 09:40:27 kernel: usbcore: deregistering interface driver huawei_cdc_ncm
Dec 14 09:40:27 kernel: usbcore: deregistering interface driver cdc_wdm
Dec 14 09:40:27 kernel: usbcore: deregistering interface driver cdc_ncm
Dec 14 09:40:27 kernel: usbcore: deregistering interface driver rndis_host
Dec 14 09:40:27 kernel: usbcore: deregistering interface driver cdc_ether
Dec 14 09:40:27 kernel: usbcore: deregistering interface driver ax88179_178a
Dec 14 09:40:27 kernel: usbcore: deregistering interface driver asix
Dec 14 09:40:27 kernel: usbcore: deregistering interface driver cdc_acm
Dec 14 09:40:27 kernel: cdrom: Uniform CD-ROM driver unloaded
Dec 14 09:40:27 kernel: usbcore: deregistering interface driver usblp
Dec 14 09:40:28 Services.Spoof: Services stopped!
=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=
*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*
=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=
May 04 22:05:05 Init.Spoof: Init starting ...
Dec 14 09:40:28 syslogd started: BusyBox v1.25.1
Dec 14 09:40:28 kernel: klogd started: BusyBox v1.25.1 (2018-12-14 00:33:15 MST)
Dec 14 09:40:28 kernel: Booting Linux on physical CPU 0x0
Dec 14 09:40:28 kernel: Linux version 4.1.27 (jbacho@ASUS-AJ082535) (gcc version 5.3.0 (Buildroot 2016.02) ) #2 SMP PREEMPT Fri Dec 14 01:13:04 MST 2018

 

[john9527]

@cmkelley

Please post or PM me your services-stop script....

 

[cmkelley]

@cmkelley

Please post or PM me your services-stop script....

#!/bin/sh

/opt/etc/init.d/rc.unslung stop

# the very last thing to do
/jffs/scripts/fake-hwclock save

echo `date "+%b   %d %T"` "Services.Spoof: Services stopped!"  >> /jffs/syslog.log

 

[john9527]

@cmkelley....I'm at a loss as to why things are hanging trying to stop the various services. Please humor me and replace the echo to the syslog with a call to logger.

 

[cmkelley]

Changed ...

logger -t Services "Services stopped!"
# echo `date "+%b   %d %T"` "Services.Spoof: Services stopped!"  >> /jffs/syslog.log

The first time I rebooted I got something very interesting ...

Dec 14 10:34:44 dropbear[5285]: Exit ([redacted]): Exited normally
Dec 14 10:35:03 rc_service: httpd 811:notify_rc reboot
Dec 14 10:35:03 lldpd[936]: removal request for address of [redacted], but no knowledge of it
Dec 14 10:35:03 lldpd[936]: removal request for address of [redacted], but no knowledge of it
Dec 14 10:35:03 lldpd[936]: removal request for address of [redacted], but no knowledge of it
Dec 14 10:35:03 lldpd[936]: removal request for address of [redacted], but no knowledge of it
Dec 14 10:35:03 lldpd[936]: removal request for address of [redacted], but no knowledge of it
Dec 14 10:35:03 iTunes: daemon is stopped
Dec 14 10:35:03 FTP_Server: daemon is stopped
Dec 14 10:35:05 Samba_Server: smb daemon is stopped
Dec 14 10:35:05 Timemachine: daemon is stopped
Dec 14 10:35:05 WEBDAV_Server: daemon is stopped
Dec 14 10:35:05 kernel: usbcore: deregistering interface driver cdc_mbim
Dec 14 10:35:05 kernel: usbcore: deregistering interface driver qmi_wwan
Dec 14 10:35:05 kernel: usbcore: deregistering interface driver huawei_cdc_ncm
Dec 14 10:35:05 kernel: usbcore: deregistering interface driver cdc_wdm
Dec 14 10:35:05 kernel: usbcore: deregistering interface driver cdc_ncm
Dec 14 10:35:05 kernel: usbcore: deregistering interface driver rndis_host
Dec 14 10:35:05 kernel: usbcore: deregistering interface driver cdc_ether
Dec 14 10:35:05 kernel: usbcore: deregistering interface driver ax88179_178a
Dec 14 10:35:05 kernel: usbcore: deregistering interface driver asix
Dec 14 10:35:05 kernel: usbcore: deregistering interface driver cdc_acm
Dec 14 10:35:05 kernel: cdrom: Uniform CD-ROM driver unloaded
Dec 14 10:35:05 kernel: usbcore: deregistering interface driver usblp
Dec 14 10:35:05 custom_script: Running /jffs/scripts/services-stop
Dec 14 10:35:05 stop_services: stopping erp_monitor
Dec 14 10:35:05 stop_services: stopping hour_monitor
Dec 14 10:35:05 stop_services: stopping bwdpi_wred_alive
Dec 14 10:35:05 stop_services: stopping bwdpi_check
Dec 14 10:35:05 stop_services: stopping dpi_engine
Dec 14 10:35:05 pixelserv-tls[1791]: 3225 uts, 1 log, 0 kcc, 13 kmx, 1.09 kvg, 4 krq, 920 req, 225 avg, 1599 rmx, 4 tav, 62 tmx, 3 slh, 4 slm, 0 sle, 383 slc, 385 slu, 12 v13, 0 v12, 0 v10, 0 uca, 0 ucb, 0 uce, 223 ush, 126 sct, 809 sch, 5 scm, 0 scp, 704 sst, 34 ssh, 0 ssm, 0 ssp, 0 nfe, 0 gif, 0 ico, 1 txt, 0 jpg, 92 png, 0 swf, 0 sta, 0 stt, 0 ufe, 0 opt, 0 pst, 0 hed, 0 rdr, 0 nou, 0 pth, 0 204, 0 bad, 12 tmo, 426 cls, 0 cly, 0 clt, 0 err
Dec 14 10:35:05 kernel: IDPfw: Exit IDPfw
Dec 14 10:35:05 kernel: mod epilog takes 0 jiffies
Dec 14 10:35:05 kernel: IDPfw: Exit IDPfw
Dec 14 10:35:06 kernel: Exit chrdev /dev/idpfw with major 191
Dec 14 10:35:06 kernel: Exit chrdev /dev/detector with major 190
Dec 14 10:35:06 stop_services: stopping webdav
Dec 14 10:35:06 WEBDAV_Server: daemon is stopped
Dec 14 10:35:06 stop_services: stopping mastiff
Dec 14 10:35:06 Mastiff: Got SIGTERM
=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=
*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*
=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=
May 04 22:05:05 Init.Spoof: Init starting ...
Dec 14 10:35:05 syslogd started: BusyBox v1.25.1
Dec 14 10:35:05 kernel: klogd started: BusyBox v1.25.1 (2018-12-14 00:33:15 MST)
Dec 14 10:35:05 kernel: Booting Linux on physical CPU 0x0
Dec 14 10:35:05 kernel: Linux version 4.1.27 (jbacho@ASUS-AJ082535) (gcc version 5.3.0 (Buildroot 2016.02) ) #2 SMP PREEMPT Fri Dec 14 01:13:04 MST 2018

The second time I got literally exactly the same as my previous post only without the "Services.Spoof" entry, also no logger entry. One thing that I found weird is that the first time the line "Dec 14 10:35:05 custom_script: Running /jffs/scripts/services-stop" appeared, which I don't remember seeing before. Indeed it's not present in my previous post, even though very clearly the services-stop script ran, since the spoof to syslog ran.

 

[preacher65]

One thing that I found weird is that the first time the line "Dec 14 10:35:05 custom_script: Running /jffs/scripts/services-stop" appeared, which I don't remember seeing before. Indeed it's not present in my previous post, even though very clearly the services-stop script ran, since the spoof to syslog ran.

As mentioned earlier, I touch a file in jffs at the end of services-stop, so it certainly seems to be running, but nothing from my services-stop logger commands are written to syslog. Same with logger commands in init-start.
I posted a syslog extract from @john9527's custom build off-thread so copying it here.

Dec 14 22:52:19 pppd[968]: Connection terminated.
Dec 14 22:52:19 pppd[968]: Sent PADT
Dec 14 22:52:19 pppd[968]: Exit.
Dec 14 22:52:19 lldpd[858]: removal request for address of 192.168.2.11%10, but no knowledge of it
Dec 14 22:52:19 dropbear[1549]: Exit ([usernameredacted]): Exited normally
Dec 14 22:52:19 iTunes: daemon is stopped
Dec 14 22:52:19 FTP_Server: daemon is stopped
Dec 14 22:52:19 Samba_Server: smb daemon is stopped
Dec 14 22:52:19 Timemachine: daemon is stopped
Dec 14 22:52:20 WEBDAV_Server: daemon is stopped
Dec 14 22:52:20 kernel: usbcore: deregistering interface driver cdc_mbim
Dec 14 22:52:20 kernel: usbcore: deregistering interface driver qmi_wwan
Dec 14 22:52:20 kernel: usbcore: deregistering interface driver huawei_cdc_ncm
Dec 14 22:52:20 kernel: usbcore: deregistering interface driver cdc_wdm
Dec 14 22:52:20 kernel: usbcore: deregistering interface driver cdc_ncm
Dec 14 22:52:20 kernel: usbcore: deregistering interface driver rndis_host
Dec 14 22:52:20 kernel: usbcore: deregistering interface driver cdc_ether
Dec 14 22:52:20 kernel: usbcore: deregistering interface driver ax88179_178a
Dec 14 22:52:20 kernel: usbcore: deregistering interface driver asix
Dec 14 22:52:20 kernel: usbcore: deregistering interface driver cdc_acm
Dec 14 22:52:20 kernel: cdrom: Uniform CD-ROM driver unloaded
Dec 14 22:52:20 kernel: usbcore: deregistering interface driver usblp
May  5 06:05:05 syslogd started: BusyBox v1.25.1
May  5 06:05:05 kernel: klogd started: BusyBox v1.25.1 (2018-12-14 00:33:15 MST)
May  5 06:05:05 kernel: Booting Linux on physical CPU 0x0
May  5 06:05:05 kernel: Linux version 4.1.27 ([email protected]) (gcc version 5.3.0 (Buildroot 2016.02) ) #2 SMP PREEMPT Fri Dec 14 01:13:04 MST 2018

I've never seen the "custom_script: Running /jffs/scripts/services-stop" line in syslog since I've been looking for it.
Is this just happening to us? Any other 86U users seeing problems?
Would there be any benefit to flashing any earlier builds, I've only had the router a few weeks and only really been looking into this since the 384.8 beta2.

 

[preacher65]

I've never seen the "custom_script: Running /jffs/scripts/services-stop" line in syslog since I've been looking for it.

This is weird, but perhaps it makes more sense to someone more knowledgeable:

I installed an external syslog server on a network PC and I can see more events there than I can in the on-router syslog.

Here's the lastest reboot from the device's syslog file in /jffs:

Dec 15 09:45:49 rc_service: httpds 811:notify_rc reboot
Dec 15 09:45:49 pppd[985]: Hangup (SIGHUP)
Dec 15 09:45:49 pppd[985]: Terminating on signal 15
Dec 15 09:45:49 pppd[985]: Connect time 109.6 minutes.
Dec 15 09:45:49 pppd[985]: Sent 10641050 bytes, received 105610468 bytes.
Dec 15 09:45:49 pppd[985]: Connection terminated.
Dec 15 09:45:50 pppd[985]: Sent PADT
Dec 15 09:45:50 pppd[985]: Exit.
Dec 15 09:45:50 iTunes: daemon is stopped
Dec 15 09:45:50 FTP_Server: daemon is stopped
Dec 15 09:45:50 dropbear[1771]: Exit ([usernameredacted]): Exited normally
Dec 15 09:45:50 Samba_Server: smb daemon is stopped
Dec 15 09:45:50 Timemachine: daemon is stopped
Dec 15 09:45:50 WEBDAV_Server: daemon is stopped
Dec 15 09:45:50 kernel: usbcore: deregistering interface driver cdc_mbim
Dec 15 09:45:50 kernel: usbcore: deregistering interface driver qmi_wwan
Dec 15 09:45:50 kernel: usbcore: deregistering interface driver huawei_cdc_ncm
Dec 15 09:45:50 kernel: usbcore: deregistering interface driver cdc_wdm
Dec 15 09:45:50 kernel: usbcore: deregistering interface driver cdc_ncm
Dec 15 09:45:50 kernel: usbcore: deregistering interface driver rndis_host
Dec 15 09:45:50 kernel: usbcore: deregistering interface driver cdc_ether
Dec 15 09:45:50 kernel: usbcore: deregistering interface driver ax88179_178a
Dec 15 09:45:50 kernel: usbcore: deregistering interface driver asix
Dec 15 09:45:50 kernel: usbcore: deregistering interface driver cdc_acm
Dec 15 09:45:50 kernel: cdrom: Uniform CD-ROM driver unloaded
Dec 15 09:45:51 kernel: usbcore: deregistering interface driver usblp
=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=
*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*
=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=
Dec 15 09:45:51 Spoof.logger (init-start): Starting init......
Dec 15 09:45:51 syslogd started: BusyBox v1.25.1
Dec 15 09:45:51 kernel: klogd started: BusyBox v1.25.1 (2018-12-14 00:33:15 MST)
Dec 15 09:45:51 kernel: Booting Linux on physical CPU 0x0

And here's what would appear to be the same time period from the external syslog server:

Dec 15 09:45:49		user	notice	rc_service	httpds 811:notify_rc reboot 
Dec 15 09:45:49		daemon	info	pppd[985]	Hangup (SIGHUP) 
Dec 15 09:45:49		daemon	info	pppd[985]	Terminating on signal 15 
Dec 15 09:45:49		daemon	info	pppd[985]	Connect time 109.6 minutes. 
Dec 15 09:45:49		daemon	info	pppd[985]	Sent 10641050 bytes, received 105610468 bytes. 
Dec 15 09:45:49		daemon	notice	pppd[985]	Connection terminated. 
Dec 15 09:45:50		daemon	info	pppd[985]	Sent PADT 
Dec 15 09:45:50		daemon	info	pppd[985]	Exit. 
Dec 15 09:45:50		user	notice	iTunes	daemon is stopped 
Dec 15 09:45:50		user	notice	FTP_Server	daemon is stopped 
Dec 15 09:45:50		authpriv	info	dropbear[1771]	Exit ([usernameredacted]): Exited normally 
Dec 15 09:45:50		user	notice	Samba_Server	smb daemon is stopped 
Dec 15 09:45:50		user	notice	Timemachine	daemon is stopped 
Dec 15 09:45:50		user	notice	WEBDAV_Server	daemon is stopped 
Dec 15 09:45:50		user	info	kernel	usbcore: deregistering interface driver cdc_mbim 
Dec 15 09:45:50		user	info	kernel	usbcore: deregistering interface driver qmi_wwan 
Dec 15 09:45:50		user	info	kernel	usbcore: deregistering interface driver huawei_cdc_ncm 
Dec 15 09:45:50		user	info	kernel	usbcore: deregistering interface driver cdc_wdm 
Dec 15 09:45:50		user	info	kernel	usbcore: deregistering interface driver cdc_ncm 
Dec 15 09:45:50		user	info	kernel	usbcore: deregistering interface driver rndis_host 
Dec 15 09:45:50		user	info	kernel	usbcore: deregistering interface driver cdc_ether 
Dec 15 09:45:50		user	info	kernel	usbcore: deregistering interface driver ax88179_178a 
Dec 15 09:45:50		user	info	kernel	usbcore: deregistering interface driver asix 
Dec 15 09:45:50		user	info	kernel	usbcore: deregistering interface driver cdc_acm 
Dec 15 09:45:50		user	info	kernel	cdrom: Uniform CD-ROM driver unloaded 
Dec 15 09:45:51		user	info	kernel	usbcore: deregistering interface driver usblp 
Dec 15 09:45:51		user	notice	custom_script	Running /jffs/scripts/services-stop 
Dec 15 09:45:51		user	notice	stop_services	stopping erp_monitor 
Dec 15 09:45:51		user	notice	stop_services	stopping hour_monitor 
Dec 15 09:45:51		user	notice	stop_services	stopping bwdpi_wred_alive 
Dec 15 09:45:51		user	notice	stop_services	stopping bwdpi_check 
Dec 15 09:45:51		user	notice	stop_services	stopping dpi_engine 
Dec 15 09:45:51		user	warning	Services	Services stopping 
Dec 15 09:45:51		daemon	crit	pixelserv-tls[17192]	1525 uts, 1 log, 0 kcc, 2 kmx, 1.35 kvg, 3 krq, 233 req, 6701 avg, 16718 rmx, 5 tav, 16 tmx, 12 slh, 1 slm, 0 sle, 17 slc, 201 slu, 0 v13, 12 v12, 0 v10, 0 uca, 0 ucb, 0 uce, 27 ush, 19 sct, 221 sch, 1 scm, 0 scp, 0 sst, 10 ssh, 140 ssm, 0 ssp, 0 nfe, 0 gif, 0 ico, 0 txt, 0 jpg, 2 png, 0 swf, 0 sta, 0 stt, 0 ufe, 0 opt, 4 pst, 0 hed, 0 rdr, 0 nou, 0 pth, 0 204, 8 bad, 0 t-m-o, 17 cls, 0 cly, 0 clt, 0 err 
Dec 15 09:45:51		user	notice	A.QoS	set_qos_off, ret=65280 
Dec 15 09:45:51		user	notice	stop_services	stopping webdav 
Dec 15 09:45:51		user	notice	WEBDAV_Server	daemon is stopped 
Dec 15 09:45:51		user	notice	stop_services	stopping mastiff 
Dec 15 09:45:51		user	notice	NAT_Tunnel	AAE Service is stopped 
Dec 15 09:45:51		user	notice	NAT_Tunnel	AAE Service is stopped 
Dec 15 09:45:51		user	notice	stop_services	stopping nas_services 
Dec 15 09:45:51		user	notice	iTunes	daemon is stopped 
Dec 15 09:45:51		user	notice	FTP_Server	daemon is stopped 
Dec 15 09:45:51		user	notice	Samba_Server	smb daemon is stopped 
Dec 15 09:45:51		user	notice	Timemachine	daemon is stopped 
Dec 15 09:45:51		user	notice	stop_services	stopping diskmon 
Dec 15 09:45:51		user	notice	disk_monitor	Finish 
Dec 15 09:45:51		user	notice	stop_services	stopping upnp 
Dec 15 09:45:51		daemon	notice	miniupnpd[17719]	shutting down MiniUPnPd 
Dec 15 09:45:51		user	notice	stop_services	stopping amas 
Dec 15 09:45:52		user	notice	stop_services	stopping lltdc 
Dec 15 09:45:52		user	notice	stop_services	stopping networkmap 
Dec 15 09:45:52		user	debug	networkmap	Error unlocking 0: 9 Bad file descriptor 
Dec 15 09:45:53		daemon	info	avahi-daemon[1661]	Got SIGTERM, quitting. 
Dec 15 09:45:53		daemon	info	avahi-daemon[1661]	Leaving mDNS multicast group on interface br0.IPv4 with address 192.168.65.10. 
Dec 15 09:45:53		daemon	info	avahi-daemon[1661]	Leaving mDNS multicast group on interface lo.IPv4 with address 127.0.0.1. 
Dec 15 09:45:53		daemon	info	avahi-daemon[1661]	avahi-daemon 0.7 exiting. 
Dec 15 09:45:54		authpriv	info	dropbear[24177]	Exit ([usernameredacted]): Terminated by signal 
Dec 15 09:45:54		authpriv	info	dropbear[2863]	Exit ([usernameredacted]): Terminated by signal 
Dec 15 09:45:54		authpriv	info	dropbear[763]	Early exit: Terminated by signal 
Dec 15 09:45:54		user	warning	Skynet	[#] 159672 IPs (+0) -- 1619 Ranges Banned (+0) || 52 Inbound -- 0 Outbound Connections Blocked! [save] [3s] 
Dec 15 09:45:54		user	notice	nat	apply nat rules (/tmp/nat_rules_ppp0_eth0)

Timestamps don't seem to match up perfectly but I'm assuming that's related to the fake-hwclock and that the message from Skynet means the router is back up.
I noticed that "custom_script Running /jffs/scripts/services-stop" is present along with other commands that seemed to reach the external syslog server before the network dropped, but aren't in the local syslog. Still can't see anything related to unmounting flash drives though others may notice things that I'm missing.

 

[john9527]

Eureka! This problem finally got me to hook up my old AC68R as a test platform for Merlin builds, and I was able to recreate the problem (so it wasn't specific to the AC86). Turns out I needed to backport a fix from my fork that I did about 2 years ago

Here's my syslog now....note the services-stop and unmount logs

Dec 15 23:10:29 kernel: et0: et_mvlan_netdev_event: event 4 for vlan1 mvlan_en 0
Dec 15 23:10:30 iTunes: daemon is stopped
Dec 15 23:10:30 FTP_Server: daemon is stopped
Dec 15 23:10:30 Samba_Server: smb daemon is stopped
Dec 15 23:10:30 kernel: gro disabled
Dec 15 23:10:30 Timemachine: daemon is stopped
Dec 15 23:10:30 WEBDAV_Server: daemon is stopped
Dec 15 23:10:30 kernel: usbcore: deregistering interface driver cdc_mbim
Dec 15 23:10:30 kernel: usbcore: deregistering interface driver cdc_ncm
Dec 15 23:10:30 kernel: usbcore: deregistering interface driver qmi_wwan
Dec 15 23:10:30 kernel: usbcore: deregistering interface driver cdc_wdm
Dec 15 23:10:30 kernel: usbcore: deregistering interface driver rndis_host
Dec 15 23:10:30 kernel: usbcore: deregistering interface driver cdc_ether
Dec 15 23:10:30 kernel: usbcore: deregistering interface driver asix
Dec 15 23:10:30 kernel: usbcore: deregistering interface driver cdc_acm
Dec 15 23:10:30 kernel: usbcore: deregistering interface driver usblp
Dec 15 23:10:31 custom_script: Running /jffs/scripts/services-stop
Dec 15 23:10:31 stop_services: begin stop_services
Dec 15 23:10:32 A.QoS: set_qos_off, ret=65280
Dec 15 23:10:32 WEBDAV_Server: daemon is stopped
Dec 15 23:10:32 NAT_Tunnel: AAE Service is stopped
Dec 15 23:10:32 NAT_Tunnel: AAE Service is stopped
Dec 15 23:10:32 iTunes: daemon is stopped
Dec 15 23:10:32 FTP_Server: daemon is stopped
Dec 15 23:10:32 Samba_Server: smb daemon is stopped
Dec 15 23:10:32 kernel: gro disabled
Dec 15 23:10:32 Timemachine: daemon is stopped
Dec 15 23:10:32 disk_monitor: Finish
Dec 15 23:10:32 miniupnpd[681]: shutting down MiniUPnPd
Dec 15 23:10:33 dnsmasq[273]: exiting on receipt of SIGTERM
Dec 15 23:10:33 avahi-daemon[664]: Got SIGTERM, quitting.
Dec 15 23:10:33 avahi-daemon[664]: Leaving mDNS multicast group on interface br0.IPv4 with address 192.168.2.1.
Dec 15 23:10:33 avahi-daemon[664]: Leaving mDNS multicast group on interface lo.IPv4 with address 127.0.0.1.
Dec 15 23:10:33 avahi-daemon[664]: avahi-daemon 0.7 exiting.
Dec 15 23:10:34 dropbear[889]: Exit (john9527): Terminated by signal
Dec 15 23:10:34 dropbear[239]: Early exit: Terminated by signal
Dec 15 23:10:35 stop_services: end stop_services
Dec 15 23:10:35 nat: apply nat rules (/tmp/nat_rules_eth0_eth0)
Dec 15 23:10:35 kernel: br0: port 3(eth2) entering forwarding state
Dec 15 23:10:35 kernel: br0: port 2(eth1) entering forwarding state
Dec 15 23:10:35 kernel: br0: port 1(vlan1) entering forwarding state
Dec 15 23:10:35 kernel: et0: et_mvlan_netdev_event: event 9 for vlan1 mvlan_en 0
Dec 15 23:10:35 kernel: device eth0 left promiscuous mode
Dec 15 23:10:35 kernel: et0: et_mvlan_netdev_event: event 2 for vlan1 mvlan_en 0
Dec 15 23:10:35 kernel: device vlan1 left promiscuous mode
Dec 15 23:10:35 kernel: br0: port 1(vlan1) entering disabled state
Dec 15 23:10:35 kernel: device eth1 left promiscuous mode
Dec 15 23:10:35 kernel: br0: port 2(eth1) entering disabled state
Dec 15 23:10:35 kernel: device eth2 left promiscuous mode
Dec 15 23:10:35 kernel: br0: port 3(eth2) entering disabled state
Dec 15 23:10:36 kernel: Hooks already unregistered
Dec 15 23:10:36 kernel: Hooks already unregistered
Dec 15 23:10:36 kernel: Interface br0 doesn't exist
Dec 15 23:10:36 kernel: Interface br0 doesn't exist
Dec 15 23:10:36 kernel: Interface br0 doesn't exist
Dec 15 23:10:36 kernel: et0: et_mvlan_netdev_event: event 6 for vlan1 mvlan_en 0
Dec 15 23:10:36 kernel: et0: et_mvlan_netdev_event: event 17 for vlan1 mvlan_en 0
Dec 15 23:10:36 kernel: Interface br0 doesn't exist
Dec 15 23:10:36 kernel: et0: et_mvlan_netdev_event: event 9 for vlan2 mvlan_en 0
Dec 15 23:10:36 kernel: et0: et_mvlan_netdev_event: event 2 for vlan2 mvlan_en 0
Dec 15 23:10:36 kernel: et0: et_mvlan_netdev_event: event 6 for vlan2 mvlan_en 0
Dec 15 23:10:36 kernel: et0: et_mvlan_netdev_event: event 17 for vlan2 mvlan_en 0
Dec 15 23:10:36 FTP_Server: daemon is stopped
Dec 15 23:10:36 kernel: Interface br0 doesn't exist
Dec 15 23:10:36 Samba_Server: smb daemon is stopped
Dec 15 23:10:36 Timemachine: daemon is stopped
Dec 15 23:10:36 custom_script: Running /jffs/scripts/unmount (args: /tmp/mnt/UltraFit_AP ) - max timeout = 120s
Dec 15 23:10:37 syslog: USB partition unmounted from /tmp/mnt/UltraFit_AP
May 4 22:05:03 syslogd started: BusyBox v1.25.1
May 4 22:05:03 kernel: klogd started: BusyBox v1.25.1 (2018-12-15 21:57:14 MST)

Compiling now for the AC86. Will PM those that have been testing when it's available.

 

[XIII]

Nice!

So maybe in the future I can finally properly shut down and have a clean USB file system on boot?

 

[john9527]

Nice!

So maybe in the future I can finally properly shut down and have a clean USB file system on boot?

Actually, it was a logging only problem. Everything was be started/executed, including the unmount. At least now, it you have a different problem, it should show up in the logs.

 

[preacher65]

Thanks, we're definitely getting somewhere now. I can see the services-stop custom script in the log, and on the firmware upgrade I could see the unmount commands, but on a normal reboot I can't see them.
I have the following lines in /jffs/unmount and the permissions octal is 755:

#!/bin/sh
/usr/bin/logger -t $(basename $0) "Unmounting"
touch /jffs/unmount_run
date >> /jffs/002debug

Nothing writes to the log, and the unmount_run and 002debug files are not written. Here's the log:

Dec 16 10:44:54 syslogd started: BusyBox v1.25.1
Dec 16 10:44:54 kernel: klogd started: BusyBox v1.25.1 (2018-12-15 23:05:19 MST)
Dec 16 10:45:20 rc_service: httpds 854:notify_rc reboot
Dec 16 10:45:20 pppd[1048]: Hangup (SIGHUP)
Dec 16 10:45:20 pppd[1048]: Terminating on signal 15
Dec 16 10:45:20 pppd[1048]: Connect time 9.7 minutes.
Dec 16 10:45:20 pppd[1048]: Sent 1884548 bytes, received 4743528 bytes.
Dec 16 10:45:20 pppd[1048]: Connection terminated.
Dec 16 10:45:20 pppd[1048]: Sent PADT
Dec 16 10:45:20 pppd[1048]: Exit.
Dec 16 10:45:20 dropbear[3178]: Exit ([usernameredacted]): Exited normally
Dec 16 10:45:21 iTunes: daemon is stopped
Dec 16 10:45:21 FTP_Server: daemon is stopped
Dec 16 10:45:21 Samba_Server: smb daemon is stopped
Dec 16 10:45:21 Timemachine: daemon is stopped
Dec 16 10:45:21 WEBDAV_Server: daemon is stopped
Dec 16 10:45:21 kernel: usbcore: deregistering interface driver cdc_mbim
Dec 16 10:45:21 kernel: usbcore: deregistering interface driver qmi_wwan
Dec 16 10:45:21 kernel: usbcore: deregistering interface driver huawei_cdc_ncm
Dec 16 10:45:21 kernel: usbcore: deregistering interface driver cdc_wdm
Dec 16 10:45:21 kernel: usbcore: deregistering interface driver cdc_ncm
Dec 16 10:45:21 kernel: usbcore: deregistering interface driver rndis_host
Dec 16 10:45:21 kernel: usbcore: deregistering interface driver cdc_ether
Dec 16 10:45:21 kernel: usbcore: deregistering interface driver ax88179_178a
Dec 16 10:45:21 kernel: usbcore: deregistering interface driver asix
Dec 16 10:45:21 kernel: usbcore: deregistering interface driver cdc_acm
Dec 16 10:45:21 kernel: cdrom: Uniform CD-ROM driver unloaded
Dec 16 10:45:21 kernel: usbcore: deregistering interface driver usblp
Dec 16 10:45:21 custom_script: Running /jffs/scripts/services-stop
Dec 16 10:45:21 stop_services: begin stop_services
Dec 16 10:45:21 Services: Services stopping
Dec 16 10:45:22 pixelserv-tls[1654]: 572 uts, 1 log, 0 kcc, 3 kmx, 1.09 kvg, 2 krq, 76 req, 548 avg, 1083 rmx, 33 tav, 144 tmx, 5 slh, 0 slm, 0 sle, 5 slc, 64 slu, 0 v13, 3 v12, 2 v10, 0 uca, 0 ucb, 0 uce, 27 ush, 22 sct, 70 sch, 3 scm, 0 scp, 0 sst, 2 ssh, 0 ssm, 0 ssp, 0 nfe, 0 gif, 0 ico, 0 txt, 0 jpg, 3 png, 0 swf, 0 sta, 0 stt, 0 ufe, 0 opt, 0 pst, 0 hed, 0 rdr, 0 nou, 0 pth, 0 204, 2 bad, 0 t-m-o, 5 cls, 2 cly, 0 clt, 0 err
Dec 16 10:45:23 A.QoS: set_qos_off, ret=65280
Dec 16 10:45:23 WEBDAV_Server: daemon is stopped
Dec 16 10:45:23 NAT_Tunnel: AAE Service is stopped
Dec 16 10:45:23 NAT_Tunnel: AAE Service is stopped
Dec 16 10:45:23 iTunes: daemon is stopped
Dec 16 10:45:23 FTP_Server: daemon is stopped
Dec 16 10:45:23 Samba_Server: smb daemon is stopped
Dec 16 10:45:23 Timemachine: daemon is stopped
Dec 16 10:45:23 disk_monitor: Finish
Dec 16 10:45:23 miniupnpd[1884]: shutting down MiniUPnPd
Dec 16 10:45:25 avahi-daemon[1870]: Got SIGTERM, quitting.
Dec 16 10:45:25 avahi-daemon[1870]: Leaving mDNS multicast group on interface br0.IPv4 with address 192.168.65.11.
Dec 16 10:45:25 avahi-daemon[1870]: Leaving mDNS multicast group on interface lo.IPv4 with address 127.0.0.1.
Dec 16 10:45:25 avahi-daemon[1870]: avahi-daemon 0.7 exiting.
Dec 16 10:45:26 dropbear[3511]: Exit ([usernameredacted]): Terminated by signal
Dec 16 10:45:26 dropbear[3289]: Exit ([usernameredacted]): Terminated by signal
Dec 16 10:45:26 dropbear[796]: Early exit: Terminated by signal
Dec 16 10:45:27 stop_services: end stop_services
Dec 16 10:45:27 nat: apply nat rules (/tmp/nat_rules_ppp0_eth0)
Dec 16 10:45:27 kernel: br0: port 7(wl0.1) entered disabled state
Dec 16 10:45:27 kernel: br0: port 6(eth6) entered disabled state
Dec 16 10:45:27 kernel: br0: port 5(eth5) entered disabled state
Dec 16 10:45:27 kernel: device eth1 left promiscuous mode
Dec 16 10:45:27 kernel: br0: port 1(eth1) entered disabled state
Dec 16 10:45:27 kernel: device eth2 left promiscuous mode
Dec 16 10:45:27 kernel: br0: port 2(eth2) entered disabled state
Dec 16 10:45:27 kernel: device eth3 left promiscuous mode
Dec 16 10:45:27 kernel: br0: port 3(eth3) entered disabled state
Dec 16 10:45:27 kernel: device eth4 left promiscuous mode
Dec 16 10:45:27 kernel: br0: port 4(eth4) entered disabled state
Dec 16 10:45:27 kernel: device eth5 left promiscuous mode
Dec 16 10:45:27 kernel: br0: port 5(eth5) entered disabled state
Dec 16 10:45:27 kernel: device eth6 left promiscuous mode
Dec 16 10:45:27 kernel: br0: port 6(eth6) entered disabled state
Dec 16 10:45:27 kernel: device wl0.1 left promiscuous mode
Dec 16 10:45:27 kernel: br0: port 7(wl0.1) entered disabled state
Dec 16 10:45:27 kernel: ubi1: attaching mtd9
Dec 16 10:45:27 kernel: ubi1: scanning is finished
Dec 16 10:45:27 kernel: ubi1: attached mtd9 (name "misc1", size 8 MiB)
Dec 16 10:45:27 kernel: ubi1: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
Dec 16 10:45:27 kernel: ubi1: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
Dec 16 10:45:27 kernel: ubi1: VID header offset: 2048 (aligned 2048), data offset: 4096
Dec 16 10:45:27 kernel: ubi1: good PEBs: 64, bad PEBs: 0, corrupted PEBs: 0
Dec 16 10:45:27 kernel: ubi1: user volume: 1, internal volumes: 1, max. volumes count: 128
Dec 16 10:45:27 kernel: ubi1: max/mean erase counter: 7/4, WL threshold: 4096, image sequence number: 663240290
Dec 16 10:45:27 kernel: ubi1: available PEBs: 0, total reserved PEBs: 64, PEBs reserved for bad PEB handling: 4
Dec 16 10:45:27 kernel: ubi1: background thread "ubi_bgt1d" started, PID 4489
Dec 16 10:45:28 kernel: UBIFS (ubi1:0): UBIFS: mounted UBI device 1, volume 0, name "nvram", R/O mode
Dec 16 10:45:28 kernel: UBIFS (ubi1:0): LEB size: 126976 bytes (124 KiB), min./max. I/O unit sizes: 2048 bytes/2048 bytes
Dec 16 10:45:28 kernel: UBIFS (ubi1:0): FS size: 5840896 bytes (5 MiB, 46 LEBs), journal size 1015809 bytes (0 MiB, 6 LEBs)
Dec 16 10:45:28 kernel: UBIFS (ubi1:0): reserved for root: 275879 bytes (269 KiB)
Dec 16 10:45:28 kernel: UBIFS (ubi1:0): media format: w4/r0 (latest is w4/r0), UUID 79472D8B-7E38-4E82-96D3-2635106FD83C, small LPT model
Dec 16 10:45:28 kernel: UBIFS (ubi1:0): un-mount UBI device 1
Dec 16 10:45:28 kernel: ubi1: detaching mtd9
Dec 16 10:45:28 kernel: ubi1: mtd9 is detached
Dec 16 10:45:30 FTP_Server: daemon is stopped
Dec 16 10:45:30 Samba_Server: smb daemon is stopped
Dec 16 10:45:30 Timemachine: daemon is stopped
=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=
*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*
=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=
Dec 16 10:45:22 Spoof.logger (init-start): Starting init......
Dec 16 10:45:22 syslogd started: BusyBox v1.25.1
Dec 16 10:45:22 kernel: klogd started: BusyBox v1.25.1 (2018-12-15 23:05:19 MST)
Dec 16 10:45:22 kernel: Booting Linux on physical CPU 0x0
Dec 16 10:45:22 kernel: Linux version 4.1.27 (jbacho@ASUS-AJ082535) (gcc version 5.3.0 (Buildroot 2016.02) ) #2 SMP PREEMPT Sat Dec 15 23:45:26 MST 2018

 

[john9527]

What device is plugged in to the port? Filesystem? Which port? If USB3, is is running as USB3 or USB2?

Can you append the part of the syslog when it is mounted?

EDIT: And please at least for now get rid of the
=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=
separator if you are generating it within a script....it makes me nervous

 

[preacher65]

What device is plugged in to the port? Filesystem? Which port? If USB3, is is running as USB3 or USB2?

Can you append the part of the syslog when it is mounted?

EDIT: And please at least for now get rid of the
=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=*=
separator if you are generating it within a script....it makes me nervous

Heh. I copied that idea from @cmkelley but have got rid of it and all spoof logger commands. I'll write a marker from ssh using logger which is what I was doing before to help me find the right section of the log. I've also disabled the fake-hwclock.

Devices are 2 x USB Ultra Flairs, ext4 with journaling disabled, I created the partition table and filesystem using on-router commands this last time instead of using the PC. USB 3 port is set to USB2.

fdisk -l
Disk /dev/sda: 15.3 GB, 15376000000 bytes
64 heads, 32 sectors/track, 14663 cylinders
Units = cylinders of 2048 * 512 = 1048576 bytes

   Device Boot      Start         End      Blocks  Id System
/dev/sda1               1       14663    15014896  83 Linux

Disk /dev/sdb: 30.7 GB, 30752000000 bytes
64 heads, 32 sectors/track, 29327 cylinders
Units = cylinders of 2048 * 512 = 1048576 bytes

   Device Boot      Start         End      Blocks  Id System
/dev/sdb1               1       29327    30030832  83 Linux

mount
/dev/sdb1 on /tmp/mnt/RTAC86U type ext4 (rw,nodev,relatime)
/dev/sda1 on /tmp/mnt/ASUS type ext4 (rw,nodev,relatime)

These seem to be the relevant sections of the log from when the USB drives are mounted:

Dec 16 11:33:15 Skynet: [*] USB Not Found - Sleeping For 10 Seconds ( Attempt 1 Of 10 )
Dec 16 11:33:16 custom_script: Running /jffs/scripts/pre-mount (args: /dev/sdb1 ) - max timeout = 120s
Dec 16 11:33:16 amtm: Running disk check 'e2fsck -p' on /dev/sdb1
Dec 16 11:33:16 miniupnpd[1538]: HTTP listening on port 39161
Dec 16 11:33:16 miniupnpd[1538]: Listening for NAT-PMP/PCP traffic on port 5351
Dec 16 11:33:16 amtm: Disk check done on /dev/sdb1
Dec 16 11:33:16 kernel: EXT4-fs (sdb1): couldn't mount as ext2 due to feature incompatibilities
Dec 16 11:33:16 hotplug: USB /dev/sdb1(ext) failed to mount at the first try!
Dec 16 11:33:16 usb: USB /dev/sdb1(ext) failed to mount at the first try!
Dec 16 11:33:16 kernel: EXT4-fs (sdb1): couldn't mount as ext3 due to feature incompatibilities
Dec 16 11:33:16 hotplug: USB ext fs at /dev/sdb1 mounted on /tmp/mnt/RTAC86U
Dec 16 11:33:16 usb: USB ext fs at /dev/sdb1 mounted on /tmp/mnt/RTAC86U.
Dec 16 11:33:16 kernel: EXT4-fs (sdb1): mounted filesystem without journal. Opts: (null)
Dec 16 11:33:16 custom_script: Running /jffs/scripts/post-mount (args: /tmp/mnt/RTAC86U ) - max timeout = 120s
Dec 16 11:33:16 kernel: Adding 262140k swap on /tmp/mnt/RTAC86U/myswap.swp.  Priority:-1 extents:2 across:270332k

and

Dec 16 11:33:21 custom_script: Running /jffs/scripts/pre-mount (args: /dev/sda1 ) - max timeout = 120s
Dec 16 11:33:21 amtm: Running disk check 'e2fsck -p' on /dev/sda1
Dec 16 11:33:21 amtm: Disk check done on /dev/sda1
Dec 16 11:33:21 hotplug: USB /dev/sda1(ext) failed to mount at the first try!
Dec 16 11:33:21 usb: USB /dev/sda1(ext) failed to mount at the first try!
Dec 16 11:33:21 kernel: EXT4-fs (sda1): couldn't mount as ext2 due to feature incompatibilities
Dec 16 11:33:21 kernel: EXT4-fs (sda1): couldn't mount as ext3 due to feature incompatibilities
Dec 16 11:33:21 hotplug: USB ext fs at /dev/sda1 mounted on /tmp/mnt/ASUS
Dec 16 11:33:21 usb: USB ext fs at /dev/sda1 mounted on /tmp/mnt/ASUS.
Dec 16 11:33:21 kernel: EXT4-fs (sda1): mounted filesystem without journal. Opts: (null)
Dec 16 11:33:21 custom_script: Running /jffs/scripts/post-mount (args: /tmp/mnt/ASUS ) - max timeout = 120s

but I've uploaded the full log to https://1drv.ms/t/s!AhAUIJstqPm_gYIGTj6xhEyP2Pz7Iw
Hopefully I've redacted just enough from the file, if anyone spots anything sensitive in there please let me know.

I don't think I've said this before but I really appreciate all the help and advice you (and others) have given so far, and would be grateful for any further help with the unmount issue. I'm really pleased to have got the services-stop showing in the syslog though.

Edit: results of fuser -m /dev/sdb1 -v

                     USER        PID ACCESS COMMAND
/dev/sdb1:           redacted    kernel swap  /tmp/mnt/RTAC86U/myswap.swp
                     redacted    kernel mount /tmp/mnt/RTAC86U
                     nobody     1618 ...e. pixelserv-tls
                     nobody     1771 F.... dnsmasq

And of fuser -m /dev/sda1 -v

                     USER        PID ACCESS COMMAND
/dev/sda1:       redacted    kernel mount /tmp/mnt/ASUS

Just to re-iterate, the drives unmount and the script runs if I unmount from the GUI or if I flash firmware, which I think is the same as @cmkelley. I can provide logs of either of those a bit later on if they'd be useful, but will be offline for a while now.

 

[john9527]

@preacher65
Can you post the output of
cat /proc/mounts

 

[preacher65]

# cat /proc/mounts
ubi:rootfs_ubifs / ubifs ro,relatime 0 0
devtmpfs /dev devtmpfs rw,relatime,mode=0755 0 0
proc /proc proc rw,relatime 0 0
tmpfs /var tmpfs rw,noexec,relatime,size=420k 0 0
sysfs /sys sysfs rw,relatime 0 0
debugfs /sys/kernel/debug debugfs rw,relatime 0 0
mtd:bootfs /bootfs jffs2 ro,relatime 0 0
devpts /dev/pts devpts rw,relatime,mode=600 0 0
mtd:data /data jffs2 rw,relatime 0 0
tmpfs /tmp tmpfs rw,relatime 0 0
/dev/mtdblock8 /jffs jffs2 rw,noatime 0 0
/dev/sdb1 /tmp/mnt/RTAC86U ext4 rw,nodev,relatime 0 0
/dev/sda1 /tmp/mnt/ASUS ext4 rw,nodev,relatime 0 0

 

[preacher65]

Also noticed something in the logs from running a firmware update, which does unmount the USB drives. A line containing "return -1, Bad file descriptor" repeats 34 times, I don't see this on a normal reboot but I do also see it when issuing an unmount from the GUI.

Dec 16 16:52:38 [redacted]: FLASHING FIRMWARE FROM GUI
Dec 16 16:52:46 kernel: nf_conntrack: automatic helper assignment is deprecated and it will be removed soon. Use the iptables CT target to attach helpers instead.
Dec 16 16:53:15 custom_script: Running /jffs/scripts/unmount (args: /tmp/mnt/ASUS ) - max timeout = 120s
Dec 16 16:53:15 unmount: Unmounting...
Dec 16 16:53:16 ejusb: USB partition unmounted from /tmp/mnt/ASUS
Dec 16 16:53:16 custom_script: Running /jffs/scripts/unmount (args: /tmp/mnt/RTAC86U ) - max timeout = 120s
Dec 16 16:53:16 unmount: Unmounting...
Dec 16 16:53:17 ejusb: USB partition unmounted from /tmp/mnt/RTAC86U fail. (return -1, Bad file descriptor)
Dec 16 16:53:17 rc_service: ejusb 31270:notify_rc stop_nasapps
Dec 16 16:53:17 avahi-daemon[1856]: Files changed, reloading.
Dec 16 16:53:17 avahi-daemon[1856]: Loading service file /tmp/avahi/services/mt-daap.service.
Dec 16 16:53:17 iTunes: daemon is stopped
Dec 16 16:53:17 FTP_Server: daemon is stopped
Dec 16 16:53:17 Samba_Server: smb daemon is stopped
Dec 16 16:53:17 avahi-daemon[1856]: Got SIGTERM, quitting.
Dec 16 16:53:17 avahi-daemon[1856]: Leaving mDNS multicast group on interface br0.IPv4 with address 192.168.65.11.
Dec 16 16:53:17 avahi-daemon[1856]: Leaving mDNS multicast group on interface lo.IPv4 with address 127.0.0.1.
Dec 16 16:53:17 avahi-daemon[1856]: avahi-daemon 0.7 exiting.
Dec 16 16:53:17 Timemachine: daemon is stopped
Dec 16 16:53:17 avahi-daemon[31294]: Found user 'nobody' (UID 65534) and group 'nobody' (GID 65534).
Dec 16 16:53:17 avahi-daemon[31294]: Successfully dropped root privileges.
Dec 16 16:53:17 avahi-daemon[31294]: avahi-daemon 0.7 starting up.
Dec 16 16:53:17 avahi-daemon[31294]: WARNING: No NSS support for mDNS detected, consider installing nss-mdns!
Dec 16 16:53:17 avahi-daemon[31294]: No service file found in /tmp/avahi/services.
Dec 16 16:53:17 avahi-daemon[31294]: Loading new alias name RT-AC86U.
Dec 16 16:53:17 avahi-daemon[31294]: Joining mDNS multicast group on interface br0.IPv4 with address 192.168.65.11.
Dec 16 16:53:17 avahi-daemon[31294]: New relevant interface br0.IPv4 for mDNS.
Dec 16 16:53:17 avahi-daemon[31294]: Joining mDNS multicast group on interface lo.IPv4 with address 127.0.0.1.
Dec 16 16:53:17 avahi-daemon[31294]: New relevant interface lo.IPv4 for mDNS.
Dec 16 16:53:17 avahi-daemon[31294]: Network interface enumeration completed.
Dec 16 16:53:17 avahi-daemon[31294]: Registering new address record for 192.168.65.11 on br0.IPv4.
Dec 16 16:53:17 avahi-daemon[31294]: Registering new address record for 192.168.65.10 on br0.IPv4.
Dec 16 16:53:17 avahi-daemon[31294]: Registering new address record for 127.0.0.1 on lo.IPv4.
Dec 16 16:53:18 avahi-daemon[31294]: Server startup complete. Host name is RT-AC86U-4330.local. Local service cookie is 3667672082.
Dec 16 16:53:18 avahi-daemon[31294]: Alias name "RT-AC86U" successfully established.
Dec 16 16:53:18 ejusb: USB partition unmounted from /tmp/mnt/RTAC86U fail. (return -1, Bad file descriptor)
** Duplicates deleted but this line repeats 34 times in total **
Dec 16 16:53:52 ejusb: USB partition unmounted from /tmp/mnt/RTAC86U fail. (return -1, Bad file descriptor)
Dec 16 16:53:53 ejusb: USB partition busy - will unmount ASAP from /tmp/mnt/RTAC86U
Dec 16 16:53:53 rc_service: httpds 837:notify_rc stop_upgrade
Dec 16 16:53:53 usb: USB is ejected