Arch Linux

ramboman

Member

Registered: 2010-01-23

Posts: 35

Netctl hangs when restarting vnstat in ExecUpPost

I need to execute the following code after the interface wlan0 is up so vnstat can monitor the network data transfer properly:

vnstat -u -i wlan0; systemctl restart vnstat.service

So I set up this netctl profile (some-profile):

Interface='wlan0'
Connection='wireless'
ESSID="some_essid"
Security="wpa-configsection"
IP="dhcp"
WPAConfigSection=(
    'ssid="'"${ESSID}"'"'
    'proto=RSN'
    'pairwise=CCMP TKIP'
    'key_mgmt=WPA-PSK'
    'group=CCMP TKIP'
    'psk="some passphrase"'
)

ExecUpPost="vnstat -u -i ${Interface}; systemctl restart vnstat.service"

When I start with the following command line:

sudo netctl start some-profile

The interface is up and I can use the internet, but the console is standing by and the prompt does not reappear. Vnstat is not working.

I did not have this problem before I updated. My last update was in 2014-10-17.

I got the following logs:

journalctl -xn 100:

-- Logs begin at Sun 2014-02-23 14:46:18 EST, end at Sat 2014-10-25 20:09:13 EDT. --
Oct 25 20:05:17 bell systemd[1]: Starting User Manager for UID 1000...
-- Subject: Unit user@1000.service has begun with start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit user@1000.service has begun starting up.
Oct 25 20:05:17 bell systemd[1]: Starting Session c1 of user albert.
-- Subject: Unit session-c1.scope has begun with start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit session-c1.scope has begun starting up.
Oct 25 20:05:17 bell systemd-logind[880]: New session c1 of user albert.
-- Subject: A new session c1 has been created for user albert
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- Documentation: http://www.freedesktop.org/wiki/Software/systemd/multiseat
-- 
-- A new session with the ID c1 has been created for the user albert.
-- 
-- The leading process of the session is 890.
Oct 25 20:05:17 bell systemd[1]: Started Session c1 of user albert.
-- Subject: Unit session-c1.scope has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit session-c1.scope has finished starting up.
-- 
-- The start-up result is done.
Oct 25 20:05:17 bell systemd[895]: pam_unix(systemd-user:session): session opened for user albert by (uid=0)
Oct 25 20:05:17 bell systemd[895]: Starting Paths.
-- Subject: Unit UNIT has begun with start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit UNIT has begun starting up.
Oct 25 20:05:17 bell systemd[895]: Reached target Paths.
-- Subject: Unit UNIT has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit UNIT has finished starting up.
-- 
-- The start-up result is done.
Oct 25 20:05:17 bell systemd[895]: Starting Timers.
-- Subject: Unit UNIT has begun with start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit UNIT has begun starting up.
Oct 25 20:05:17 bell systemd[895]: Reached target Timers.
-- Subject: Unit UNIT has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit UNIT has finished starting up.
-- 
-- The start-up result is done.
Oct 25 20:05:17 bell systemd[895]: Starting Sockets.
-- Subject: Unit UNIT has begun with start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit UNIT has begun starting up.
Oct 25 20:05:17 bell systemd[895]: Reached target Sockets.
-- Subject: Unit UNIT has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit UNIT has finished starting up.
-- 
-- The start-up result is done.
Oct 25 20:05:17 bell systemd[895]: Starting Basic System.
-- Subject: Unit UNIT has begun with start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit UNIT has begun starting up.
Oct 25 20:05:17 bell systemd[895]: Reached target Basic System.
-- Subject: Unit UNIT has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit UNIT has finished starting up.
-- 
-- The start-up result is done.
Oct 25 20:05:17 bell systemd[895]: Starting Default.
-- Subject: Unit UNIT has begun with start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit UNIT has begun starting up.
Oct 25 20:05:17 bell systemd[895]: Reached target Default.
-- Subject: Unit UNIT has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit UNIT has finished starting up.
-- 
-- The start-up result is done.
Oct 25 20:05:17 bell systemd[895]: Startup finished in 300ms.
-- Subject: System start-up is now complete
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- All system services necessary queued for starting at boot have been
-- successfully started. Note that this does not mean that the machine is
-- now idle as services might still be busy with completing start-up.
-- 
-- Kernel start-up required KERNEL_USEC microseconds.
-- 
-- Initial RAM disk start-up required INITRD_USEC microseconds.
-- 
-- Userspace start-up required 300728 microseconds.
Oct 25 20:05:17 bell systemd[1]: Started User Manager for UID 1000.
-- Subject: Unit user@1000.service has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit user@1000.service has finished starting up.
-- 
-- The start-up result is done.
Oct 25 20:05:17 bell login[890]: LOGIN ON tty1 BY albert
Oct 25 20:05:23 bell acpid[881]: client connected from 1001[1000:1005]
Oct 25 20:05:23 bell acpid[881]: 1 client rule loaded
Oct 25 20:05:23 bell acpid[881]: client connected from 1001[1000:1005]
Oct 25 20:05:23 bell acpid[881]: 1 client rule loaded
Oct 25 20:05:33 bell sudo[1053]: albert : TTY=unknown ; PWD=/home/albert/.config/awesome/shell_script/conky/useful_view ; USER=root ; COMMAND=/usr/sbin/hddtemp /dev/sda /dev/sdb
Oct 25 20:05:33 bell sudo[1053]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 25 20:05:33 bell sudo[1053]: pam_unix(sudo:session): session closed for user root
Oct 25 20:05:56 bell sudo[1368]: albert : TTY=pts/1 ; PWD=/home/albert ; USER=root ; COMMAND=/usr/bin/vim /etc/systemd/system/netctl@.service
Oct 25 20:05:56 bell sudo[1368]: pam_unix(sudo:session): session opened for user root by albert(uid=0)
Oct 25 20:05:59 bell sudo[1389]: albert : TTY=unknown ; PWD=/home/albert/.config/awesome/shell_script/conky/useful_view ; USER=root ; COMMAND=/usr/sbin/hddtemp /dev/sda /dev/sdb
Oct 25 20:05:59 bell sudo[1389]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 25 20:05:59 bell sudo[1389]: pam_unix(sudo:session): session closed for user root
Oct 25 20:06:02 bell sudo[1368]: pam_unix(sudo:session): session closed for user root
Oct 25 20:06:06 bell sudo[1198]: albert : TTY=pts/0 ; PWD=/home/albert ; USER=root ; COMMAND=/usr/bin/netctl start some-profile
Oct 25 20:06:06 bell sudo[1198]: pam_unix(sudo:session): session opened for user root by albert(uid=0)
Oct 25 20:06:06 bell systemd[1]: Starting system-netctl.slice.
-- Subject: Unit system-netctl.slice has begun with start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit system-netctl.slice has begun starting up.
Oct 25 20:06:06 bell systemd[1]: Created slice system-netctl.slice.
-- Subject: Unit system-netctl.slice has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit system-netctl.slice has finished starting up.
-- 
-- The start-up result is done.
Oct 25 20:06:06 bell systemd[1]: Starting Networking for netctl profile some-profile...
-- Subject: Unit netctl@some\x2dprofile.service has begun with start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit netctl@some\x2dprofile.service has begun starting up.
Oct 25 20:06:06 bell network[1462]: Starting network profile 'some-profile'...
Oct 25 20:06:06 bell kernel: iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
Oct 25 20:06:06 bell kernel: iwlwifi 0000:04:00.0: Radio type=0x1-0x2-0x0
Oct 25 20:06:06 bell kernel: iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
Oct 25 20:06:06 bell kernel: iwlwifi 0000:04:00.0: Radio type=0x1-0x2-0x0
Oct 25 20:06:06 bell kernel: IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Oct 25 20:06:09 bell kernel: wlan0: authenticate with 00:23:6a:16:99:73
Oct 25 20:06:09 bell kernel: wlan0: send auth to 00:23:6a:16:99:73 (try 1/3)
Oct 25 20:06:09 bell kernel: wlan0: authenticated
Oct 25 20:06:09 bell kernel: wlan0: associate with 00:23:6a:16:99:73 (try 1/3)
Oct 25 20:06:09 bell kernel: wlan0: RX AssocResp from 00:23:6a:16:99:73 (capab=0x411 status=0 aid=1)
Oct 25 20:06:09 bell kernel: wlan0: associated
Oct 25 20:06:09 bell kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Oct 25 20:06:10 bell dhcpcd[1643]: version 6.5.0 starting
Oct 25 20:06:10 bell dhcpcd[1643]: DUID 00:01:00:01:19:9a:d7:02:00:23:5a:d1:55:5e
Oct 25 20:06:10 bell dhcpcd[1643]: wlan0: IAID 65:2b:01:ee
Oct 25 20:06:11 bell dhcpcd[1643]: wlan0: rebinding lease of 192.168.1.4
Oct 25 20:06:12 bell ntpd[884]: Listen normally on 4 wlan0 [fe80::21e:65ff:fe2b:1ee%3]:123
Oct 25 20:06:12 bell ntpd[884]: new interface(s) found: waking up resolver
Oct 25 20:06:16 bell dhcpcd[1643]: wlan0: leased 192.168.1.4 for 86400 seconds
Oct 25 20:06:16 bell dhcpcd[1643]: wlan0: adding route to 192.168.1.0/24
Oct 25 20:06:16 bell dhcpcd[1643]: wlan0: adding default route via 192.168.1.1
Oct 25 20:06:16 bell dhcpcd[1643]: forked to background, child pid 1747
Oct 25 20:06:16 bell systemd[1]: Stopping vnStat network traffic monitor...
-- Subject: Unit vnstat.service has begun shutting down
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit vnstat.service has begun shutting down.
Oct 25 20:06:16 bell vnstatd[864]: Info: Monitoring: wlan0 (100 Mbit) wlan1 (100 Mbit) eth0 (100 Mbit)
Oct 25 20:06:16 bell vnstatd[864]: Info: SIGTERM received, exiting.
Oct 25 20:06:17 bell ntpd[884]: Listen normally on 5 wlan0 192.168.1.4:123
Oct 25 20:06:17 bell ntpd[884]: new interface(s) found: waking up resolver
Oct 25 20:06:20 bell systemd[895]: Time has been changed
-- Subject: Time change
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- The system clock has been changed to REALTIME microseconds after January 1st, 1970.
Oct 25 20:06:20 bell systemd[1]: Time has been changed
-- Subject: Time change
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- The system clock has been changed to REALTIME microseconds after January 1st, 1970.
Oct 25 20:06:22 bell logger[1828]: ACPI action undefined: PNP0C0A:00
Oct 25 20:06:22 bell laptop-mode[1855]: Laptop mode
Oct 25 20:06:22 bell laptop-mode[1858]: enabled, not active
Oct 25 20:06:23 bell su[2211]: (to albert) root on none
Oct 25 20:06:23 bell su[2211]: pam_unix(su:session): session opened for user albert by (uid=0)
Oct 25 20:06:23 bell su[2211]: pam_unix(su:session): session closed for user albert
Oct 25 20:06:23 bell laptop-mode[2445]: Laptop mode
Oct 25 20:06:23 bell laptop-mode[2446]: enabled, not active [unchanged]
Oct 25 20:06:24 bell sudo[2427]: albert : TTY=unknown ; PWD=/home/albert/.config/awesome/shell_script/conky/useful_view ; USER=root ; COMMAND=/usr/sbin/hddtemp /dev/sda /dev/sdb
Oct 25 20:06:24 bell sudo[2427]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 25 20:06:24 bell sudo[2427]: pam_unix(sudo:session): session closed for user root
Oct 25 20:06:50 bell sudo[2699]: albert : TTY=unknown ; PWD=/home/albert/.config/awesome/shell_script/conky/useful_view ; USER=root ; COMMAND=/usr/sbin/hddtemp /dev/sda /dev/sdb
Oct 25 20:06:50 bell sudo[2699]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 25 20:06:50 bell sudo[2699]: pam_unix(sudo:session): session closed for user root
Oct 25 20:07:16 bell sudo[2853]: albert : TTY=unknown ; PWD=/home/albert/.config/awesome/shell_script/conky/useful_view ; USER=root ; COMMAND=/usr/sbin/hddtemp /dev/sda /dev/sdb
Oct 25 20:07:16 bell sudo[2853]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 25 20:07:16 bell sudo[2853]: pam_unix(sudo:session): session closed for user root
Oct 25 20:07:41 bell sudo[3101]: albert : TTY=unknown ; PWD=/home/albert/.config/awesome/shell_script/conky/useful_view ; USER=root ; COMMAND=/usr/sbin/hddtemp /dev/sda /dev/sdb
Oct 25 20:07:42 bell sudo[3101]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 25 20:07:42 bell sudo[3101]: pam_unix(sudo:session): session closed for user root
Oct 25 20:08:08 bell sudo[3342]: albert : TTY=unknown ; PWD=/home/albert/.config/awesome/shell_script/conky/useful_view ; USER=root ; COMMAND=/usr/sbin/hddtemp /dev/sda /dev/sdb
Oct 25 20:08:08 bell sudo[3342]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 25 20:08:08 bell sudo[3342]: pam_unix(sudo:session): session closed for user root
Oct 25 20:08:19 bell sudo[3433]: albert : TTY=pts/2 ; PWD=/home/albert ; USER=root ; COMMAND=/usr/bin/journalctl -xn 100
Oct 25 20:08:19 bell sudo[3433]: pam_unix(sudo:session): session opened for user root by albert(uid=0)
Oct 25 20:08:33 bell sudo[3505]: albert : TTY=unknown ; PWD=/home/albert/.config/awesome/shell_script/conky/useful_view ; USER=root ; COMMAND=/usr/sbin/hddtemp /dev/sda /dev/sdb
Oct 25 20:08:33 bell sudo[3505]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 25 20:08:34 bell sudo[3505]: pam_unix(sudo:session): session closed for user root
Oct 25 20:08:55 bell sudo[3433]: pam_unix(sudo:session): session closed for user root
Oct 25 20:08:59 bell sudo[3654]: albert : TTY=unknown ; PWD=/home/albert/.config/awesome/shell_script/conky/useful_view ; USER=root ; COMMAND=/usr/sbin/hddtemp /dev/sda /dev/sdb
Oct 25 20:08:59 bell sudo[3654]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 25 20:09:00 bell sudo[3654]: pam_unix(sudo:session): session closed for user root
Oct 25 20:09:13 bell sudo[3814]: albert : TTY=pts/2 ; PWD=/home/albert ; USER=root ; COMMAND=/usr/bin/sh -c journalctl -xn 100 > /tmp/journalctl.txt
Oct 25 20:09:13 bell sudo[3814]: pam_unix(sudo:session): session opened for user root by albert(uid=0)

ps aux | grep vnstat:

root      1750  0.0  0.0  19252  1180 ?        S    20:06   0:00 systemctl restart vnstat.service
albert    2497  0.0  0.0  12160  1096 pts/1    S+   20:06   0:00 grep vnstat

sudo systemctl -l status vnstat.service:

● vnstat.service - vnStat network traffic monitor
   Loaded: loaded (/usr/lib/systemd/system/vnstat.service; enabled)
   Active: inactive (dead) since Sat 2014-10-25 20:06:16 EDT; 4min 6s ago
     Docs: man:vnstatd(1)
           man:vnstat(1)
           man:vnstat.conf(5)
  Process: 864 ExecStart=/usr/sbin/vnstatd -n (code=exited, status=0/SUCCESS)
 Main PID: 864 (code=exited, status=0/SUCCESS)

Oct 25 20:06:16 bell systemd[1]: Stopping vnStat network traffic monitor...
Oct 25 20:06:16 bell vnstatd[864]: Info: Monitoring: wlan0 (100 Mbit) wlan1 (100 Mbit) eth0 (100 Mbit)
Oct 25 20:06:16 bell vnstatd[864]: Info: SIGTERM received, exiting.

sudo systemctl -l status netctl@some\\x2dprofile.service:

● netctl@some\x2dprofile.service - Networking for netctl profile some-profile
   Loaded: loaded (/etc/systemd/system/netctl@.service; static)
   Active: activating (start) since Sat 2014-10-25 20:06:06 EDT; 18min ago
     Docs: man:netctl.profile(5)
 Main PID: 1462 (network)
   CGroup: /system.slice/system-netctl.slice/netctl@some\x2dprofile.service
           ├─1462 /bin/bash /usr/lib/network/network start some-profile
           ├─1471 wpa_supplicant -B -P /run/wpa_supplicant_wlan0.pid -i wlan0 -D nl80211,wext -c/run/network/wpa_supplicant_wlan0.conf
           ├─1747 dhcpcd -4 -q -t 30 -L wlan0
           ├─1748 /bin/bash /usr/lib/network/network start some-profile
           └─1750 systemctl restart vnstat.service

Oct 25 20:06:06 bell network[1462]: Starting network profile 'some-profile'...
Oct 25 20:06:10 bell dhcpcd[1643]: version 6.5.0 starting
Oct 25 20:06:10 bell dhcpcd[1643]: DUID 00:01:00:01:19:9a:d7:02:00:23:5a:d1:55:5e
Oct 25 20:06:10 bell dhcpcd[1643]: wlan0: IAID 65:2b:01:ee
Oct 25 20:06:11 bell dhcpcd[1643]: wlan0: rebinding lease of 192.168.1.4
Oct 25 20:06:16 bell dhcpcd[1643]: wlan0: leased 192.168.1.4 for 86400 seconds
Oct 25 20:06:16 bell dhcpcd[1643]: wlan0: adding route to 192.168.1.0/24
Oct 25 20:06:16 bell dhcpcd[1643]: wlan0: adding default route via 192.168.1.1
Oct 25 20:06:16 bell dhcpcd[1643]: forked to background, child pid 1747

- Is this a bug?
- What should I do to solve this problem?