Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

skiping titles needs exeption handling #1791

Open
kermitnc opened this issue Aug 11, 2019 · 1 comment
Open

skiping titles needs exeption handling #1791

kermitnc opened this issue Aug 11, 2019 · 1 comment

Comments

@kermitnc
Copy link

Using Volumio 2.599 on RPi 3B+ Volumio stop working after skipping a title goes wrong.
I patched the statemachine about the issue with negative play back timer (a different github PR). and now i describe the second trouble:
When a webradio channel is streaming for about >10min then the skipping of titles become a jeopardy: When the volumio.log state "info: Received update from a service different from the one supposed to be playing music. ..." then the following happens:

info: sending command...
2019-08-11T14:28:09.746Z - info: ------------------------------ 88ms
2019-08-11T14:28:09.752Z - info:
2019-08-11T14:28:09.753Z - info: ------------------------------ 57ms
2019-08-11T14:28:09.812Z - info:
---------------------------- MPD announces system playlist update
2019-08-11T14:28:09.814Z - info: Ignoring MPD Status Update
2019-08-11T14:28:09.815Z - info: parsing response...
2019-08-11T14:28:09.816Z - info: CoreStateMachine::setConsumeUpdateService mpd
2019-08-11T14:28:09.817Z - info: ControllerMpd::sendMpdCommand play
2019-08-11T14:28:09.819Z - info: sending command...
2019-08-11T14:28:09.822Z - info: ------------------------------ 10ms
2019-08-11T14:28:09.827Z - info: parsing response...
2019-08-11T14:28:10.965Z - info:
--- no Audio and the MPD get stuck. On tailing volumio.log you can see that the system is reacting on play, pause, prev, next... but MPD does nothing. ---Not Always---
Recovering from this state: service mpd restart (stopping takes very long 2-3min), Setting/playback some different buffer size e.g. 4MB --> 8MB (timeout upnp 1 min 20 s), reboot (1min).
Running this section without exception handling is careless.

A funny thing is in this case: When a webradio channel is after a tidal title in the playlist, then i always get negative playback timer and in 2-3 out of 4 cases, the player can recover. If not the player stops again (on the end the player does prefetching the next title regardless the source).
I uploaded the volumio.log on http://logs.volumio.org/volumio/Id6Jldy.html . With no skipping possible and negative play back timer issues.

@kermitnc
Copy link
Author

I did further analysis about this issue and the following happens, when skipping goes wrong:

---------------------------- MPD announces system playlist update
2019-08-17T19:34:58.032Z - info: Ignoring MPD Status Update
2019-08-17T19:34:58.033Z - info: parsing response...
2019-08-17T19:34:58.034Z - info: parsing response...
2019-08-17T19:34:58.034Z - info: ControllerMpd::parseState
2019-08-17T19:34:58.035Z - info: ControllerMpd::sendMpdCommand playlistinfo
2019-08-17T19:34:58.035Z - info: ControllerMpd::sendMpdCommand load "http://yp.shoutcast.com/sbin/tunein-station.m3u?id=500181"
2019-08-17T19:34:58.036Z - info: sending command...
2019-08-17T19:34:58.037Z - info: sending command...
2019-08-17T19:34:58.038Z - info:
2019-08-17T19:34:58.039Z - info: ------------------------------ 7ms
2019-08-17T19:34:58.039Z - info: parsing response...
2019-08-17T19:34:58.040Z - info: ControllerMpd::parseTrackInfo
2019-08-17T19:34:58.041Z - info: ControllerMpd::pushError
2019-08-17T19:34:58.046Z - info: message=Cannot read property 'split' of undefined, stack=TypeError: Cannot read property 'split' of undefined
at Promise._successFn (/volumio/app/plugins/music_service/mpd/index.js:291:54)
at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28)
at _combinedTickCallback (internal/process/next_tick.js:131:7)
at process._tickCallback (internal/process/next_tick.js:180:9)
2019-08-17T19:34:58.047Z - info: ------------------------------ 25ms

This causes also trouble to mpd:

2019-08-17T19:54:44.632Z - info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd

The Upnp client error comes about 5min40s later and sometimes the mpd restart with new connections to local.host.

2019-08-17T19:40:47.635Z - error: Upnp client error: Error: connect ETIMEDOUT 127.0.0.1:6600

When the mpd restarts, the volumio log shows

2019-08-17T19:51:32.929Z - error: Upnp client error: Error: read ECONNRESET
2019-08-17T19:51:32.930Z - error: MPD error: Error: read ECONNRESET

I also monitored the OS with top and the mpd process somewhat disappears from the list but service mpd status states a running mpd.

In this state the mpd service is not reachable:

2019-08-17T19:42:40.090Z - info: CoreCommandRouter::volumioPlay
2019-08-17T19:42:40.091Z - info: CoreStateMachine::play index undefined
2019-08-17T19:42:40.091Z - info: CoreStateMachine::setConsumeUpdateService undefined
2019-08-17T19:42:40.091Z - info: CorePlayQueue::getTrack 1
2019-08-17T19:42:40.092Z - info: CoreStateMachine::startPlaybackTimer
2019-08-17T19:42:40.092Z - info: CorePlayQueue::getTrack 1
2019-08-17T19:42:40.092Z - info: [1566070960092] ControllerWebradio::clearAddPlayTrack
2019-08-17T19:42:40.093Z - info: ControllerMpd::sendMpdCommand stop
2019-08-17T19:42:40.096Z - info: sending command...

Restarting the mpd service in this state takes about 2 min!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant