search

volumio / Volumio2

Volumio 2 - Audiophile Music Player
http://volumio.org
Other
1.37k stars 315 forks source link

volumio keeps restarting #1419

Closed xipmix closed 6 years ago

xipmix commented 6 years ago

Just upgraded to 2.344, fresh burn of the image from volumio.org. I set up the network with ethernet only, wireless and hotspot were disabled.

I noticed volumio exit and restart at seemingly random times, it seemed worst in 'My Music'. I've seen 21 of these restarts, in various guises, over the 33minutes the machine has been up. As I've been typing it has gotten worse.

Looking through the logs I found this

Dec 16 00:11:11 volumio systemd[1]: Reached target Host and Network Name Lookups.
Dec 16 00:11:11 volumio volumio[649]: Could not open config: /tmp/upmpdcli.conf
Dec 16 00:11:11 volumio systemd[1]: Received SIGRTMIN+21 from PID 281 (plymouthd).
Dec 16 00:11:11 volumio systemd[1]: Starting Wireless Services...
Dec 16 00:11:11 volumio avahi-daemon[692]: Server startup complete. Host name is volumio.local. Local service 
Dec 16 00:11:11 volumio systemd[1]: Started Hold until boot process finishes up.
Dec 16 00:11:11 volumio systemd[1]: Started Terminate Plymouth Boot Screen.
Dec 16 00:11:11 volumio dbus[698]: [system] Successfully activated service 'org.freedesktop.UDisks'
Dec 16 00:11:11 volumio systemd[1]: Started Disk Manager (legacy version).
Dec 16 00:11:11 volumio systemd[1]: Starting Getty on tty1...
Dec 16 00:11:11 volumio systemd[1]: Started Getty on tty1.
Dec 16 00:11:11 volumio systemd[1]: Starting Serial Getty on ttyAMA0...
Dec 16 00:11:11 volumio systemd[1]: Started Serial Getty on ttyAMA0.
Dec 16 00:11:11 volumio systemd[1]: Starting Login Prompts.
Dec 16 00:11:11 volumio systemd[1]: Reached target Login Prompts.
Dec 16 00:11:11 volumio systemd[1]: upmpdcli.service: main process exited, code=exited, status=1/FAILURE
Dec 16 00:11:11 volumio systemd[1]: Unit upmpdcli.service entered failed state.
Dec 16 00:11:11 volumio sudo[778]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 set pow

and a few of these

Dec 16 05:46:21 Volumio volumio[942]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares
Dec 16 05:46:23 Volumio volumio[942]: info: CoreCommandRouter::executeOnPlugin: wizard , getDonation
Dec 16 05:46:23 Volumio volumio[942]: info: CoreCommandRouter::executeOnPlugin: wizard , getDonationsArray
Dec 16 05:46:23 Volumio volumio[942]: info: CoreCommandRouter::executeOnPlugin: wizard , getDoneMessage
Dec 16 05:46:26 Volumio volumio[942]: info: CoreCommandRouter::executeOnPlugin: wizard , setWizardAction
Dec 16 05:46:26 Volumio volumio[942]: info: CoreCommandRouter::executeOnPlugin: system , setShowWizard
Dec 16 05:46:26 Volumio volumio[942]: info: Wizard terminated Successfully
Dec 16 05:48:10 Volumio volumio[942]: events.js:160
Dec 16 05:48:10 Volumio volumio[942]: throw er; // Unhandled 'error' event
Dec 16 05:48:10 Volumio volumio[942]: ^
Dec 16 05:48:10 Volumio volumio[942]: Error: connect EINVAL fe80::21c:c0ff:fe22:1d46:6544 - Local (:::0)
Dec 16 05:48:10 Volumio volumio[942]: at Object.exports._errnoException (util.js:1018:11)
Dec 16 05:48:10 Volumio volumio[942]: at exports._exceptionWithHostPort (util.js:1041:20)
Dec 16 05:48:10 Volumio volumio[942]: at connect (net.js:880:16)
Dec 16 05:48:10 Volumio volumio[942]: at net.js:969:9
Dec 16 05:48:10 Volumio volumio[942]: at _combinedTickCallback (internal/process/next_tick.js:73:7)
Dec 16 05:48:10 Volumio volumio[942]: at process._tickCallback (internal/process/next_tick.js:104:9)
Dec 16 05:48:10 Volumio volumio-remote-updater[650]: [2017-12-16 05:48:10] [error] handle_read_frame error: websocketpp.transport:7 (
Dec 16 05:48:10 Volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE
Dec 16 05:48:10 Volumio volumio-remote-updater[650]: [2017-12-16 05:48:10] [disconnect] Disconnect close local:[1006,End of File] rem
Dec 16 05:48:10 Volumio systemd[1]: Unit volumio.service entered failed state.

another variant

Dec 16 05:48:27 Volumio volumio-remote-updater[650]: [2017-12-16 05:48:27] [connect] Successful connection
Dec 16 05:48:27 Volumio volumio-remote-updater[650]: [2017-12-16 05:48:27] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSock
Dec 16 05:48:28 Volumio sudo[2509]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Dec 16 05:48:28 Volumio sudo[2509]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 16 05:48:28 Volumio systemd[1]: Started UPnP Renderer front-end to MPD.
Dec 16 05:48:28 Volumio sudo[2509]: pam_unix(sudo:session): session closed for user root
Dec 16 05:48:28 Volumio volumio[2391]: info: Upmpdcli Daemon Started
Dec 16 05:53:21 Volumio volumio[2391]: events.js:160
Dec 16 05:53:21 Volumio volumio[2391]: throw er; // Unhandled 'error' event
Dec 16 05:53:21 Volumio volumio[2391]: ^
Dec 16 05:53:21 Volumio volumio[2391]: Error: connect EINVAL fe80::21c:c0ff:fe22:1d46:6544 - Local (:::0)
Dec 16 05:53:21 Volumio volumio[2391]: at Object.exports._errnoException (util.js:1018:11)
Dec 16 05:53:21 Volumio volumio[2391]: at exports._exceptionWithHostPort (util.js:1041:20)
Dec 16 05:53:21 Volumio volumio[2391]: at connect (net.js:880:16)
Dec 16 05:53:21 Volumio volumio[2391]: at net.js:969:9
Dec 16 05:53:21 Volumio volumio[2391]: at _combinedTickCallback (internal/process/next_tick.js:73:7)
Dec 16 05:53:21 Volumio volumio[2391]: at process._tickCallback (internal/process/next_tick.js:104:9)
Dec 16 05:53:21 Volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE
Dec 16 05:53:21 Volumio volumio-remote-updater[650]: [2017-12-16 05:53:21] [error] handle_read_frame error: websocketpp.transport:7 (
Dec 16 05:53:21 Volumio volumio-remote-updater[650]: [2017-12-16 05:53:21] [disconnect] Disconnect close local:[1006,End of File] rem
Dec 16 05:53:21 Volumio systemd[1]: Unit volumio.service entered failed state.

and this just after restarting

Dec 16 05:53:33 Volumio volumio[4516]: info: BOOT COMPLETED
Dec 16 05:53:33 Volumio volumio[4516]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 16 05:53:33 Volumio volumio[4516]: info: CoreCommandRouter::Close All Modals sent
Dec 16 05:53:33 Volumio volumio[4516]: Express server listening on port 3000
Dec 16 05:53:33 Volumio volumio[4516]: Volumio Calling Home
Dec 16 05:53:33 Volumio volumio[4516]: info: [1513403613853] CoreStateMachine::resetVolumioState
Dec 16 05:53:33 Volumio volumio[4516]: info: [1513403613857] CoreStateMachine::getcurrentVolume
Dec 16 05:53:33 Volumio volumio[4516]: info: CoreCommandRouter::volumioRetrievevolume
Dec 16 05:53:33 Volumio volumio[4516]: info: [1513403613893] CoreStateMachine::updateTrackBlock
Dec 16 05:53:33 Volumio volumio[4516]: info: [1513403613897] CorePlayQueue::getTrackBlock
Dec 16 05:53:34 Volumio volumio[4516]: info: Cannot read play queue from file
Dec 16 05:53:34 Volumio volumio[4516]: events.js:160
Dec 16 05:53:34 Volumio volumio[4516]: throw er; // Unhandled 'error' event
Dec 16 05:53:34 Volumio volumio[4516]: ^
Dec 16 05:53:34 Volumio volumio[4516]: Error: connect EINVAL fe80::21c:c0ff:fe22:1d46:6544 - Local (:::0)
Dec 16 05:53:34 Volumio volumio[4516]: at Object.exports._errnoException (util.js:1018:11)
Dec 16 05:53:34 Volumio volumio[4516]: at exports._exceptionWithHostPort (util.js:1041:20)
Dec 16 05:53:34 Volumio volumio[4516]: at connect (net.js:880:16)
Dec 16 05:53:34 Volumio volumio[4516]: at net.js:969:9
Dec 16 05:53:34 Volumio volumio[4516]: at _combinedTickCallback (internal/process/next_tick.js:73:7)
Dec 16 05:53:34 Volumio volumio[4516]: at process._tickCallback (internal/process/next_tick.js:104:9)
Dec 16 05:53:34 Volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE
Dec 16 05:53:34 Volumio systemd[1]: Unit volumio.service entered failed state.

The source seems to be /volumio/node_modules/inquirer/lib/utils/events.js

xipmix commented 6 years ago

Looks similar to #1414 but I don't have spotify/spop installed.

xipmix commented 6 years ago

I did the obvious thing and rebooted but it's not any better. It fails so often I can't even get a log to upload. I can send a journalctl dump out of band if you wish.

volumio commented 6 years ago

Can you please connect via SSH and try to manually revert this commit: https://github.com/volumio/Build/commit/8c1dcbe2952334e91b117418d817da818fa2fb40 (change the order as it was before the commit). Save, sync and turn off. Reboot your router and restart

let me know

Also, how did you came to the conclusion that it's the inquirer module? /volumio/node_modules/inquirer/lib/utils/events.js

volumio commented 6 years ago

@xipmix I am not able to recreate this bug, so it would be super useful if you could help us track down the issue (so please don't format this SD card).

Thanks

xipmix commented 6 years ago

I'll git the revert a try. WRT events.js I guess the issue is more with whatever is calling events.js but I could not track that down with a quick grep -r.

xipmix commented 6 years ago

For reference I did not see this problem with 2.323.

Reverting the change to nsswitch.conf made no apparent difference. I even rebooted the router, which I don't understand the need for.

There was something a little goofy about my setup - in my local dns server 'volumio' is a CNAME for a particular hardware device. I did have it pointed at the IP for the wireless interface of the pi, which as mentioned was not configured. I changed that so the CNAME points at the IP for the ethernet interface. As one might have hoped, that didn't make any difference. Note that my local dns domain is a private name, not '.local.', so there should be no overlap with resolution of volumio.local -

volumio@volumio:~$ host volumio.local
Host volumio.local not found: 3(NXDOMAIN)
$ cat /etc/resolv.conf
# Generated by dhcpcd from eth0
domain <redacted>
nameserver 192.168.x.x
# OpenDNS nameservers
nameserver 208.67.222.222
nameserver 208.67.220.220
volumio@volumio:~$ host volumio
volumio is an alias for rpi2a-wire.
rpi2a-wire has address 192.168.x.y

When I dug into the logs a bit more I find all of the repeating failures of the volumio process are to do with getting EINVAL from trying an IPv6 address, e.g.

Dec 17 03:06:37 volumio volumio[1221]: Volumio Calling Home
Dec 17 03:06:38 volumio volumio[1221]: info: [1513479998044] CoreStateMachine::resetVolumioState
Dec 17 03:06:38 volumio volumio[1221]: info: [1513479998048] CoreStateMachine::getcurrentVolume
Dec 17 03:06:38 volumio volumio[1221]: info: CoreCommandRouter::volumioRetrievevolume
Dec 17 03:06:38 volumio volumio[1221]: info: [1513479998084] CoreStateMachine::updateTrackBlock
Dec 17 03:06:38 volumio volumio[1221]: info: [1513479998087] CorePlayQueue::getTrackBlock
Dec 17 03:06:38 volumio volumio[1221]: info: Cannot read play queue from file
Dec 17 03:06:38 volumio volumio[1221]: events.js:160
Dec 17 03:06:38 volumio volumio[1221]: throw er; // Unhandled 'error' event
Dec 17 03:06:38 volumio volumio[1221]: ^
Dec 17 03:06:38 volumio volumio[1221]: Error: connect EINVAL fe80::21c:c0ff:fe22:1d46:6544 - Local (:::0)
Dec 17 03:06:38 volumio volumio[1221]: at Object.exports._errnoException (util.js:1018:11)
Dec 17 03:06:38 volumio volumio[1221]: at exports._exceptionWithHostPort (util.js:1041:20)
Dec 17 03:06:38 volumio volumio[1221]: at connect (net.js:880:16)
Dec 17 03:06:38 volumio volumio[1221]: at net.js:969:9
Dec 17 03:06:38 volumio volumio[1221]: at _combinedTickCallback (internal/process/next_tick.js:73:7)
Dec 17 03:06:38 volumio volumio[1221]: at process._tickCallback (internal/process/next_tick.js:104:9)
Dec 17 03:06:38 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE
Dec 17 03:06:38 volumio volumio-remote-updater[527]: [2017-12-17 03:06:38] [info] asio async_read_at_least error: system:104 (Connection reset by peer)
Dec 17 03:06:38 volumio volumio-remote-updater[527]: [2017-12-17 03:06:38] [error] handle_read_http_response error: websocketpp.transport:2 (Underlying Transport Error)
Dec 17 03:06:38 volumio volumio-remote-updater[527]: [2017-12-17 03:06:38] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected)

On my router, v6 is disabled as I don't understand how it works and have no need for it. I tried reducing the priority of v6 with this change and a reboot

--- gai.conf.old        2017-12-17 03:25:41.000000000 +0000
+++ /etc/gai.conf       2017-12-17 03:20:58.000000000 +0000
@@ -51,7 +51,7 @@
 #
 #    For sites which prefer IPv4 connections change the last line to
 #
-#precedence ::ffff:0:0/96  100
+precedence ::ffff:0:0/96  100

 #
 # scopev4  <mask>  <value>

That didn't work either.

xipmix commented 6 years ago

I noticed in the log that volumio was not able to connect to the NAS. It had done so ok the first time, and completed a scan of the music there. So I was a bit surprised when I tried to ping it and got

volumio@volumio:~$ ping 192.168.x.z
ping: icmp open socket: Operation not permitted

Root is allowed to do this

volumio@volumio:~$ sudo ping 192.168.x.z
[sudo] password for volumio: 
PING 192.168.x.z (192.168.x.z) 56(84) bytes of data.
64 bytes from 192.168.x.z: icmp_seq=1 ttl=64 time=3.98 ms
^C

I tried a manual (NFS) mount of the NAS as root and that worked also.

Could this be related to the recent capabilities changes?

xipmix commented 6 years ago

I started disabling things to do with networking.

# systemctl disable volumio-remote-updater; systemctl stop volumio-remote-updater

That seemed to make things a bit more stable; ie if I reboot and do nothing in the web ui, just wait for it to fail, that happens less often.

I messed about with ipv6 configuration but that did not seem to help much.

I tried commenting out the self.callHome() in onVolumioStart. That seemed to help also.

As I was watching the logs I can see it keeps trying to mount the NAS even though it is mounted already. I don't think that is right but it may be a side effect.

I am still getting restarts but far fewer.

$ sudo journalctl |grep FAILURE
Dec 18 12:38:25 volumio systemd[1]: upmpdcli.service: main process exited, code=exited, status=1/FAILURE
Dec 18 12:38:28 volumio systemd[1]: hotspot.service: main process exited, code=exited, status=1/FAILURE
Dec 18 12:39:05 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE
Dec 18 12:39:18 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE
Dec 18 12:39:30 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE
Dec 18 12:39:43 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE
Dec 18 12:39:55 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE
Dec 18 12:40:08 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE
Dec 18 12:41:10 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE
Dec 18 12:42:11 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE
Dec 18 12:48:13 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE
Dec 18 12:50:05 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE

Something is up with shairport discovery

Dec 18 12:48:28 volumio shairport-sync[4811]: Successful Startup
Dec 18 12:48:28 volumio volumio[4732]: Discovery: adding 5f8126d0-02be-4e90-8e5e-b854eaad6259
Dec 18 12:48:28 volumio volumio[4732]: info: mDNS: Found device Volumio
Dec 18 12:48:28 volumio volumio[4732]: info: [1513601308939] Shairport-Sync Started
Dec 18 12:48:28 volumio volumio[4732]: Error adding Membership: Error: addMembership EINVAL
Dec 18 12:48:29 volumio volumio[4732]: info: CoreCommandRouter::volumioGetState

Still seeing these, over time they are the most common error.

Dec 18 12:48:31 volumio systemd[1]: Started UPnP Renderer front-end to MPD.
Dec 18 12:48:31 volumio sudo[4849]: pam_unix(sudo:session): session closed for user root
Dec 18 12:48:31 volumio volumio[4732]: info: Upmpdcli Daemon Started
Dec 18 12:48:33 volumio volumio[4732]: info: Cannot mount NAS 192.168.x.y at system boot, trial number 3 ,retrying in 5 seconds
Dec 18 12:48:34 volumio sudo[2883]: pam_unix(sudo:session): session closed for user root
Dec 18 12:48:38 volumio volumio[4732]: info: Cannot mount NAS 192.168.x.y at system boot, trial number 4 ,retrying in 5 seconds
Dec 18 12:48:43 volumio volumio[4732]: info: Cannot mount NAS at system boot, trial number 4 ,stopping
Dec 18 12:50:05 volumio volumio[4732]: events.js:160
Dec 18 12:50:05 volumio volumio[4732]: throw er; // Unhandled 'error' event
Dec 18 12:50:05 volumio volumio[4732]: ^
Dec 18 12:50:05 volumio volumio[4732]: Error: connect EINVAL fe80::21c:c0ff:fe22:1d46:6544 - Local (:::0)
Dec 18 12:50:05 volumio volumio[4732]: at Object.exports._errnoException (util.js:1018:11)
Dec 18 12:50:05 volumio volumio[4732]: at exports._exceptionWithHostPort (util.js:1041:20)
Dec 18 12:50:05 volumio volumio[4732]: at connect (net.js:880:16)
Dec 18 12:50:05 volumio volumio[4732]: at net.js:969:9
Dec 18 12:50:05 volumio volumio[4732]: at _combinedTickCallback (internal/process/next_tick.js:73:7)
Dec 18 12:50:05 volumio volumio[4732]: at process._tickCallback (internal/process/next_tick.js:104:9)
Dec 18 12:50:05 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE
Dec 18 12:50:05 volumio systemd[1]: Unit volumio.service entered failed state.

I'm stuck. I cannot find 'net.js' anywhere on the system. /volumio/node_modules/inquirer/lib/utils/events.js exists but has only 45 lines. utils.js appears in lots of node_modules. I do see the line "throw er; // Unhandled 'error' event", in /volumio/node_modules/musicmetadata/dist/musicmetadata.js at line 1426 /volumio/node_modules/is-function/browser-test.js line 1382 (the code looks very similar)

volumio commented 6 years ago

To me it looks like: https://github.com/diversario/node-ssdp/issues/84

I included a tentative fix here: https://github.com/volumio/Volumio2/commit/d97f0675ed74e2fd2fe8fd10913aada238146397

I will build an image and send to you, if you can test it, that would be awesome

volumio commented 6 years ago

@xipmix as promised: http://updates.volumio.org/pi/volumio/2.345/volumio-2.345-2017-12-18-pi.img.zip

Could you please try it and report back?

volumio commented 6 years ago

@xipmix , furthermore, could you please do as explained in this post?

https://volumio.org/forum/344-crashing-odroid-t8346.html#p42352

xipmix commented 6 years ago

I gave the new image a try. I booted it and modified node-ssdp/index.js, then rebooted. It falls over so fast now that it can't even start the web interface.

I burned it again and booted with no code changes. It starts the web interface once, then fails every 12-15 seconds. Sometimes there is a longer gap. The rate seems about the same as the first try.

volumio commented 6 years ago

You should see it failing at a specific IP address, can you understand what service there is on this IP address?

xipmix commented 6 years ago

The only IP address mentioned in the logs is the v6 one shown above. Which is rather odd. It corresponds to a lan-local address for the eth0 interface (which is why the loopback ::1 is there also). But the system explicitly disables v6 with systctl. The ipv6 module is loaded of course. I tried to blacklist it in /etc/modprobe.d but it still loads.

I tried hacking musicmetadata.js and browser-test.js to log the error rather than rethrowing it, no joy.

volumio commented 6 years ago

@xipmix I definetely think the error is due to the DLNA browser plugin. Can you confirm it?

To do it, disable it by doing

nano /data/configuration/plugins.json

And set upnp_browser like this: "upnp_browser": { "enabled": { "type": "boolean", "value": false },

xipmix commented 6 years ago

Burned the image afresh, and made the edit you suggested, ran 'killall node'. It's solid now. I was able to turn off hotspot & wireless, configure a NAS drive and play a track after the scan finished. Did a reboot via the web UI and it came up ok. I was able to tweak a playback setting without the UI crashing.

So I think you've found the problem plugin. What next?

volumio commented 6 years ago

We need to find where the plugin actually crashes. and sanitize it with error handling or try catch. IMHO, this is the issue we're having: https://github.com/diversario/node-ssdp/issues/84

xipmix commented 6 years ago 
$ git diff 74957d23a0ea4f76014b8b6ee49bcbc3550d98d0 -- app/plugins/music_service/upnp_browser/|diffstat
 dlna-browser.js |  232 +++++++++++++++++++++++++++
 dlnaicon.png    |binary
 index.js        |  474 ++++++++++++++++++++++++++++++++++++++++----------------
 package.json    |    7 
 4 files changed, 578 insertions(+), 135 deletions(-)

That's a fair bit to dig through... hmm

volumio commented 6 years ago

Ok, let's do this: I will create a new branch and put some logs and fixes in there. Then I will send you the commands to execute to test it. Hopefully we nail the crash down..

volumio commented 6 years ago

Ok, let's try. First, start from a fresh image. Then connect via SSH and do:

volumio pull

then

cd /volumio
git checkout fix-dlna
killall node

Tell me if that works. If not, I may have traced the root cause. Do:

nano +101 /volumio/node_modules/node-ssdp/lib/client.js

Remove the line: 

self._logger('Sent M-SEARCH request: %o', {'message': pkt})

and put instead: 

if (err) {
                self._logger('Error in M-SEARCH: ' + err);
        } else {
                self._logger('Sent M-SEARCH request: %o', {'message': pkt})
        }
xipmix commented 6 years ago

The fix-dlna branch does not work, as you hoped. Patching the node-ssdp client.js did not seem to work after 'killall node'. After a reboot I thought we might be progressing but when I tried tweaking a playback setting, it fell over. Below is the patch I made, I think I got it right.

--- /volumio/node_modules/node-ssdp/lib/client.js.orig  2017-12-19 12:53:47.000000000 +0000
+++ /volumio/node_modules/node-ssdp/lib/client.js       2017-12-19 12:52:35.000000000 +0000
@@ -99,7 +99,12 @@
   var message = new Buffer(pkt)

   self._send(message, function (err, bytes) {
-    self._logger('Sent M-SEARCH request: %o', {'message': pkt})
+    // self._logger('Sent M-SEARCH request: %o', {'message': pkt})
+    if (err) {
+      self._logger('Error in M-SEARCH ' + err);
+    } else {
+      self._logger('Sent M-SEARCH request: %o', {'message': pkt})
+    }
   })
 }

NB I still had fix-dlna checked out in /volumio.

volumio commented 6 years ago

Can you resend the log after you tweaked playback settings?

xipmix commented 6 years ago

To clarify - the errors are the same as before. A v6 address appears and the error is thrown shortly after a call to volumio-remote-updater, or volumio calling home.

volumio commented 6 years ago

Yes, that's the real deal. IMHO what happens is: this IPV6 advertises itself as DLNA server, but the parsing and contacting of this IPV6 fails. Problem is, I can't replicate to find a fix. What if I do a remote connection to your system? Would that be ok for you? If yes, please drop me an email to info at volumio dot org

xipmix commented 6 years ago

Here is the section close to the time I saved the settings.

Dec 19 12:55:54 volumio volumio[987]: info: CoreCommandRouter::Close All Modals sent
Dec 19 12:55:56 volumio sudo[1102]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Dec 19 12:55:56 volumio sudo[1102]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 19 12:55:56 volumio systemd[1]: Starting UPnP Renderer front-end to MPD...
Dec 19 12:55:56 volumio systemd[1]: Started UPnP Renderer front-end to MPD.
Dec 19 12:55:56 volumio sudo[1102]: pam_unix(sudo:session): session closed for user root
Dec 19 12:55:56 volumio volumio[987]: info: Upmpdcli Daemon Started
Dec 19 12:56:39 volumio volumio[987]: info: UPNP: Started search routine
Dec 19 12:57:11 volumio volumio[987]: info: CoreCommandRouter::getUIConfigOnPlugin
Dec 19 12:57:11 volumio volumio[987]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions
Dec 19 12:57:11 volumio volumio[987]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 19 12:57:11 volumio volumio[987]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus
Dec 19 12:57:11 volumio volumio[987]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 19 12:57:11 volumio volumio[987]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 19 12:57:11 volumio volumio[987]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 19 12:57:11 volumio volumio[987]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 19 12:57:11 volumio volumio[987]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 19 12:57:11 volumio volumio[987]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 19 12:57:11 volumio volumio[987]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 19 12:57:15 volumio volumio[987]: info: CALLMETHOD: music_service mpd savePlaybackOptions [object Object]
Dec 19 12:57:15 volumio volumio[987]: info: CoreCommandRouter::executeOnPlugin: mpd , savePlaybackOptions
Dec 19 12:57:15 volumio sudo[1665]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 19 12:57:15 volumio volumio[987]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 19 12:57:15 volumio volumio[987]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 19 12:57:15 volumio volumio[987]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 19 12:57:15 volumio volumio[987]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 19 12:57:15 volumio sudo[1665]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 19 12:57:15 volumio volumio[987]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 19 12:57:15 volumio volumio[987]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 19 12:57:15 volumio volumio[987]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 19 12:57:15 volumio sudo[1665]: pam_unix(sudo:session): session closed for user root
Dec 19 12:57:15 volumio sudo[1668]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 19 12:57:15 volumio sudo[1668]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 19 12:57:15 volumio volumio[987]: info: MPD Permissions set
Dec 19 12:57:15 volumio systemd[1]: Stopping Music Player Daemon...
Dec 19 12:57:15 volumio systemd[1]: Starting Music Player Daemon...
Dec 19 12:57:16 volumio systemd[1]: Started Music Player Daemon.
Dec 19 12:57:16 volumio sudo[1668]: pam_unix(sudo:session): session closed for user root
Dec 19 12:57:16 volumio volumio[987]: error: Upnp client error: Error: This socket has been ended by the other party
Dec 19 12:57:16 volumio volumio[987]: info:
Dec 19 12:57:29 volumio volumio[987]: info: UPNP: Started search routine
Dec 19 12:57:29 volumio volumio[987]: events.js:160
Dec 19 12:57:29 volumio volumio[987]: throw er; // Unhandled 'error' event
Dec 19 12:57:29 volumio volumio[987]: ^
Dec 19 12:57:29 volumio volumio[987]: Error: connect EINVAL fe80::21c:c0ff:fe22:1d46:6544 - Local (:::0)
Dec 19 12:57:29 volumio volumio[987]: at Object.exports._errnoException (util.js:1018:11)
Dec 19 12:57:29 volumio volumio[987]: at exports._exceptionWithHostPort (util.js:1041:20)
Dec 19 12:57:29 volumio volumio[987]: at connect (net.js:880:16)
Dec 19 12:57:29 volumio volumio[987]: at net.js:969:9
Dec 19 12:57:29 volumio volumio[987]: at _combinedTickCallback (internal/process/next_tick.js:73:7)
Dec 19 12:57:29 volumio volumio[987]: at process._tickCallback (internal/process/next_tick.js:104:9)
Dec 19 12:57:29 volumio volumio-remote-updater[616]: [2017-12-19 12:57:29] [error] handle_read_frame error: websocketpp.transport:7 (End of File)
Dec 19 12:57:29 volumio volumio-remote-updater[616]: [2017-12-19 12:57:29] [disconnect] Disconnect close local:[1006,End of File] remote:[1006]
Dec 19 12:57:29 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE
Dec 19 12:57:29 volumio systemd[1]: Unit volumio.service entered failed state.
Dec 19 12:57:29 volumio systemd[1]: Starting dynamicswap service...
Dec 19 12:57:29 volumio systemd[1]: Started dynamicswap service.
Dec 19 12:57:29 volumio systemd[1]: volumio.service holdoff time over, scheduling restart.

This is from the end of the log, the endless loop of restarts

Dec 19 13:04:35 volumio volumio[4452]: info: BOOT COMPLETED
Dec 19 13:04:35 volumio volumio[4452]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 19 13:04:35 volumio volumio[4452]: info: CoreCommandRouter::Close All Modals sent
Dec 19 13:04:35 volumio volumio[4452]: Express server listening on port 3000
Dec 19 13:04:35 volumio volumio[4452]: Volumio Calling Home
Dec 19 13:04:35 volumio volumio[4452]: info: [1513688675459] CoreStateMachine::resetVolumioState
Dec 19 13:04:35 volumio volumio[4452]: info: [1513688675462] CoreStateMachine::getcurrentVolume
Dec 19 13:04:35 volumio volumio[4452]: info: CoreCommandRouter::volumioRetrievevolume
Dec 19 13:04:35 volumio volumio[4452]: info: [1513688675495] CoreStateMachine::updateTrackBlock
Dec 19 13:04:35 volumio volumio[4452]: info: [1513688675500] CorePlayQueue::getTrackBlock
Dec 19 13:04:35 volumio volumio[4452]: info: Cannot read play queue from file
Dec 19 13:04:35 volumio volumio[4452]: events.js:160
Dec 19 13:04:35 volumio volumio[4452]: throw er; // Unhandled 'error' event
Dec 19 13:04:35 volumio volumio[4452]: ^
Dec 19 13:04:35 volumio volumio[4452]: Error: connect EINVAL fe80::21c:c0ff:fe22:1d46:6544 - Local (:::0)
Dec 19 13:04:35 volumio volumio[4452]: at Object.exports._errnoException (util.js:1018:11)
Dec 19 13:04:35 volumio volumio[4452]: at exports._exceptionWithHostPort (util.js:1041:20)
Dec 19 13:04:35 volumio volumio[4452]: at connect (net.js:880:16)
Dec 19 13:04:35 volumio volumio[4452]: at net.js:969:9
Dec 19 13:04:35 volumio volumio[4452]: at _combinedTickCallback (internal/process/next_tick.js:73:7)
Dec 19 13:04:35 volumio volumio[4452]: at process._tickCallback (internal/process/next_tick.js:104:9)
Dec 19 13:04:35 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE
Dec 19 13:04:36 volumio systemd[1]: Unit volumio.service entered failed state.
Dec 19 13:04:36 volumio systemd[1]: Starting dynamicswap service...
Dec 19 13:04:36 volumio systemd[1]: Started dynamicswap service.
Dec 19 13:04:36 volumio systemd[1]: volumio.service holdoff time over, scheduling restart.
volumio commented 6 years ago

Ok, I think I pinpointed the issue. The browsing tries to parse from this IPV6, which for some reason is invalid or unavailable.

Do you have any idea of which device in your network is using this IPV6? I ask because I need to replicate the issue.

EDIT: Can you launch this command while root?

sysctl net.ipv6.conf.all.disable_ipv6=0 killall node

does the issue still happen?

xipmix commented 6 years ago

On Tue, Dec 19, 2017 at 01:53:40PM +0000, Volumio wrote:

Do you have any idea of which device in your network is using this IPV6? I ask because I need to replicate the issue.

Nothing that I explicitly configured that way, but there are boxes that configure link-local by default. I will check against the address in the log.

-- You are receiving this because you were mentioned. Reply to this email directly or view it on GitHub: https://github.com/volumio/Volumio2/issues/1419#issuecomment-352757562

--

xipmix commented 6 years ago

I have a mythtv box and I found it is running some kind of dlna service on that link-local address at port 6544. From a separate machine with ipv6 enabled I can ping6 that address.

I can't ping6 it from volumio, because eth0 has no v6 address set up.

I had a;ready tried enabling v6 by commenting out the disable lines in /etc/sysctl.conf and rebooting, but it did not seem to help. I tried that again. It allowed me to ping6 the offending address

$ sudo ping6 -I eth0 fe80::21c:c0ff:fe22:1d46
64 bytes from fe80::21c:c0ff:fe22:1d46: icmp_seq=1 ttl=64 time=8.05 ms
64 bytes from fe80::21c:c0ff:fe22:1d46: icmp_seq=2 ttl=64 time=4.55 ms

but the failures continue, the same as above.

If I prevent the ipv6 module from being loaded in volumio (this might help you reproduce?)

# cat >/etc/modprobe.d/ipv6.conf
blacklist ipv6
alias net-pf-10 off
alias ipv6 off
^D
# reboot

then I get different failures, like this

Dec 20 00:08:15 volumio volumio[3129]: Volumio Calling Home
Dec 20 00:08:15 volumio volumio[3129]: info: [1513728495807] CoreStateMachine::resetVolumioState
Dec 20 00:08:15 volumio volumio[3129]: info: [1513728495811] CoreStateMachine::getcurrentVolume
Dec 20 00:08:15 volumio volumio[3129]: info: CoreCommandRouter::volumioRetrievevolume
Dec 20 00:08:15 volumio volumio[3129]: info: [1513728495846] CoreStateMachine::updateTrackBlock
Dec 20 00:08:15 volumio volumio[3129]: info: [1513728495850] CorePlayQueue::getTrackBlock
Dec 20 00:08:15 volumio volumio[3129]: info: Cannot read play queue from file
Dec 20 00:08:16 volumio volumio[3129]: events.js:160
Dec 20 00:08:16 volumio volumio[3129]: throw er; // Unhandled 'error' event
Dec 20 00:08:16 volumio volumio[3129]: ^
Dec 20 00:08:16 volumio volumio[3129]: Error: connect EAFNOSUPPORT fe80::21c:c0ff:fe22:1d46:6544 - Local (undefined:undefined)
Dec 20 00:08:16 volumio volumio[3129]: at Object.exports._errnoException (util.js:1018:11)
Dec 20 00:08:16 volumio volumio[3129]: at exports._exceptionWithHostPort (util.js:1041:20)
Dec 20 00:08:16 volumio volumio[3129]: at connect (net.js:880:16)
Dec 20 00:08:16 volumio volumio[3129]: at net.js:969:9
Dec 20 00:08:16 volumio volumio[3129]: at _combinedTickCallback (internal/process/next_tick.js:73:7)
Dec 20 00:08:16 volumio volumio[3129]: at process._tickCallback (internal/process/next_tick.js:104:9)
Dec 20 00:08:16 volumio volumio-remote-updater[641]: [2017-12-20 00:08:16] [info] asio async_read_at_least error: system:104 (Connection reset by peer)
Dec 20 00:08:16 volumio volumio-remote-updater[641]: [2017-12-20 00:08:16] [error] handle_read_http_response error: websocketpp.transport:2 (Underlying Transport Error)
Dec 20 00:08:16 volumio volumio-remote-updater[641]: [2017-12-20 00:08:16] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected)
Dec 20 00:08:16 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE

mythtv is configured to offer services only to localhost. I tried connecting to the myth box from an external machine on v4 (telnet myth 6544) but get connection refused, as expected. I could not work out how to try connecting over v6, telnet seems not to understand v6 addresses, even if I use the -6 argument and add the address to /etc/hosts.

Tried internally on the myth box and I see the listening state

$ netstat -an|grep 6544
tcp        0      0 127.0.0.1:6544          0.0.0.0:*               LISTEN     
tcp6       0      0 fe80::21c:c0ff:fe2:6544 :::*                    LISTEN     
tcp6       0      0 ::1:6544                :::*                    LISTEN

and can connect ok

$ telnet 127.0.0.1 6544
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
^]
telnet> quit
Connection closed.

but again can't figure out what to do for v6.

I disabled v6 on the myth box

$ sudo net.ipv6.conf.all.disable_ipv6=1

and confirmed I can no longer ping6 it from volumio. Then re-disable v6 in sysctl.conf and reboot volumio...and it still fails on the v6 address.

volumio commented 6 years ago

Good news, think I nailed it: http://updates.volumio.org/pi/volumio/2.346/volumio-2.346-2017-12-19-pi.img.zip

or do volumio pull

PS: Your error was really fundamental to understand a huge potential issue, thanks again (if its solved). To discover it I basically built an ipv6 dlna server that was acting like mythtv

xipmix commented 6 years ago

Tried the image. Much better. You seem to be catching the fatal error now.

Dec 20 01:26:17 volumio systemd[1328]: Starting Paths.
Dec 20 01:26:17 volumio systemd[1328]: Reached target Paths.
Dec 20 01:26:17 volumio systemd[1328]: Starting Timers.
Dec 20 01:26:17 volumio systemd[1328]: Reached target Timers.
Dec 20 01:26:17 volumio systemd[1328]: Starting Sockets.
Dec 20 01:26:17 volumio systemd[1328]: Reached target Sockets.
Dec 20 01:26:17 volumio systemd[1328]: Starting Basic System.
Dec 20 01:26:17 volumio systemd[1328]: Reached target Basic System.
Dec 20 01:26:17 volumio systemd[1328]: Starting Default.
Dec 20 01:26:17 volumio systemd[1328]: Reached target Default.
Dec 20 01:26:17 volumio systemd[1328]: Startup finished in 56ms.
Dec 20 01:26:17 volumio systemd[1]: Started User Manager for UID 1000.
Dec 20 01:26:22 volumio sudo[1377]: volumio : TTY=tty1 ; PWD=/home/volumio ; USER=root ; COMMAND=/bin/journalctl -f
Dec 20 01:26:22 volumio sudo[1377]: pam_unix(sudo:session): session opened for user root by volumio(uid=0)
Dec 20 01:27:34 volumio volumio[946]: error: error
Dec 20 01:27:34 volumio volumio[946]: error: error
Dec 20 01:27:34 volumio volumio[946]: error: error
Dec 20 01:27:34 volumio volumio[946]: error: error
Dec 20 01:27:34 volumio volumio[946]: error: error
Dec 20 01:27:34 volumio volumio[946]: error: error
Dec 20 01:27:35 volumio volumio[946]: error: error
Dec 20 01:27:35 volumio volumio[946]: error: error
Dec 20 01:28:24 volumio volumio[946]: error: error
Dec 20 01:28:24 volumio volumio[946]: error: error
Dec 20 01:28:24 volumio volumio[946]: error: error
Dec 20 01:28:24 volumio volumio[946]: error: error
Dec 20 01:28:25 volumio volumio[946]: error: error
Dec 20 01:28:25 volumio volumio[946]: error: error
Dec 20 01:28:26 volumio volumio[946]: error: error
Dec 20 01:28:26 volumio volumio[946]: error: error
volumio commented 6 years ago

Great to hear! Thanks a lot for your help on this, it was fundamental