What's new

Solved dn-vnstat fails when more than 1 USB drive attached

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

Oracle

Regular Contributor
Hello, everyone.
I hope I'm at the right place.

In short:
Yesterday I installed Diversity and vnStat on a Merlin 386.5_2 Asus-AC86U router.
Later, an "Entware not found" error showed up.
The router has 2 USB drives attached: SSD and a larger HDD.

This is now solved, solution at the bottom of this post.

Details:

I was able to run the installation via amtm with only the SSD connected and everything worked nicely. That's until I attached a second USB drive and rebooted. Disconnecting the second drive and rebooting fixes the problem but I'd like to have both drives on.

As far as I can tell, initially the SSD was sda and HDD was sdb. The router will randomly switch sda/sdb after reboot and I don't see a way to control this.
The mount points stay the same, i.e. the SSD is always mounted at tmp/mnt/ssd (regardless if it appears as sda1 or sdb1), so the paths should be ok.
However, when SSD becomes sdb and the HDD becomes sda, the dn-vnstat webUI falls apart and errors come up. Or maybe it's just confused by the presence of 2 USB drives.

The errors I can see in the router log look like this:
...
Jun 1 02:41:20 dn-vnstat: Entware not found, sleeping for 10s (attempt 9 of 10)
Jun 1 02:41:30 dn-vnstat: Entware not found, sleeping for 10s (attempt 10 of 10)
Jun 1 02:41:40 dn-vnstat: Entware not found and is required for dn-vnstat to run, please resolve
...

Maybe the problem is not in dn-vnstat but I have to start from somewhere.
Any advice how to debug this further?

Root cause and solution
If there is a drive with an asusware.arm folder, it will steal the /opt symlink and break Entware.
The symlink should point to the correct path.
So delete or rename that folder.
This is a feature of the original Asus router firmware designed for the Download Master application.
Apparently, such a problem is unlikely to happen with a single drive attached because the Entware installation will detect it. As the second drive wasn't plugged in initially, the detection was bypassed.

It might be possible to add a script that restores the stolen symlink or something to that effect. Or, at least detect the problem and print a proper message in the system log to notify the user what the issue is and what could be done about it. Something like this:
Bash:
#!/bin/sh
#Check for potential conflict with asusware.arm
#Keyword to search for
name="asusware.arm"

#Set path if not provided
path=$1
if [ -z "$1" ]; then
   path="/"
fi

#Wait for concurrent processes to complete
sleep 7

#Determine if Entware is installed
#-type option not recognized by built-in find
opkgpath=$(find / -name opkg 2>&1| grep /bin/opkg | head -1) #Get first match
entpath=""
#logger -t check-usb "Found opkg path: $opkgpath"
#Check if output is a file
if [ -f $opkgpath ]; then
   entpath=${opkgpath/"/bin/opkg"/""} #Determine Entware path
fi
#Entware found, now check for conflict
#if [ -d $entpath ]; then #Doesn't work with empty string
if [ -d $entpath ] && [ -z ${entpath##*"entware"*} ]; then
   logger -t check-usb "Entware found in $entpath"
   logger -t check-usb "Looking for $name in $path"
   #asusdir=$($entpath/bin/find $path -type d -iname $name 2>&1) #Run find command from Entware
   asusdir=$(find $path -iname $name 2>&1) #using built-in find   
   #Print output if any
   if [ "${#asusdir}" != "0" ]; then
      logger -t check-usb "$asusdir"
   fi
   #
   if [ -d "$asusdir" ]; then
      logger -t check-usb "WARNING: Incompatible asusware directory found at $asusdir"
      logger -t check-usb "Please delete or rename $name to avoid possible conflict with Entware."
      logger -t check-usb "opt path: $(readlink -f /opt)"
      if [ $(readlink -f /opt) != $entpath ]; then
         #Try to restore the original path
         rm /tmp/opt
         ln -s $entpath /tmp/opt
         logger -t check-usb "opt path reset to: $(readlink -f /opt)"
      fi
   else
      logger -t check-usb "No $name conflict found."
   fi
fi
logger -t check-usb "USB device check completed."
echo "USB device check completed. See log for details."
The above can be put in a separate script in /jffs/scripts, e.g. "check-usb" (so it doesn't interfere with other code).
It can then be called and sent to background from post-mount like this:
/jffs/scripts/check-usb $1 &

Looking at the log, it seems this problem doesn't always happen. You can put a USB device with an asusware.arm folder on it and have it take away the opt symlink. Then you can put another device with such a folder and have the correct opt link preserved. Go figure.
 
Last edited:
Is there a /opt/bin/opkg file?
Bash:
ls -ld /tmp/opt
ls -l /opt/bin
cat /jffs/scripts/post-mount
 
Here's the output:
admin@RT-AC86U:/tmp/home/root# ls -ld /tmp/opt
lrwxrwxrwx 1 admin root 20 May 5 2018 /tmp/opt -> /tmp/mnt/ssd/entware

admin@RT-AC86U:/tmp/home/root# ls -l /opt/bin
-rwxr-xr-x 1 admin root 36 Apr 1 21:29 7z
-rwxr-xr-x 1 admin root 37 Apr 1 21:29 7za
-rwxr-xr-x 1 admin root 37 Apr 1 21:29 7zr
lrwxrwxrwx 1 admin root 8 May 31 11:37 ash -> /bin/ash
lrwxrwxrwx 1 admin root 29 May 31 11:37 base64 -> /opt/libexec/base64-coreutils
-rwxr-xr-x 1 admin root 51320 Apr 3 16:31 column
-rwxr-xr-x 1 admin root 80100 May 31 11:35 diversion
lrwxrwxrwx 1 admin root 23 May 31 13:53 dn-vnstat -> /jffs/scripts/dn-vnstat
-rwxr-xr-x 1 admin root 28 Dec 23 19:29 egrep
lrwxrwxrwx 1 admin root 26 May 31 11:37 entware-services -> /opt/etc/init.d/rc.unslung
-rwxr-xr-x 1 admin root 28 Dec 23 19:29 fgrep
-rwxr-xr-x 1 admin root 278968 Apr 2 20:23 find
-rwxr-xr-x 1 admin root 224480 Dec 23 19:29 grep
-rwxr-xr-x 1 admin root 281656 Apr 2 20:28 jq
-rwxr-xr-x 1 admin root 42872 Apr 1 21:29 locale.new
-rwxr-xr-x 1 admin root 261696 Apr 1 21:29 localedef.new
lrwxrwxrwx 1 admin root 12 May 31 11:37 netstat -> /bin/netstat
-rwxr-xr-x 1 admin root 860184 Apr 3 16:26 opkg
-rwxr-xr-x 1 admin root 73056 Apr 1 21:29 pixelserv-tls
lrwxrwxrwx 1 admin root 7 May 31 11:37 sh -> /bin/sh
-rwxr-xr-x 1 admin root 254912 Apr 2 19:09 sqlite3
-rwxr-xr-x 1 admin root 137944 Apr 2 20:12 vnstat
-rwxr-xr-x 1 admin root 105336 Apr 2 20:12 vnstati
-rwxr-xr-x 1 admin root 72400 Apr 2 20:23 xargs

admin@RT-AC86U:/tmp/home/root# cat /jffs/scripts/post-mount
#!/bin/sh

logger -t post-mount "Mounted as $(mount | grep $1)"

. /jffs/addons/diversion/mount-entware.div # Added by Diversion
/jffs/scripts/dn-vnstat startup "$@" & # dn-vnstat
 
I played some more to determine what was causing the dn-vnstat to fail. It seems to be the mere addition of a second USB device. This has nothing to do with sda/sdb assignment.
Within 5 min of connecting the second USB drive the errors show up, even if everything was fine before that.
Drive plugged in at 20:16:49, dn-vnstat starts reporting an error on 20:20:00.
Here's the whole chain:

Jun 1 20:16:49 kernel: usb 2-2.4: new SuperSpeed USB device number 4 using xhci-hcd
Jun 1 20:16:49 kernel: usb-storage 2-2.4:1.0: USB Mass Storage device detected
Jun 1 20:16:49 kernel: scsi host1: usb-storage 2-2.4:1.0
Jun 1 20:16:50 kernel: scsi 1:0:0:0: Direct-Access Seagate Expansion Desk 0915 PQ: 0 ANSI: 6
Jun 1 20:16:50 kernel: sd 1:0:0:0: Attached scsi generic sg1 type 0
Jun 1 20:16:50 kernel: sd 1:0:0:0: [sdb] Spinning up disk...
Jun 1 20:16:58 kernel: .......ready
Jun 1 20:16:58 kernel: sd 1:0:0:0: [sdb] Very big device. Trying to use READ CAPACITY(16).
Jun 1 20:16:58 kernel: sd 1:0:0:0: [sdb] 5860533167 512-byte logical blocks: (3.00 TB/2.73 TiB)
Jun 1 20:16:58 kernel: sd 1:0:0:0: [sdb] 4096-byte physical blocks
Jun 1 20:16:58 kernel: sd 1:0:0:0: [sdb] Write Protect is off
Jun 1 20:16:58 kernel: sd 1:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Jun 1 20:16:58 kernel: sd 1:0:0:0: [sdb] Very big device. Trying to use READ CAPACITY(16).
Jun 1 20:16:58 kernel: sdb: sdb1 sdb2
Jun 1 20:16:58 kernel: sd 1:0:0:0: [sdb] Very big device. Trying to use READ CAPACITY(16).
Jun 1 20:16:58 kernel: sd 1:0:0:0: [sdb] Attached SCSI disk
Jun 1 20:17:05 kernel: tntfs info (device sdb2, pid 27000): ntfs_fill_super(): fail_safe is enabled.
Jun 1 20:17:05 kernel: tntfs info (device sdb2, pid 27000): load_system_files(): NTFS volume name 'Seagate Expansion Drive', version 3.1 (cluster_size 4096, PAGE_SIZE 4096).
Jun 1 20:17:06 hotplug[26989]: USB ntfs fs at /dev/sdb2 mounted on /tmp/mnt/Seagate_Expansion_Drive
Jun 1 20:17:06 usb: USB ntfs fs at /dev/sdb2 mounted on /tmp/mnt/Seagate_Expansion_Drive.
Jun 1 20:17:06 asusware: umount partition /dev/sdb2...
Jun 1 20:17:06 disk_monitor: unmount partition
Jun 1 20:17:06 custom_script: Running /jffs/scripts/unmount (args: /tmp/mnt/Seagate_Expansion_Drive)
Jun 1 20:17:07 hotplug: USB partition unmounted from /tmp/mnt/Seagate_Expansion_Drive
Jun 1 20:17:07 asusware: Automatically scan partition /dev/sdb2...
Jun 1 20:17:07 disk_monitor: scan partition
Jun 1 20:17:08 asusware: re-mount partition /dev/sdb2...
Jun 1 20:17:08 disk_monitor: re-mount partition
Jun 1 20:17:08 kernel: tntfs info (device sdb2, pid 27076): ntfs_fill_super(): fail_safe is enabled.
Jun 1 20:17:08 kernel: tntfs info (device sdb2, pid 27076): load_system_files(): NTFS volume name 'Seagate Expansion Drive', version 3.1 (cluster_size 4096, PAGE_SIZE 4096).
Jun 1 20:17:08 hotplug: USB ntfs fs at /dev/sdb2 mounted on /tmp/mnt/Seagate_Expansion_Drive
Jun 1 20:17:08 usb: USB ntfs fs at /dev/sdb2 mounted on /tmp/mnt/Seagate_Expansion_Drive.
Jun 1 20:17:08 asusware: done.
Jun 1 20:17:08 disk_monitor: done
Jun 1 20:17:09 custom_script: Running /jffs/scripts/post-mount (args: /tmp/mnt/Seagate_Expansion_Drive)
Jun 1 20:17:09 rc_service: hotplug 26989:notify_rc restart_nasapps
Jun 1 20:17:09 custom_script: Running /jffs/scripts/service-event (args: restart nasapps)
Jun 1 20:17:09 avahi-daemon[3610]: Files changed, reloading.
Jun 1 20:17:09 avahi-daemon[3610]: Loading service file /tmp/avahi/services/mt-daap.service.
Jun 1 20:17:09 avahi-daemon[3610]: Alias name RT-AC86U: avahi_server_add_cname failure: The requested operation is invalid because redundant
Jun 1 20:17:09 iTunes: daemon is stopped
Jun 1 20:17:09 FTP_Server: daemon is stopped
Jun 1 20:17:09 wsdd2[3628]: Terminated received.
Jun 1 20:17:09 wsdd2[3628]: terminating.
Jun 1 20:17:09 Samba_Server: smb daemon is stopped
Jun 1 20:17:09 avahi-daemon[3610]: Got SIGTERM, quitting.
Jun 1 20:17:09 avahi-daemon[3610]: Leaving mDNS multicast group on interface br0.IPv4 with address 192.168.20.2.
Jun 1 20:17:09 avahi-daemon[3610]: Leaving mDNS multicast group on interface lo.IPv4 with address 127.0.1.1.
Jun 1 20:17:09 avahi-daemon[3610]: avahi-daemon 0.8 exiting.
Jun 1 20:17:11 Timemachine: daemon is stopped
Jun 1 20:17:11 avahi-daemon[27292]: Found user 'nobody' (UID 65534) and group 'nobody' (GID 65534).
Jun 1 20:17:11 avahi-daemon[27292]: Successfully dropped root privileges.
Jun 1 20:17:11 avahi-daemon[27292]: avahi-daemon 0.8 starting up.
Jun 1 20:17:11 avahi-daemon[27292]: WARNING: No NSS support for mDNS detected, consider installing nss-mdns!
Jun 1 20:17:11 avahi-daemon[27292]: No service file found in /tmp/avahi/services.
Jun 1 20:17:11 avahi-daemon[27292]: Loading new alias name RT-AC86U.
Jun 1 20:17:11 miniupnpd[3633]: shutting down MiniUPnPd
Jun 1 20:17:11 avahi-daemon[27292]: Joining mDNS multicast group on interface br0.IPv4 with address 192.168.20.2.
Jun 1 20:17:11 avahi-daemon[27292]: New relevant interface br0.IPv4 for mDNS.
Jun 1 20:17:11 avahi-daemon[27292]: Joining mDNS multicast group on interface lo.IPv4 with address 127.0.1.1.
Jun 1 20:17:11 avahi-daemon[27292]: New relevant interface lo.IPv4 for mDNS.
Jun 1 20:17:11 avahi-daemon[27292]: Network interface enumeration completed.
Jun 1 20:17:11 avahi-daemon[27292]: Registering new address record for 192.168.20.2 on br0.IPv4.
Jun 1 20:17:11 avahi-daemon[27292]: Registering new address record for 192.168.20.1 on br0.IPv4.
Jun 1 20:17:11 avahi-daemon[27292]: Registering new address record for 127.0.1.1 on lo.IPv4.
Jun 1 20:17:11 avahi-daemon[27292]: Registering new address record for 127.0.0.1 on lo.IPv4.
Jun 1 20:17:11 Samba_Server: daemon is started
Jun 1 20:17:11 wsdd2[27310]: starting.
Jun 1 20:17:11 miniupnpd[27315]: HTTP listening on port 46071
Jun 1 20:17:11 miniupnpd[27315]: Listening for NAT-PMP/PCP traffic on port 5351
Jun 1 20:17:12 avahi-daemon[27292]: Server startup complete. Host name is RT-AC86U.local. Local service cookie is 451317325.
Jun 1 20:17:12 avahi-daemon[27292]: Alias name RT-AC86U: avahi_server_add_cname failure: The requested operation is invalid because redundant
Jun 1 20:20:00 dn-vnstat: Entware not found, sleeping for 10s (attempt 1 of 10)
Jun 1 20:20:10 dn-vnstat: Entware not found, sleeping for 10s (attempt 2 of 10)
Jun 1 20:20:20 dn-vnstat: Entware not found, sleeping for 10s (attempt 3 of 10)
Jun 1 20:20:30 dn-vnstat: Entware not found, sleeping for 10s (attempt 4 of 10)
Jun 1 20:20:40 dn-vnstat: Entware not found, sleeping for 10s (attempt 5 of 10)
Jun 1 20:20:50 dn-vnstat: Entware not found, sleeping for 10s (attempt 6 of 10)
Jun 1 20:21:00 dn-vnstat: Entware not found, sleeping for 10s (attempt 7 of 10)
Jun 1 20:21:10 dn-vnstat: Entware not found, sleeping for 10s (attempt 8 of 10)
Jun 1 20:21:20 dn-vnstat: Entware not found, sleeping for 10s (attempt 9 of 10)
Jun 1 20:21:30 dn-vnstat: Entware not found, sleeping for 10s (attempt 10 of 10)
Jun 1 20:21:40 dn-vnstat: Entware not found and is required for dn-vnstat to run, please resolve
 
Sounds like a bug in dn-vnstat. The timing (exactly at xx:20:00) is suspicious. Can you check the crontab:
Code:
cru l
 
Yes, good guess, dn-vnstat appears to generate stats every 5 min (line 4).
admin@RT-AC86U:/tmp# cru l
0 8 * * * /jffs/addons/amtm/ledcontrol -on #amtm_LEDcontrol_on#
0 0 * * * /jffs/addons/amtm/ledcontrol -off #amtm_LEDcontrol_off#
00 2 * * Tue sh /opt/share/diversion/file/update-bl.div reset #Diversion_UpdateBL#
*/5 * * * * /jffs/scripts/dn-vnstat generate #dn-vnstat_generate#
59 23 * * * /jffs/scripts/dn-vnstat summary #dn-vnstat_summary#
The problem could also be in something dn-vnstat is trying to access.

Edit:
I think I found the code printing the error message. Appears to check this path: /opt/bin/opkg
I checked and it's there.
Question is why plugging in a second USB drive messes it up.
Also, unplugging the second USB doesn't fix the problem - a full restart is needed.
### function based on @Adamm00's Skynet USB wait function ###
Entware_Ready(){
if [ ! -f /opt/bin/opkg ]; then
Check_Lock
sleepcount=1
while [ ! -f /opt/bin/opkg ] && [ "$sleepcount" -le 10 ]; do
Print_Output true "Entware not found, sleeping for 10s (attempt $sleepcount of 10)" "$ERR"
sleepcount="$((sleepcount + 1))"
sleep 10
done
if [ ! -f /opt/bin/opkg ]; then
Print_Output true "Entware not found and is required for $SCRIPT_NAME to run, please resolve" "$CRIT"
Clear_Lock
exit 1
else
Print_Output true "Entware found, $SCRIPT_NAME will now continue" "$PASS"
Clear_Lock
fi
fi

Edit 2:
dn-vnstat
is not to blame here.
Just tested what's happening to the /opt/bin path when mounting a second drive.
Before: /tmp/mnt/ssd/entware/bin
After: /tmp/mnt/Seagate_Expansion_Drive/asusware.arm/bin
How so and how do I prevent it?

Edit 3:
Upon further digging, I found out this was a core feature of the router firmware.
When a USB storage device is inserted into the router’s USB port, the rc system daemon mounts the partition and checks for the existence of an asusware/.asusrouter script on the mount point. If it exists, the asusware folder is then symlinked to /tmp/opt (and also /opt) and the script is executed. Since this is all open source, you can find the relevant code in the mount_partition function in release/src/router/rc/usb.c.
From here: Hacking Functionality into ASUSWRT Routers « irq5.io

In other words, it's not the plugging of a second USB drive that messes things up but the asusware.arm folder on it. It causes the router to "steal" the Entware symlink and repoint it to its own folder.
So the solution is as simple as removing or renaming the asusware.arm.

How did this asusware.arm folder appear on the disk? I used the same disk on a previous Asus router with Download Master installed.

I'll update my first post with the solution.
 
Last edited:

Similar threads

Sign Up For SNBForums Daily Digest

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