Mwan3.user trouble

For Developers
1

I am using mwan3.user to trigger transmission of queued data, in case connection to web is available (again).
Unfortunately, I notice, that event "connected" is triggered twice for mwan3.user

Wed Aug 25 07:43:04 2021 daemon.notice netifd: Interface 'wan' is now up
Wed Aug 25 07:43:07 2021 user.notice mwan3-hotplug[18053]: Execute ifup event on interface wan (eth1)
Wed Aug 25 07:43:08 2021 user.warn mwan3-hotplug[18053]: failed to add 192.168.20.0/24 dev eth1 proto static scope link metric 10 to ta
Wed Aug 25 07:43:08 2021 user.warn mwan3-hotplug[18053]: failed to add default via 192.168.20.1 dev eth1 proto static src 192.168.20.15
Wed Aug 25 07:43:09 2021 user.info mwan3track[1592]: Detect ifup event on interface wan (eth1)
Wed Aug 25 07:43:09 2021 user.info mwan3track[1592]: Check (ping) success for target "1.1.1.1" on interface wan (eth1). Current score:
Wed Aug 25 07:43:09 2021 user.notice mwan3track[1592]: Interface wan (eth1) is connecting
Wed Aug 25 07:43:10 2021 user.notice mwan3track[1592]: Interface wan (eth1) is online
Wed Aug 25 07:43:11 2021 user.notice root: msgq wan connected
Wed Aug 25 07:43:11 2021 user.notice root: msgq trigger post_old_msg_q
...
Wed Aug 25 07:43:14 2021 user.info mwan3track[1592]: Check (ping) success for target "1.1.1.1" on interface wan (eth1). Current score:
Wed Aug 25 07:43:14 2021 user.notice mwan3track[1592]: Interface wan (eth1) is connecting
...
Data transmission via eth1 is running
...
Wed Aug 25 07:46:14 2021 user.info mwan3track[1592]: Check (ping) success for target "1.1.1.1" on interface wan (eth1). Current score:
Wed Aug 25 07:46:14 2021 user.notice mwan3track[1592]: Interface wan (eth1) is online
Wed Aug 25 07:46:15 2021 user.notice mwan3-hotplug[29611]: Execute connected event on interface wan (eth1)
Wed Aug 25 07:46:16 2021 user.notice root: msgq wan connected
Wed Aug 25 07:46:16 2021 user.notice root: msgq trigger post_old_msg_q``

Excerpt from mwan3.user:

if [ "${ACTION}" == "connected" ]; then
        if [ "${INTERFACE}" == "wan" ] ||  [ "${INTERFACE}" == "wwan" ] || [ "${INTERFACE}" == "wifiwan" ]; then
                logger "msgq ${INTERFACE} connected"
                logger "msgq trigger post_old_msg_q"
        fi
fi

It looks like, mwan3 signals "connected" already, when in state "online".

Which might further cause some issues, because I see

22935 root      1296 S    /bin/sh /sbin/hotplug-call iface
22941 root      1512 S    /bin/sh /sbin/hotplug-call iface
22950 root      1248 S    flock 1000

which seems to prevent "disconnected" in case of active transmission of queue and "ifdown wan".
"disconnected" then oly shows up, when transmission of queue (into nirvana) finished.

Any ideas ?

2

Check all environment variables:

logger -t mwan3-hotplug $(env)
3

Here you go, to see the bug:

Fri Aug 27 08:13:44 2021 user.info mwan3track[1593]: Detect ifup event on interface wan (eth1)
Fri Aug 27 08:13:44 2021 user.info mwan3track[1593]: Check (ping) success for target "1.1.1.1" on interface wan (eth1). Current score: 0
Fri Aug 27 08:13:44 2021 user.notice mwan3track[1593]: Interface wan (eth1) is connecting
Fri Aug 27 08:13:46 2021 user.notice mwan3-hotplug: ACTION=ifup SHLVL=1 INTERFACE=wan PWD=/ DEVICE=eth1
Fri Aug 27 08:13:46 2021 user.notice mwan3-hotplug: ACTION=connecting SHLVL=1 INTERFACE=wan PWD=/ DEVICE=eth1
Fri Aug 27 08:13:46 2021 user.info mwan3track[1593]: Lost 2 ping(s) on interface wan (eth1). Current score: 0
Fri Aug 27 08:13:46 2021 user.notice mwan3track[1593]: Interface wan (eth1) is online
Fri Aug 27 08:13:47 2021 user.notice mwan3-hotplug: ACTION=connected SHLVL=1 INTERFACE=wan PWD=/ DEVICE=eth1
Fri Aug 27 08:13:47 2021 user.notice root: web_up up
Fri Aug 27 08:13:47 2021 user.info mwan3track[1593]: Check (ping) success for target "1.1.1.1" on interface wan (eth1). Current score: 1
Fri Aug 27 08:13:47 2021 user.notice mwan3track[1593]: Interface wan (eth1) is connecting
Fri Aug 27 08:13:48 2021 user.notice mwan3-hotplug: ACTION=connecting SHLVL=1 INTERFACE=wan PWD=/ DEVICE=eth1
Fri Aug 27 08:13:53 2021 user.info mwan3track[1593]: Check (ping) success for target "1.1.1.1" on interface wan (eth1). Current score: 2
Fri Aug 27 08:13:53 2021 user.notice mwan3track[1593]: Interface wan (eth1) is online
Fri Aug 27 08:13:54 2021 user.notice mwan3-hotplug[18449]: Execute connected event on interface wan (eth1)
Fri Aug 27 08:13:55 2021 user.notice mwan3-hotplug: ACTION=connected SHLVL=1 INTERFACE=wan PWD=/ DEVICE=eth1
Fri Aug 27 08:13:55 2021 user.notice root: web_up up

mwan3.user:

#!/bin/sh
logger -t mwan3-hotplug $(env)
if [ "${ACTION}" == "connected" ]; then
        if [ "${INTERFACE}" == "wan" ] ||  [ "${INTERFACE}" == "wwan" ] || [ "${INTERFACE}" == "wifiwan" ]; then
                touch /tmp/web_up
                logger "web_up up"
        fi
fi
if [ "${ACTION}" == "disconnected" ]; then
        if [ "${INTERFACE}" == "wan" ] ||  [ "${INTERFACE}" == "wwan" ] || [ "${INTERFACE}" == "wifiwan" ]; then
                grep -q online /tmp/run/mwan3/iface_state/*
                if [ $? -eq 1 ]; then
                        logger "web_up down"
                        rm -f /tmp/web_up
                fi
        fi
fi
exit 0

Will try to get rid of mwan3.user, and do polling of /tmp/run/mwan3/iface_state/*
for online instead.

1 Like
4

Polling helps me as a workaround.
Filed official bug report

1 Like