Reboot when entering snapcast plugin settings

[heiderich]

I installed this plugin on volumio 2.376. When entering the settings page of the snapcast plugin, volumio seems to initiate a reboot and I cannot change anything anymore. Is this a known problem?

The output of sudo journalctl -f is:

Mar 13 18:09:58 volumio volumio[12496]: info: CoreCommandRouter::getUIConfigOnPlugin
Mar 13 18:09:58 volumio volumio[12496]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam
Mar 13 18:09:58 volumio volumio[12496]: info: Received Get System Version
Mar 13 18:09:58 volumio volumio[12496]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Mar 13 18:10:01 volumio volumio[12496]: info: [{"prettyName":"SnapCast","name":"snapcast","category":"miscellanea","version":"2.2.2","icon":"fa fa-podcast","enabled":true,"active":true}]
Mar 13 18:10:03 volumio volumio[12496]: info: CoreCommandRouter::getUIConfigOnPlugin
Mar 13 18:10:03 volumio volumio[12496]: info: Loaded the previous config.
Mar 13 18:10:03 volumio volumio[12496]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getDevices
Mar 13 18:10:03 volumio volumio[12496]: info: ## populating UI...
Mar 13 18:10:03 volumio volumio[12496]: info: 1/7 server settings loaded
Mar 13 18:10:03 volumio volumio[12496]: info: 2/7 client settings loaded
Mar 13 18:10:03 volumio volumio[12496]: info: 3/7 MPD settings loaded
Mar 13 18:10:03 volumio volumio[12496]: info: 4/7 asound settings loaded
Mar 13 18:10:03 volumio volumio[12496]: info: 5/7 spotify settings loaded
Mar 13 18:10:03 volumio volumio[12496]: info: 6/7 template settings loaded
Mar 13 18:10:03 volumio volumio[12496]: info: 7/7 environment settings loaded
Mar 13 18:10:03 volumio volumio[12496]: info: Populated config screen.
Mar 13 18:10:04 volumio volumio[12496]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Mar 13 18:10:04 volumio volumio[12496]: SyntaxError: Unexpected end of JSON input
Mar 13 18:10:04 volumio volumio[12496]: at Object.parse (native)
Mar 13 18:10:04 volumio volumio[12496]: at /data/plugins/miscellanea/snapcast/index.js:1085:25
Mar 13 18:10:04 volumio volumio[12496]: at Socket.<anonymous> (/data/plugins/miscellanea/snapcast/node_modules/json-socket/lib/json-socket.js:67:17)
Mar 13 18:10:04 volumio volumio[12496]: at emitOne (events.js:101:20)
Mar 13 18:10:04 volumio volumio[12496]: at Socket.emit (events.js:188:7)
Mar 13 18:10:04 volumio volumio[12496]: at readableAddChunk (_stream_readable.js:176:18)
Mar 13 18:10:04 volumio volumio[12496]: at Socket.Readable.push (_stream_readable.js:134:10)
Mar 13 18:10:04 volumio volumio[12496]: at TCP.onread (net.js:547:20)
Mar 13 18:10:04 volumio volumio[12496]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Mar 13 18:10:05 volumio sudo[12985]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2018-03-13 18:09
Mar 13 18:10:05 volumio sudo[12985]: pam_unix(sudo:session): session opened for user root by (uid=0)
Mar 13 18:10:05 volumio sudo[12985]: pam_unix(sudo:session): session closed for user root
Mar 13 18:10:06 volumio volumio-remote-updater[559]: [2018-03-13 18:10:06] [error] handle_read_frame error: websocketpp.transport:7 (End of File)
Mar 13 18:10:06 volumio volumio-remote-updater[559]: [2018-03-13 18:10:06] [disconnect] Disconnect close local:[1006,End of File] remote:[1006]
Mar 13 18:10:06 volumio systemd[1]: volumio.service: main process exited, code=exited, status=1/FAILURE
Mar 13 18:10:06 volumio systemd[1]: Unit volumio.service entered failed state.
Mar 13 18:10:06 volumio systemd[1]: Starting dynamicswap service...
Mar 13 18:10:06 volumio systemd[1]: Started dynamicswap service.
Mar 13 18:10:06 volumio systemd[1]: volumio.service holdoff time over, scheduling restart.
Mar 13 18:10:06 volumio systemd[1]: Starting dynamicswap service...
Mar 13 18:10:06 volumio systemd[1]: Started dynamicswap service.
Mar 13 18:10:06 volumio systemd[1]: Stopping Volumio Backend Module...
Mar 13 18:10:06 volumio systemd[1]: Starting Volumio Backend Module...
Mar 13 18:10:06 volumio systemd[1]: Started Volumio Backend Module.
Mar 13 18:10:10 volumio volumio[13007]: info: -------------------------------------------
Mar 13 18:10:10 volumio volumio[13007]: info: -----            Volumio2              ----
Mar 13 18:10:10 volumio volumio[13007]: info: -------------------------------------------
Mar 13 18:10:10 volumio volumio[13007]: info: -----          System startup          ----
Mar 13 18:10:10 volumio volumio[13007]: info: -------------------------------------------

[Saiyato]

Looks like a problem parsing the JSON response from the snapserver, have seen this before, just not when opening the config.

Updating to build 377 now and will test afterwards

[Saiyato]

Just updated and installed plugin, I'm getting all kinds of errors (expected ones, since my config is not okay), but no reboot:

Mar 13 20:12:44 volumioboss volumio[812]: info: ## populating UI...
Mar 13 20:12:44 volumioboss volumio[812]: info: 1/7 server settings loaded
Mar 13 20:12:44 volumioboss volumio[812]: info: 2/7 client settings loaded
Mar 13 20:12:44 volumioboss volumio[812]: info: 3/7 MPD settings loaded
Mar 13 20:12:44 volumioboss volumio[812]: info: 4/7 asound settings loaded
Mar 13 20:12:44 volumioboss volumio[812]: info: 5/7 spotify settings loaded
Mar 13 20:12:44 volumioboss volumio[812]: info: 6/7 template settings loaded
Mar 13 20:12:44 volumioboss volumio[812]: info: 7/7 environment settings loaded
Mar 13 20:12:44 volumioboss volumio[812]: info: Populated config screen.
Mar 13 20:12:45 volumioboss snapclient[3050]: Exception in Controller::worker(): connect: Connection refused
Mar 13 20:12:45 volumioboss snapclient[3050]: Error in socket shutdown: Transport endpoint is not connected
Mar 13 20:12:46 volumioboss snapclient[3050]: Exception in Controller::worker(): connect: Connection refused
Mar 13 20:12:46 volumioboss snapclient[3050]: Error in socket shutdown: Transport endpoint is not connected

[Saiyato]

Update, when configured correctly I'm getting the following (EOF error is because there has been no playback yet):

Mar 13 20:14:26 volumioboss volumio[812]: info: [{"prettyName":"Kodi Krypton","name":"kodi","category":"miscellanea","version":"2.2.11","icon":"fa fa-tv","enabled":false,"active":false},{"prettyName":"SnapCast","name":"snapcast","category":"miscellanea","version":"2.2.2","icon":"fa fa-podcast","enabled":true,"active":true}]
Mar 13 20:14:30 volumioboss volumio[812]: info: CoreCommandRouter::getUIConfigOnPlugin
Mar 13 20:14:30 volumioboss volumio[812]: info: Loaded the previous config.
Mar 13 20:14:30 volumioboss volumio[812]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getDevices
Mar 13 20:14:30 volumioboss snapserver[4113]: ControlServer::NewConnection: ::ffff:127.0.0.1
Mar 13 20:14:30 volumioboss volumio[812]: info: ## populating UI...
Mar 13 20:14:30 volumioboss volumio[812]: info: 1/7 server settings loaded
Mar 13 20:14:30 volumioboss volumio[812]: info: 2/7 client settings loaded
Mar 13 20:14:30 volumioboss volumio[812]: info: 3/7 MPD settings loaded
Mar 13 20:14:30 volumioboss volumio[812]: info: 4/7 asound settings loaded
Mar 13 20:14:30 volumioboss volumio[812]: info: 5/7 spotify settings loaded
Mar 13 20:14:30 volumioboss volumio[812]: info: 6/7 template settings loaded
Mar 13 20:14:30 volumioboss volumio[812]: info: 7/7 environment settings loaded
Mar 13 20:14:30 volumioboss volumio[812]: info: Populated config screen.
Mar 13 20:14:30 volumioboss snapserver[4113]: Exception in ControlSession::reader(): read_until: End of file
Mar 13 20:14:39 volumioboss volumio[812]: info: CALLMETHOD: miscellanea snapcast updateSnapServer [object Object]
Mar 13 20:14:39 volumioboss volumio[812]: info: CoreCommandRouter::executeOnPlugin: snapcast , updateSnapServer
Mar 13 20:14:39 volumioboss volumio[812]: info: Successfully updated snapserver configuration

Running on "System version: 2.377 Release: Tue Mar 13 17:56:48 CET 2018"

[heiderich]

I was mistaken. The box does not reboot, but the volumio service restarts.

Could you help to debug this?

[Saiyato]

I can't reproduce... can you update to 377 please?

Correction: 378 has been released.

[heiderich]

With version 2.378 this problems does not occur anymore.

[Saiyato]

Awesome! :)

I think Volumio solved it by using the crash reports.