Web interface inaccessible after period of time

jbmfg commented 6 years ago

Log here: http://logs.volumio.org/volumio/lQtbS7C.html

On reboot it will stay available for maybe 24 hours but then i get a timeout. I believe i can still SSH into the pi when this happens but I'm not 100% on that part, will update later when it goes down again.

arjenpdevries commented 6 years ago

Maybe this issue I reported is related: https://github.com/volumio/Volumio2/issues/1487 Can you check if your browser shows CSS errors (e.g.: ctrl-shift-K in firefox)?

PS: I have seen the problem twice during my (overall very happy!) use of Volumio, the second time I managed to resolve it without re-installing by just re-creating the UI. (I can post more info if you like.)

xipmix commented 6 years ago

At the time you submitted the log, your eth0 (ethernet) interface had no IP address configured, all that you had was the wifi (wlan0).

Do you have the hotspot feature enabled? It might help with debugging if you disable it (cog menu -> networking). Similarly, if you are mainly wanting to connect by wifi it might help to disable the wired ethernet in the volumio settings.

Below is the sequence of things related to dhcpcd in the log. It shows eth0 fails to get an IP address and eventually dhcpcd times out, but wlan0 succeeds. I can't see evidence of wlan0 losing connection and failing to regain it.

Feb 15 13:53:42 volumio ifup[458]: dhcpcd[480]: version 6.0.5 starting
Feb 15 13:53:42 volumio dhcpcd[480]: version 6.0.5 starting
Feb 15 13:53:42 volumio dhcpcd[480]: eth0: waiting for carrier
Feb 15 13:53:42 volumio ifup[458]: dhcpcd[480]: eth0: waiting for carrier
Feb 15 13:53:43 volumio dhcpcd[560]: Not running dhcpcd because there is aleady an interface specific instance ... failed!
Feb 15 13:53:43 volumio dhcpcd[560]: /var/run/dhcpcd-eth0.pid ... failed!
Feb 15 13:53:44 volumio systemd[1]: dhcpcd.service: control process exited, code=exited status=6
Feb 15 13:53:44 volumio systemd[1]: Unit dhcpcd.service entered failed state.
Feb 15 13:53:51 volumio sudo[803]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/dhcpcd
Feb 15 13:53:51 volumio dhcpcd[807]: version 6.0.5 starting
Feb 15 13:53:51 volumio dhcpcd[807]: eth0: waiting for carrier
Feb 15 13:53:51 volumio dhcpcd[807]: wlan0: waiting for carrier
Feb 15 13:53:53 volumio dhcpcd[807]: wlan0: carrier acquired
Feb 15 13:53:53 volumio dhcpcd[807]: wlan0: soliciting an IPv6 router
Feb 15 13:53:53 volumio dhcpcd[807]: wlan0: using static address 192.168.0.40
Feb 15 13:53:53 volumio dhcpcd[807]: wlan0: adding host route to 192.168.0.40 via 127.0.0.1
Feb 15 13:53:53 volumio dhcpcd[807]: wlan0: adding route to 192.168.0.0/24
Feb 15 13:53:53 volumio dhcpcd[807]: wlan0: adding default route via 192.168.0.1
Feb 15 13:53:53 volumio dhcpcd[807]: forked to background, child pid 893
  # system time was updated to correct values here
Mar 02 16:45:21 volumio dhcpcd[480]: timed out
Mar 02 16:45:21 volumio dhcpcd[480]: allowing 8 seconds for IPv4LL timeout
Mar 02 16:45:21 volumio ifup[458]: dhcpcd[480]: timed out
Mar 02 16:45:21 volumio ifup[458]: dhcpcd[480]: allowing 8 seconds for IPv4LL timeout
Mar 02 16:45:29 volumio dhcpcd[480]: timed out
Mar 02 16:45:29 volumio dhcpcd[480]: exited
Mar 02 16:45:29 volumio ifup[458]: dhcpcd[480]: timed out
Mar 02 16:45:29 volumio ifup[458]: dhcpcd[480]: exited

When did the timeout occur - I guessing it was before you rebooted and sent this log? If so you might need to run a few journalctl commands to go back in the logs beyond the reboot, and paste that log here. Something like this, depending on how long it was before you noticed the timeout.

$ sudo journalctl --since "-1h" >log.txt

jbmfg commented 6 years ago

Thanks @xipmix. Yes, i am not sure how long after the webui wouldnt come up that i was able to reboot and collect those logs. I can confirm however that i have ssh access when i dont have webui access so I'm thinking this is not a network issue. I will try to reboot today and pay attention to when i am no longer able to get to the webui and then collect logs quicker. I will also double check that wifi hotspot is off and that i can disable the wired connection, though i thought i had tried to do that and didnt have the option, will look again.

@arjenpdevries, I cannot do as you suggest since the webui wont load at all once this happens. It's as if the webserver is no longer running. Unless you are suggesting i look at the css before the issue occurs?

jbmfg commented 6 years ago

Lost connection completely just now; no webui, no ssh, new logs here http://logs.volumio.org/volumio/W03f9RM.html

arjenpdevries commented 6 years ago

Then seems as if you have a different problem - I got a blank UI page and could only see these errors in the debug console. For me, http://volumio.local/dev always worked btw, so maybe you unfortunately have a different issue to resolve.

xipmix commented 6 years ago

Thanks for the W03f9RM log. Unfortunately the 'send logs' button only sends the log as far back as the time the system was last booted up. Once you lost connection, you had to reboot, is that correct? If so, then we need to go back further in time, to before you had to reboot.

I thought this would do it - SSH in and run this

$ sudo journalctl --since "-2d" > journal-2d.txt

but it doesn't work for me; I only get logs back as far as the last boot. I guess this is because the logging is done in a way designed to avoid wear on the SD card and avoid overflowing it as well.

I guess you will need your own copy of the log. Once the system is up, run this

$ cd /home/volumio
$ sudo journalctl -f > journal.txt&
$ exit

When the system falls over, reboot and log in to retrieve the journal.txt file. With luck the details of what happened will be in there.

jbmfg commented 6 years ago

I was able to get a log after this happened without rebooting so everything should be there. Wasnt sure where to host it so i put it on my google drive to share here: https://drive.google.com/file/d/1jiWhlq5mjDdYtGxybQOBNQ_NWV66pQ_K/view?usp=sharing

volumio commented 6 years ago

I don't see anything wrong. Can you share the exact symptoms of your issue?

jbmfg commented 6 years ago

I get a spinner on the webui. If i attempt to reload the page i then get a timeout. To fix i have to reboot, then it will stay up for maybe 12 hours (just a guess) or so before happening again.

xipmix commented 6 years ago

When you get the spinner, are you able to 'ping' the volumio machine from another?

$ ping 192.168.0.40

The log is not what I was expecting; I was expecting journalctl -f to start recording a file that would not show any boot details at the start, and would be truncated by the reboot. Is it possible you did

sudo journalctl > journal.txt &

instead? Or did you just clean it up before sharing?

The -f means 'follow' and it needs to be there for this diagnostic. If you log back in after starting it you should see the journal.txt file growing over time (there is i/o buffering so it will probably grow in chunks, not continuously).

jbmfg commented 6 years ago

Hi @xipmix, yes you are correct, i accidentally copied your first command that didnt have the -f included. And yes, i can typically ping and ssh to volumio when this occurs. I've tried to rerun the journal command with -f but its taking a really long time to complete, perhaps because i havent rebooted it since the last time it broke (Monday.) If it ever finishes i will upload. Otherwise i will reboot and wait for it to happen again before trying the logging.

jbmfg commented 6 years ago

disregard my previous comment, i was being thick. I have rebooted and started the logging with -f. Once it fails i will post the log here. Thanks again for the help!

jbmfg commented 6 years ago

Alright, here is the log file. It's huge but sometime during its collection the web interface went down. Actually, this time the web interface AND network connectivity went down. I could not ssh or ping the pi this morning just before rebooting and grabbing this log. Not sure if this is the same issue as when just the web interface goes down or not.

https://drive.google.com/open?id=1wU9LxH2Vjpgyamam1jT0FWHNpJaBWk8k

xipmix commented 6 years ago

Great work. Now we're getting somewhere. So you have a working system, playing a few tunes and then this happens

Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: Drv Event 47 (NL80211_CMD_ROAM) received for wlan0
Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: Roam event
Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: Associated on 2437 MHz
Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: Associated with 20:e5:2a:2b:78:47
Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: Operating frequency for the associated BSS from scan results: 2437 MHz
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: Event ASSOC (0) received
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: Association info event
Mar 09 02:24:46 volumio wpa_supplicant[864]: req_ies - hexdump(len=87): 03 00 00 08 42 65 6e 6a 61 6d 69 6e 01 08 82 84 8b 96 24 30 48 6c 32 04 0c 12 18 60 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00 2d 1a ee 11 1f ff
 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 dd 07 00 50 f2 02 00 01 00
Mar 09 02:24:46 volumio wpa_supplicant[864]: resp_ies - hexdump(len=122): 01 08 82 84 8b 96 24 30 48 6c 32 04 0c 12 18 60 46 05 32 08 01 00 00 2d 1a ad 09 17 ff 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3d 16 06 00 17 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 7f 08 04 00 00 00 00 00 00 40 dd 09 00 10 18 02 09 00 1c 00 00 dd 18 00 50 f2 02 01 01 88 00 03 a4 00 00 27 a4 00 00 42 43 5e 00 62 32 2f 00
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=7): 46 05 32 08 01 00 00
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=24): 3d 16 06 00 17 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: WMM Parameter Element - hexdump(len=24): 00 50 f2 02 01 01 88 00 03 a4 00 00 27 a4 00 00 42 43 5e 00 62 32 2f 00
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: freq=2437 MHz
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: set own WPA/RSN IE - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
Mar 09 02:24:46 volumio wpa_supplicant[864]: FT: Stored MDIE and FTIE from (Re)Association Response - hexdump(len=0):
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: State: COMPLETED -> ASSOCIATED
Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: Set wlan0 operstate 1->0 (DORMANT)
Mar 09 02:24:46 volumio wpa_supplicant[864]: netlink: Operstate: ifindex=3 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: Associated with 20:e5:2a:2b:78:47
Mar 09 02:24:46 volumio dhcpcd[922]: wlan0: carrier lost
Mar 09 02:24:46 volumio netplugd[937]: wlan0: state ACTIVE flags 0x00011043 UP,BROADCAST,RUNNING,MULTICAST,10000 -> 0x00011003 UP,BROADCAST,MULTICAST,10000
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: WPA: Association event - clear replay counter
Mar 09 02:24:46 volumio dhcpcd[922]: wlan0: deleting host route to 192.168.0.40 via 127.0.0.1
Mar 09 02:24:46 volumio netplugd[14053]: /etc/netplug/netplug wlan0 out -> pid 14053
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: WPA: Clear old PTK
Mar 09 02:24:46 volumio dhcpcd[922]: wlan0: deleting route to 192.168.0.0/24
Mar 09 02:24:46 volumio wpa_supplicant[864]: TDLS: Remove peers on association
Mar 09 02:24:46 volumio dhcpcd[922]: wlan0: deleting default route via 192.168.0.1
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: External notification - portEnabled=0
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: SUPP_PAE entering state DISCONNECTED
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: Supplicant port status: Unauthorized
Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: Set supplicant port unauthorized for 20:e5:2a:2b:78:47
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: SUPP_BE entering state INITIALIZE
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: External notification - portValid=0
Mar 09 02:24:46 volumio avahi-daemon[589]: Withdrawing address record for 192.168.0.40 on wlan0.
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: External notification - EAP success=0
Mar 09 02:24:46 volumio avahi-daemon[589]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.40.
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: External notification - portEnabled=1
Mar 09 02:24:46 volumio avahi-daemon[589]: Interface wlan0.IPv4 no longer relevant for mDNS.
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: SUPP_PAE entering state CONNECTING
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: enable timer tick
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: SUPP_BE entering state IDLE
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: Setting authentication timeout: 10 sec 0 usec
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: Cancelling scan request
Mar 09 02:24:46 volumio wpa_supplicant[864]: RTM_NEWLINK: ifi_index=3 ifname=wlan0 wext ifi_family=0 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
Mar 09 02:24:46 volumio wpa_supplicant[864]: RTM_NEWLINK: ifi_index=3 ifname=wlan0 wext ifi_family=0 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
Mar 09 02:24:46 volumio wpa_supplicant[864]: RTM_NEWLINK: ifi_index=3 ifname=wlan0 wext ifi_family=0 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])
Mar 09 02:24:46 volumio wpa_supplicant[864]: RTM_NEWLINK: ifi_index=3 ifname=wlan0 operstate=5 linkmode=1 ifi_family=0 ifi_flags=0x11003 ([UP][LOWER_UP])
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: RX EAPOL from 20:e5:2a:2b:78:47
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: Setting authentication timeout: 10 sec 0 usec
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: IEEE 802.1X RX: version=2 type=3 length=117
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0:   EAPOL-Key type=2
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0:   key_length=16 key_data_length=22
Mar 09 02:24:46 volumio wpa_supplicant[864]: replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 03
Mar 09 02:24:46 volumio wpa_supplicant[864]: key_nonce - hexdump(len=32): 1a 01 37 91 56 3b 84 9a 86 29 21 53 63 22 29 c3 a7 ec 80 e5 87 4d 9a 65 60 58 68 41 b1 6f c5 2b
Mar 09 02:24:46 volumio wpa_supplicant[864]: key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Mar 09 02:24:46 volumio wpa_supplicant[864]: key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
Mar 09 02:24:46 volumio wpa_supplicant[864]: key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
Mar 09 02:24:46 volumio wpa_supplicant[864]: key_mic - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: State: ASSOCIATED -> 4WAY_HANDSHAKE
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: WPA: RX message 1 of 4-Way Handshake from 20:e5:2a:2b:78:47 (ver=2)
Mar 09 02:24:46 volumio wpa_supplicant[864]: RSN: msg 1/4 key data - hexdump(len=22): dd 14 00 0f ac 04 1b 78 d0 6b 50 d8 d0 05 31 0e 2d b1 27 ee c0 e8
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: PMKID in EAPOL-Key - hexdump(len=22): dd 14 00 0f ac 04 1b 78 d0 6b 50 d8 d0 05 31 0e 2d b1 27 ee c0 e8
Mar 09 02:24:46 volumio wpa_supplicant[864]: RSN: PMKID from Authenticator - hexdump(len=16): 1b 78 d0 6b 50 d8 d0 05 31 0e 2d b1 27 ee c0 e8
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: RSN: no matching PMKID found
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: Renewed SNonce - hexdump(len=32): fa 26 34 5d d6 db 2b 18 5f 9e 1f dc 1a 86 a4 2a db 3c 53 f4 b5 e6 ba df 9b a7 35 04 26 b8 57 bb
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: PTK derivation - A1=80:1f:02:b6:85:9c A2=20:e5:2a:2b:78:47
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: Nonce1 - hexdump(len=32): fa 26 34 5d d6 db 2b 18 5f 9e 1f dc 1a 86 a4 2a db 3c 53 f4 b5 e6 ba df 9b a7 35 04 26 b8 57 bb
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: Nonce2 - hexdump(len=32): 1a 01 37 91 56 3b 84 9a 86 29 21 53 63 22 29 c3 a7 ec 80 e5 87 4d 9a 65 60 58 68 41 b1 6f c5 2b
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: PMK - hexdump(len=32): [REMOVED]
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: PTK - hexdump(len=48): [REMOVED]
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: WPA IE for msg 2/4 - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 03
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: WPA: Sending EAPOL-Key 2/4
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: KCK - hexdump(len=16): [REMOVED]
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: Derived Key MIC - hexdump(len=16): 2a 86 6c e0 5e 90 8c 10 b7 23 7b 21 d7 81 bb e6
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: RX EAPOL from 20:e5:2a:2b:78:47
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: IEEE 802.1X RX: version=2 type=3 length=151
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0:   EAPOL-Key type=2
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0:   key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0:   key_length=16 key_data_length=56
Mar 09 02:24:46 volumio wpa_supplicant[864]: replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 04
Mar 09 02:24:46 volumio wpa_supplicant[864]: key_nonce - hexdump(len=32): 1a 01 37 91 56 3b 84 9a 86 29 21 53 63 22 29 c3 a7 ec 80 e5 87 4d 9a 65 60 58 68 41 b1 6f c5 2b
Mar 09 02:24:46 volumio wpa_supplicant[864]: key_iv - hexdump(len=16): a7 ec 80 e5 87 4d 9a 65 60 58 68 41 b1 6f c5 2d
Mar 09 02:24:46 volumio wpa_supplicant[864]: key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
Mar 09 02:24:46 volumio wpa_supplicant[864]: key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
Mar 09 02:24:46 volumio wpa_supplicant[864]: key_mic - hexdump(len=16): 70 6b 49 7b 2b 4f 27 ba 4b f7 a9 b7 ef 85 a2 06
Mar 09 02:24:46 volumio wpa_supplicant[864]: RSN: encrypted key data - hexdump(len=56): 4d 23 b5 13 e4 62 86 43 f3 07 98 e8 ea e9 bf 2a 42 96 62 1d d6 d7 79 05 34 62 78 90 4b 65 aa 90 e3 89 87 da a8 c8 99 4b d2 f7 66 89 3b a3 7a de de 6f 4c a2 80 94 59 10
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: decrypted EAPOL-Key key data - hexdump(len=48): [REMOVED]
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: WPA: RX message 3 of 4-Way Handshake from 20:e5:2a:2b:78:47 (ver=2)
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: IE KeyData - hexdump(len=48): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 0c 00 dd 16 00 0f ac 01 01 00 89 17 40 3e 98 9a 56 49 14 4d 02 99 b7 be d4 c8 dd 00
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: RSN IE in EAPOL-Key - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 0c 00
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: GTK in EAPOL-Key - hexdump(len=24): [REMOVED]
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: WPA: Sending EAPOL-Key 4/4
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: KCK - hexdump(len=16): [REMOVED]
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: Derived Key MIC - hexdump(len=16): 86 b2 46 ea 4d 85 bd 14 ad f4 39 c0 b9 c7 f4 21
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: WPA: Installing PTK to the driver
Mar 09 02:24:46 volumio wpa_supplicant[864]: wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=3 addr=0x21a7de0 key_idx=0 set_tx=1 seq_len=6 key_len=16
Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: KEY_DATA - hexdump(len=16): [REMOVED]
Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: KEY_SEQ - hexdump(len=6): 00 00 00 00 00 00
Mar 09 02:24:46 volumio wpa_supplicant[864]: addr=20:e5:2a:2b:78:47
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: External notification - portValid=1
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE
Mar 09 02:24:46 volumio wpa_supplicant[864]: RSN: received GTK in pairwise handshake - hexdump(len=18): [REMOVED]
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: Group Key - hexdump(len=16): [REMOVED]
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: WPA: Installing GTK to the driver (keyidx=1 tx=0 len=16)
Mar 09 02:24:46 volumio wpa_supplicant[864]: WPA: RSC - hexdump(len=6): 00 00 00 00 00 00
Mar 09 02:24:46 volumio wpa_supplicant[864]: wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=3 addr=0x62f2a8 key_idx=1 set_tx=0 seq_len=6 key_len=16
Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: KEY_DATA - hexdump(len=16): [REMOVED]
Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: KEY_SEQ - hexdump(len=6): 00 00 00 00 00 00
Mar 09 02:24:46 volumio wpa_supplicant[864]: broadcast key
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: WPA: Key negotiation completed with 20:e5:2a:2b:78:47 [PTK=CCMP GTK=CCMP]
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: Cancelling authentication timeout
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: State: GROUP_HANDSHAKE -> COMPLETED
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: CTRL-EVENT-CONNECTED - Connection to 20:e5:2a:2b:78:47 completed [id=0 id_str=]
Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: Set wlan0 operstate 0->1 (UP)
Mar 09 02:24:46 volumio wpa_supplicant[864]: netlink: Operstate: ifindex=3 linkmode=-1 (no change), operstate=6 (IF_OPER_UP)
Mar 09 02:24:46 volumio netplugd[937]: wlan0: state OUTING flags 0x00011003 UP,BROADCAST,MULTICAST,10000 -> 0x00011043 UP,BROADCAST,RUNNING,MULTICAST,10000
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: External notification - portValid=1
Mar 09 02:24:46 volumio dhcpcd[922]: wlan0: carrier acquired
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: External notification - EAP success=1
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: SUPP_PAE entering state AUTHENTICATING
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: SUPP_BE entering state SUCCESS
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAP: EAP entering state DISABLED
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: SUPP_PAE entering state AUTHENTICATED
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: Supplicant port status: Authorized
Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: Set supplicant port authorized for 20:e5:2a:2b:78:47
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: SUPP_BE entering state IDLE
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL authentication completed - result=SUCCESS
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: Removing interface wlan0
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: Request to deauthenticate - bssid=20:e5:2a:2b:78:47 pending_bssid=00:00:00:00:00:00 reason=3 state=COMPLETED
Mar 09 02:24:46 volumio wpa_supplicant[864]: TDLS: Tear down peers
Mar 09 02:24:46 volumio wpa_supplicant[864]: wpa_driver_nl80211_disconnect(reason_code=3)
Mar 09 02:24:46 volumio systemd[1]: Stopping Wireless Services...
Mar 09 02:24:46 volumio volumio[936]: info: mDNS: A device disapperared from network
Mar 09 02:24:46 volumio volumio[936]: info: mDNS: Device volumio disapperared from network
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: Event DEAUTH (12) received
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: Deauthentication notification
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0:  * reason 3 (locally generated)
Mar 09 02:24:46 volumio wpa_supplicant[864]: Deauthentication frame IE(s) - hexdump(len=0): [NULL]
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: CTRL-EVENT-DISCONNECTED bssid=20:e5:2a:2b:78:47 reason=3 locally_generated=1
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: Auto connect disabled: do not try to re-connect
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: Ignore connection failure indication since interface has been put into disconnected state
Mar 09 02:24:46 volumio wpa_supplicant[864]: TDLS: Remove peers on disassociation
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: Disconnect event - remove keys
Mar 09 02:24:46 volumio wpa_supplicant[864]: wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=0 addr=(nil) key_idx=0 set_tx=0 seq_len=0 key_len=0
Mar 09 02:24:46 volumio wpa_supplicant[864]: wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=0 addr=(nil) key_idx=1 set_tx=0 seq_len=0 key_len=0
Mar 09 02:24:46 volumio wpa_supplicant[864]: wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=0 addr=0x21a6a48 key_idx=0 set_tx=0 seq_len=0 key_len=0
Mar 09 02:24:46 volumio wpa_supplicant[864]: addr=20:e5:2a:2b:78:47
Mar 09 02:24:46 volumio netplugd[937]: wlan0: state OUTING flags 0x00011043 UP,BROADCAST,RUNNING,MULTICAST,10000 -> 0x00001003 UP,BROADCAST,MULTICAST
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: State: COMPLETED -> DISCONNECTED
Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: Set wlan0 operstate 1->0 (DORMANT)
Mar 09 02:24:46 volumio wpa_supplicant[864]: netlink: Operstate: ifindex=3 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: External notification - portEnabled=0
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: SUPP_PAE entering state DISCONNECTED
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: Supplicant port status: Unauthorized
Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: Skip set_supp_port(unauthorized) while not associated
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: SUPP_BE entering state INITIALIZE
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: External notification - portValid=0
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: External notification - EAP success=0
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: State: DISCONNECTED -> DISCONNECTED
Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: Set wlan0 operstate 0->0 (DORMANT)
Mar 09 02:24:46 volumio wpa_supplicant[864]: netlink: Operstate: ifindex=3 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: External notification - portEnabled=0
Mar 09 02:24:46 volumio wpa_supplicant[864]: EAPOL: External notification - portValid=0
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: BSS: Remove id 0 BSSID 20:e5:2a:2b:78:47 SSID 'Benjamin' due to wpa_bss_flush
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: Cancelling scan request
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: Cancelling authentication timeout
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: P2P: Disable P2P since removing the management interface is being removed
Mar 09 02:24:46 volumio wpa_supplicant[864]: P2P: Stopping find
Mar 09 02:24:46 volumio wpa_supplicant[864]: P2P: Clear timeout (state=IDLE)
Mar 09 02:24:46 volumio wpa_supplicant[864]: P2P: State IDLE -> IDLE
Mar 09 02:24:46 volumio wpa_supplicant[864]: Remove interface wlan0 from radio phy0
Mar 09 02:24:46 volumio wpa_supplicant[864]: Remove radio phy0
Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: Remove monitor interface: refcount=0
Mar 09 02:24:46 volumio wpa_supplicant[864]: netlink: Operstate: ifindex=3 linkmode=0 (kernel-control), operstate=6 (IF_OPER_UP)
Mar 09 02:24:46 volumio netplugd[937]: wlan0: state OUTING flags 0x00001003 UP,BROADCAST,MULTICAST -> 0x00001002 BROADCAST,MULTICAST
Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: Set mode ifindex 3 iftype 2 (STATION)
Mar 09 02:24:46 volumio wpa_supplicant[864]: nl80211: Unsubscribe mgmt frames handle 0x8a92f241 (mode change)
Mar 09 02:24:46 volumio wpa_supplicant[864]: wlan0: CTRL-EVENT-TERMINATING
Mar 09 02:24:46 volumio kernel: ------------[ cut here ]------------
Mar 09 02:24:46 volumio kernel: WARNING: CPU: 0 PID: 3377 at net/wireless/sme.c:943 __cfg80211_disconnected+0x4a4/0x4fc [cfg80211]
Mar 09 02:24:46 volumio kernel: Modules linked in: rpcsec_gss_krb5 xt_REDIRECT nf_nat_redirect xt_tcpudp iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack ip_tables x_tables nfsd 8192cu cfg80211 snd_soc_pcm512x_i2c rfkill snd_soc_pcm512x snd_soc_bcm2835_i2s snd_soc_hifiberry_dacplus snd_soc_core snd_bcm2835 snd_compress snd_pcm_dmaengine snd_pcm snd_seq snd_seq_device snd_timer snd i2c_bcm2835 bcm2835_gpiomem clk_hifiberry_dacpro uio_pdrv_genirq uio fixed i2c_dev fuse ipv6 squashfs overlay
Mar 09 02:24:46 volumio kernel: CPU: 0 PID: 3377 Comm: kworker/u8:0 Not tainted 4.9.65-v7+ #1056
Mar 09 02:24:46 volumio kernel: Hardware name: BCM2835
Mar 09 02:24:46 volumio kernel: Workqueue: cfg80211 cfg80211_event_work [cfg80211]
Mar 09 02:24:46 volumio kernel: [<8010fa48>] (unwind_backtrace) from [<8010c058>] (show_stack+0x20/0x24)
Mar 09 02:24:46 volumio kernel: [<8010c058>] (show_stack) from [<80457704>] (dump_stack+0xd4/0x118)
Mar 09 02:24:46 volumio kernel: [<80457704>] (dump_stack) from [<8011d348>] (__warn+0xf8/0x110)
Mar 09 02:24:46 volumio kernel: [<8011d348>] (__warn) from [<8011d430>] (warn_slowpath_null+0x30/0x38)
Mar 09 02:24:46 volumio kernel: [<8011d430>] (warn_slowpath_null) from [<7f2ff250>] (__cfg80211_disconnected+0x4a4/0x4fc [cfg80211])
Mar 09 02:24:46 volumio kernel: [<7f2ff250>] (__cfg80211_disconnected [cfg80211]) from [<7f2d4bac>] (cfg80211_process_wdev_events+0x1a0/0x1a8 [cfg80211])
Mar 09 02:24:46 volumio kernel: [<7f2d4bac>] (cfg80211_process_wdev_events [cfg80211]) from [<7f2d4bf0>] (cfg80211_process_rdev_events+0x3c/0x70 [cfg80211])
Mar 09 02:24:46 volumio kernel: [<7f2d4bf0>] (cfg80211_process_rdev_events [cfg80211]) from [<7f2cf284>] (cfg80211_event_work+0x24/0x2c [cfg80211])
Mar 09 02:24:46 volumio kernel: [<7f2cf284>] (cfg80211_event_work [cfg80211]) from [<801367b8>] (process_one_work+0x158/0x454)
Mar 09 02:24:46 volumio kernel: [<801367b8>] (process_one_work) from [<80136b18>] (worker_thread+0x64/0x5b8)
Mar 09 02:24:46 volumio kernel: [<80136b18>] (worker_thread) from [<8013ca34>] (kthread+0x10c/0x124)
Mar 09 02:24:46 volumio kernel: [<8013ca34>] (kthread) from [<80108148>] (ret_from_fork+0x14/0x2c)
Mar 09 02:24:46 volumio kernel: ---[ end trace 7b579bc48261f64f ]---

A lot happened in that second but it would seem the root cause is some kind of bug in the kernel wireless driver code - the bit that starts with [cut here].

For the rest of the log you linked to, volumio tries to start the wireless again but fails; so it seems the wireless device gets into a state that it can't recover from. So I think this a problem in the kernel.

I found a similar issue but there it was blamed on the hardware. There is also this but it's not clear it's the same problem.

Ultimately this might be fixed in the kernels that come with later versions of volumio but that's going to be a while.

Suggestions

use wired ethernet, disable wireless and hotspot
stick with wireless but disable hotspot
try a different usb wireless device
try unplugging and replugging the wireless device while the machine is running, if that is possiblel that might cause a driver reload.

Other readers of this issue - please have a close look yourself as I may have missed something.

jbmfg commented 6 years ago

Thanks @xipmix, thats great info. However, most of the time i am still able to get to the server via ssh. So it is still up an able to play music via "volumio play" command. Its seems when this issue occurs it mostly results in the webinterface not being available.

Also, issuing a volumio vrestart did not bring the web interface back up. Only a full reboot will allow the ui to load

xipmix commented 6 years ago

That's valuable information, thanks. When you connect in that circumstance, does

/sbin/ifconfig wlan0`

show the IP address you expect, or the 'hotspot' one (192.168.211.1) ?

I'm afraid the web interface is somewhat mysterious to me so I'll have to leave that to others. It might be worth posting the log just after doing the vrestart though; eg

$ volumio vrestart
$ sudo journalctl --since="-5m"

jbmfg commented 6 years ago

ifconfig shows the correct ip address of the pi and i have the wifi hotspot feature turned off. Here is a log right after issuing the vrestart command: https://drive.google.com/open?id=1qaUdaOVSmDJSILuLHfn-Jq2SdGIkUOgK

One thing i just noticed is that i can only ssh into the pi from a linux machine that is hard wired to my network. Further, when i did a "curl 192.168.0.40" from that box i got a response from the webUI so it is apparently up. When i attempt to ssh from putty on a wireless windows client i cannot connect or ping (no webui.) Another hard wired windows machine will not ping or ssh (and obv no webui here either.) Finally my phone with connectbot would not ssh into the pi either, i did not try to ping as i dont have an app for that. In short i seem to only have any kind of network access to the pi from one machine on my network. So it seems i have a networking issue? I dont know why rebooting the pi makes all of this go away though.

macmpi commented 6 years ago

Feb 15 13:53:37 volumio kernel: usb 1-1.4: Product: 802.11n WLAN Adapter
Feb 15 13:53:37 volumio kernel: usb 1-1.4: Manufacturer: Realtek

Can you specify which Realtek USB dongle you are using on your Pi2? Can you give output of lsusb and lsmod ?

Also you may want to set proper CRDA region code: some devices are quite picky about that, and your router may change channels sometimes to 12 or 13 which are region dependent.

jbmfg commented 6 years ago

I have now set the CRDA to US, will see if that helps. Outputs of lsusb and lsmod below:

volumio@volumio:~$ lsusb
Bus 001 Device 004: ID 7392:7811 Edimax Technology Co., Ltd EW-7811Un 802.11n Wireless Adapter [Realtek RTL8188CUS]
Bus 001 Device 003: ID 0424:ec00 Standard Microsystems Corp. SMSC9512/9514 Fast Ethernet Adapter
Bus 001 Device 002: ID 0424:9514 Standard Microsystems Corp.
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

volumio@volumio:~$ lsmod
Module                  Size  Used by
rpcsec_gss_krb5        23752  0
xt_REDIRECT             1618  1
nf_nat_redirect         1937  1 xt_REDIRECT
xt_tcpudp               2526  1
iptable_nat             2320  1
nf_conntrack_ipv4       8890  1
nf_defrag_ipv4          1824  1 nf_conntrack_ipv4
nf_nat_ipv4             6071  1 iptable_nat
nf_nat                 17066  2 nf_nat_redirect,nf_nat_ipv4
nf_conntrack          104634  3 nf_conntrack_ipv4,nf_nat_ipv4,nf_nat
ip_tables              13161  1 iptable_nat
x_tables               20578  3 ip_tables,xt_tcpudp,xt_REDIRECT
nfsd                  291125  2
8192cu                582281  0
cfg80211              544609  1 8192cu
snd_soc_pcm512x_i2c     2718  1
snd_soc_pcm512x        21992  1 snd_soc_pcm512x_i2c
rfkill                 20851  2 cfg80211
snd_soc_hifiberry_dacplus     5055  1
snd_soc_bcm2835_i2s     7480  2
snd_bcm2835            24427  1
snd_soc_core          180471  3 snd_soc_pcm512x,snd_soc_hifiberry_dacplus,snd_soc_bcm2835_i2s
snd_compress           10384  1 snd_soc_core
snd_pcm_dmaengine       5894  1 snd_soc_core
snd_pcm                98501  7 snd_soc_pcm512x,snd_pcm_dmaengine,snd_soc_hifiberry_dacplus,snd_soc_bcm2835_i2s,snd_bcm2835,snd_soc_core
snd_seq                62122  0
snd_seq_device          5542  1 snd_seq
snd_timer              23968  2 snd_seq,snd_pcm
snd                    70032  10 snd_compress,snd_seq,snd_timer,snd_seq_device,snd_bcm2835,snd_soc_core,snd_pcm
i2c_bcm2835             7167  0
bcm2835_gpiomem         3940  0
clk_hifiberry_dacpro     2812  1
fixed                   3285  3
uio_pdrv_genirq         3923  0
uio                    10204  1 uio_pdrv_genirq
i2c_dev                 6913  0
fuse                   99603  1
ipv6                  409002  70
squashfs               33761  1
overlay                38962  1

macmpi commented 6 years ago

Any benefit since CRDA was set? This EW-7811Un dongle and assorted 8192cu driver has been pretty stable so far AFAIK.

jbmfg commented 6 years ago

No, no improvement. Seeing as how i have access to the pi from one computer on my network Im starting to think its not an issue with the pi. I cant explain why that one computer can still contact the pi and nothing else can though

xipmix commented 6 years ago

When you say 'contact' do you mean: 'ping' or access the web UI ?

jbmfg commented 6 years ago

Both. Once the issue occurs nothing on my network can ping, ssh, or access the web ui except one linux box. I have tried from computers on both my wireless networks (same ap, 5ghz & 2.4ghz)jbg as well as an ethernet connected windows machine on the same switch as the linux box that can connect (ssh, webui, ping, etc)

Since the webui survived the night i tried accessing it from all the available machines i have. I cannot access it from my phone on wireless, the ethernet connected windows machine, or a VM on my main computer connected via wireless. I can however access everything from that same machine that hosts the vm and a linux box ethernet connected. I cant make heads or tails of it.

xipmix commented 6 years ago

Tricky. Is the VM linux? To make progress it would be nice to know what volumio is doing when the web ui appears to go dead. This might allow that:

start capturing logs on the pi with the journalctl -f trick
leave a script running on the VM that does a ping and/or a curl connection every minute or so

When your volumio web ui falls over from the point of view of a machine external to the pi, you will see errors start appearing from the script on the VM. You can use that timestamp to find the corresponding time in the volumio log, which may tell us something useful.

For extra data, you might also ping your home router to check that it's not causing the issue. So something like

VM$ cat test.sh

#!/bin/bash
ROUTER=192.168.0.1
VOLUMIO=192.168.0.40
while true
do
   echo "------------------------------------"
    date -u
    # basic connectivity
    ping -n -q -c 5 $ROUTER || echo "$ROUTER PING FAILED"
    # volumio connectivity
    ping -n -q -c 5 $VOLUMIO || echo "$VOLUMIO PING FAILED"
    # volumio ui check
    curl -sSf http:/${VOLUMIO} > /dev/null
    sleep 60
done

VM$ sh test.sh >test.log

The above could probably be made to work on windows with the cygwin tools.

jbmfg commented 6 years ago

Thanks @xipmix ! Below is the only thing i see when the pings of volumio began to fail:

Mar 26 14:34:25 volumio nmbd[819]: [2018/03/26 14:34:25.296673,  0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response)
Mar 26 14:34:25 volumio nmbd[819]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.0.40 for name WORKGROUP<1d>.
Mar 26 14:34:25 volumio nmbd[819]: This response was from IP 192.168.0.239, reporting an IP address of 192.168.0.239.

192.168.0.239 is another raspberry pi on my network (openelec/recalbox). Interestingly, while these pings are failing in the guest VM i am running the connectivity script on I still have access to volumio (pings, webui, ssh) from the host OS

volumio / Volumio2

Web interface inaccessible after period of time #1497