tcrass writes
Hi there,
first of all: thanks for this nice little program that — as you point out — allows for "using a single control application (UPnP-based) for everything"! I’m using it with mopidy on a raspi to play music served by mediatomb on the same machine; my control point software is BubbleUPnP on a tablet.
This used to work fine for some months, but after a recent upgrade playback ceased to work. The mopidy people helped me out fixing a version conflict I accidently introduced into the mopdy python dependencies, but now, even after completely re-installing wheezy on the pi, I can’t playback anything (https://discuss.mopidy.com/t/track-is-not-playable/871). Initially I suspected mopidy to be the culprit, but there’s one mopidy log entry (marked with **) that might point into the direction of upmpdcli:
...
DEBUG 2015-09-10 21:13:50,448 [1741:MpdSession-10] mopidy.mpd.session
Request from [::ffff:127.0.0.1]:47911: addtagid "0" "Artist" "Kraftwerk"
DEBUG 2015-09-10 21:13:50,462 [1741:MpdSession-10] mopidy.mpd.session
Response to [::ffff:127.0.0.1]:47911: ACK [0@0] {addtagid} Not implemented
DEBUG 2015-09-10 21:13:50,487 [1741:MpdSession-10] mopidy.internal.network
Client most likely disconnected. **********
INFO 2015-09-10 21:13:50,495 [1741:MpdSession-11] mopidy.mpd.session
New MPD connection from [::ffff:127.0.0.1]:47918
DEBUG 2015-09-10 21:13:50,508 [1741:MpdSession-11] mopidy.mpd.session
Request from [::ffff:127.0.0.1]:47918: status
DEBUG 2015-09-10 21:13:50,516 [1741:MpdSession-10] mopidy.internal.network
Already stopping: Actor is shutting down.
...I’m neither an expert in the MPD protocol, nor in mopidy’s architecture, but the fact that mopidy seems to think that some "client has disconnected" suggests to me that the problem might be related to some other software than mopidy (perhaps upmpdcli?).
Here’s what upmpdcli’s logs (at log level 6) while the mopidy problem occurs:
src/mpdcli.cxx:220::MPDCli::checkForCommand: addtagid
libupnpp/upnpplib.cxx:105::LibUPnP: serveronly 1 &hwaddr 0xbedb0b70 ifname [] inip [] port 0
libupnpp/upnpplib.cxx:144::LibUPnP: Using IP 192.168.0.19 port 49153
src/ohproduct.cxx:64::OHProduct::OHProduct: sources: <SourceList >
<Source >
<Name >Playlist</Name >
<Type >Playlist</Type >
<Visible >1</Visible >
</Source >
</SourceList >
src/mpdcli.cxx:461::MPDCli::consume:0
src/ohplaylist.cxx:105::ohPlaylist: cache restore done
src/upmpd.cxx:524::Entering event loop
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_CONTROL_ACTION_REQUEST
libupnpp/device/device.cxx:292::UPNP_CONTROL_ACTION_REQUEST: Characteristics. Params: <?xml version="1.0"? >
<u:Characteristics xmlns:u="urn:av-openhome-org:service:Volume:1" ></u:Characteristics >
src/ohvolume.cxx:108::OHVolume::charact.
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_CONTROL_ACTION_REQUEST
libupnpp/device/device.cxx:292::UPNP_CONTROL_ACTION_REQUEST: SourceXml. Params: <?xml version="1.0"? >
<u:SourceXml xmlns:u="urn:av-openhome-org:service:Product:1" ></u:SourceXml >
src/ohproduct.cxx:191::OHProduct::sourceXML
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_CONTROL_ACTION_REQUEST
libupnpp/device/device.cxx:292::UPNP_CONTROL_ACTION_REQUEST: Product. Params: <?xml version="1.0"? >
<u:Product xmlns:u="urn:av-openhome-org:service:Product:1" ></u:Product >
src/ohproduct.cxx:156::OHProduct::product
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_CONTROL_ACTION_REQUEST
libupnpp/device/device.cxx:292::UPNP_CONTROL_ACTION_REQUEST: ProtocolInfo. Params: <?xml version="1.0"? >
<u:ProtocolInfo xmlns:u="urn:av-openhome-org:service:Playlist:1" ></u:ProtocolInfo >
src/ohplaylist.cxx:715::OHPlaylist::protocolInfo
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:RenderingControl LastChange
src/avtransport.cxx:288::UpMpdAVTransport::getEventDataTransport: <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT_RCS" >
<InstanceID val="0" >
<RelativeCounterPosition val="0"/ >
<CurrentPlayMode val="NORMAL"/ >
<CurrentTrackDuration val="00:00:00"/ >
<RelativeTimePosition val="0:00:00"/ >
<NumberOfTracks val="1"/ >
<RecordStorageMedium val="NOT_IMPLEMENTED"/ >
<CurrentRecordQualityMode val="NOT_IMPLEMENTED"/ >
<PossiblePlaybackStorageMedia val="HDD,NETWORK"/ >
<RecordMediumWriteStatus val="NOT_IMPLEMENTED"/ >
<PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/ >
<TransportState val="STOPPED"/ >
<CurrentTransportActions val="Next,Previous,Play"/ >
<TransportStatus val="OK"/ >
<TransportPlaySpeed val="1"/ >
<PossibleRecordQualityModes val="NOT_IMPLEMENTED"/ >
<CurrentTrack val="1"/ >
<PlaybackStorageMedium val="NONE"/ >
<CurrentMediaDuration val="00:00:00"/ >
<AbsoluteTimePosition val="0:00:00"/ >
<AbsoluteCounterPosition val="0"/ >
</InstanceID >
</Event >
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:AVTransport LastChange
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Info DetailsCount
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Duration
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Volume VolumeMax
src/mpdcli.cxx:636::MPDCli::getQueueSongs: 0 songs
src/ohplaylist.cxx:144::OHPlaylist: current ids:
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Playlist IdArray
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_EVENT_SUBSCRIPTION_REQUEST
libupnpp/device/device.cxx:349::UPNP_EVENT_SUBSCRIPTION_REQUEST: urn:upnp-org:serviceId:RenderingControl
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_EVENT_SUBSCRIPTION_REQUEST
libupnpp/device/device.cxx:349::UPNP_EVENT_SUBSCRIPTION_REQUEST: urn:upnp-org:serviceId:AVTransport
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_EVENT_SUBSCRIPTION_REQUEST
libupnpp/device/device.cxx:349::UPNP_EVENT_SUBSCRIPTION_REQUEST: urn:upnp-org:serviceId:ConnectionManager
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_EVENT_SUBSCRIPTION_REQUEST
libupnpp/device/device.cxx:349::UPNP_EVENT_SUBSCRIPTION_REQUEST: urn:av-openhome-org:serviceId:Product
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_EVENT_SUBSCRIPTION_REQUEST
libupnpp/device/device.cxx:349::UPNP_EVENT_SUBSCRIPTION_REQUEST: urn:av-openhome-org:serviceId:Info
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_EVENT_SUBSCRIPTION_REQUEST
libupnpp/device/device.cxx:349::UPNP_EVENT_SUBSCRIPTION_REQUEST: urn:av-openhome-org:serviceId:Time
src/avtransport.cxx:288::UpMpdAVTransport::getEventDataTransport: <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT_RCS" >
<InstanceID val="0" >
<RelativeCounterPosition val="0"/ >
<CurrentPlayMode val="NORMAL"/ >
<CurrentTrackDuration val="00:00:00"/ >
<RelativeTimePosition val="0:00:00"/ >
<NumberOfTracks val="1"/ >
<RecordStorageMedium val="NOT_IMPLEMENTED"/ >
<CurrentRecordQualityMode val="NOT_IMPLEMENTED"/ >
<PossiblePlaybackStorageMedia val="HDD,NETWORK"/ >
<RecordMediumWriteStatus val="NOT_IMPLEMENTED"/ >
<PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/ >
<TransportState val="STOPPED"/ >
<CurrentTransportActions val="Next,Previous,Play"/ >
<TransportStatus val="OK"/ >
<TransportPlaySpeed val="1"/ >
<PossibleRecordQualityModes val="NOT_IMPLEMENTED"/ >
<CurrentTrack val="1"/ >
<PlaybackStorageMedium val="NONE"/ >
<CurrentMediaDuration val="00:00:00"/ >
<AbsoluteTimePosition val="0:00:00"/ >
<AbsoluteCounterPosition val="0"/ >
</InstanceID >
</Event >
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_CONTROL_ACTION_REQUEST
libupnpp/device/device.cxx:292::UPNP_CONTROL_ACTION_REQUEST: SourceIndex. Params: <?xml version="1.0"? >
<u:SourceIndex xmlns:u="urn:av-openhome-org:service:Product:1" ></u:SourceIndex >
src/ohproduct.cxx:198::OHProduct::sourceIndex
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_EVENT_SUBSCRIPTION_REQUEST
libupnpp/device/device.cxx:349::UPNP_EVENT_SUBSCRIPTION_REQUEST: urn:av-openhome-org:serviceId:Playlist
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_EVENT_SUBSCRIPTION_REQUEST
libupnpp/device/device.cxx:349::UPNP_EVENT_SUBSCRIPTION_REQUEST: urn:av-openhome-org:serviceId:Info
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_EVENT_SUBSCRIPTION_REQUEST
libupnpp/device/device.cxx:349::UPNP_EVENT_SUBSCRIPTION_REQUEST: urn:av-openhome-org:serviceId:Product
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_EVENT_SUBSCRIPTION_REQUEST
libupnpp/device/device.cxx:349::UPNP_EVENT_SUBSCRIPTION_REQUEST: urn:av-openhome-org:serviceId:Volume
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:RenderingControl LastChange
src/avtransport.cxx:288::UpMpdAVTransport::getEventDataTransport: <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT_RCS" >
<InstanceID val="0" >
<RelativeCounterPosition val="0"/ >
<CurrentPlayMode val="NORMAL"/ >
<CurrentTrackDuration val="00:00:00"/ >
<RelativeTimePosition val="0:00:00"/ >
<NumberOfTracks val="1"/ >
<RecordStorageMedium val="NOT_IMPLEMENTED"/ >
<CurrentRecordQualityMode val="NOT_IMPLEMENTED"/ >
<PossiblePlaybackStorageMedia val="HDD,NETWORK"/ >
<RecordMediumWriteStatus val="NOT_IMPLEMENTED"/ >
<PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/ >
<TransportState val="STOPPED"/ >
<CurrentTransportActions val="Next,Previous,Play"/ >
<TransportStatus val="OK"/ >
<TransportPlaySpeed val="1"/ >
<PossibleRecordQualityModes val="NOT_IMPLEMENTED"/ >
<CurrentTrack val="1"/ >
<PlaybackStorageMedium val="NONE"/ >
<CurrentMediaDuration val="00:00:00"/ >
<AbsoluteTimePosition val="0:00:00"/ >
<AbsoluteCounterPosition val="0"/ >
</InstanceID >
</Event >
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:AVTransport LastChange
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:ConnectionManager SinkProtocolInfo
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Product ManufacturerName
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Info DetailsCount
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Seconds
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Volume VolumeMilliDbPerSteps
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Playlist IdArray
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:RenderingControl LastChange
src/avtransport.cxx:288::UpMpdAVTransport::getEventDataTransport: <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT_RCS" >
<InstanceID val="0" >
<RelativeCounterPosition val="0"/ >
<CurrentPlayMode val="NORMAL"/ >
<CurrentTrackDuration val="00:00:00"/ >
<RelativeTimePosition val="0:00:00"/ >
<NumberOfTracks val="1"/ >
<RecordStorageMedium val="NOT_IMPLEMENTED"/ >
<CurrentRecordQualityMode val="NOT_IMPLEMENTED"/ >
<PossiblePlaybackStorageMedia val="HDD,NETWORK"/ >
<RecordMediumWriteStatus val="NOT_IMPLEMENTED"/ >
<PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/ >
<TransportState val="STOPPED"/ >
<CurrentTransportActions val="Next,Previous,Play"/ >
<TransportStatus val="OK"/ >
<TransportPlaySpeed val="1"/ >
<PossibleRecordQualityModes val="NOT_IMPLEMENTED"/ >
<CurrentTrack val="1"/ >
<PlaybackStorageMedium val="NONE"/ >
<CurrentMediaDuration val="00:00:00"/ >
<AbsoluteTimePosition val="0:00:00"/ >
<AbsoluteCounterPosition val="0"/ >
</InstanceID >
</Event >
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:AVTransport LastChange
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:ConnectionManager SinkProtocolInfo
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Product ManufacturerName
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Info DetailsCount
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Seconds
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Volume VolumeMilliDbPerSteps
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Playlist IdArray
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_CONTROL_ACTION_REQUEST
libupnpp/device/device.cxx:292::UPNP_CONTROL_ACTION_REQUEST: DeleteAll. Params: <?xml version="1.0"? >
<u:DeleteAll xmlns:u="urn:av-openhome-org:service:Playlist:1" ></u:DeleteAll >
src/ohplaylist.cxx:635::OHPlaylist::deleteAll
src/mpdcli.cxx:574::MPDCli::clearQueue
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_CONTROL_ACTION_REQUEST
libupnpp/device/device.cxx:292::UPNP_CONTROL_ACTION_REQUEST: Insert. Params: <?xml version="1.0"? >
<u:Insert xmlns:u="urn:av-openhome-org:service:Playlist:1" >
<AfterId >0</AfterId >
<Uri >http://192.168.0.7:8200/MediaItems/114355.mp3</Uri >
<Metadata ><DIDL-Lite xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/" xmlns:sec="http://www.sec.co.kr/"><item id="64$0$2$7$6$13" parentID="64$0$2$7$6" restricted="1"><upnp:class>object.item.audioItem.musicTrack</upnp:class><dc:title>Trans Europa Express</dc:title><dc:creator>Kraftwerk</dc:creator><upnp:artist>Kraftwerk</upnp:artist><upnp:albumArtURI>http://192.168.0.7:8200/AlbumArt/430-114355.jpg</upnp:albumArtURI><upnp:albumArtURI dlna:profileID="JPEG_TN">http://192.168.0.7:8200/AlbumArt/430-114355.jpg</upnp:albumArtURI><upnp:genre>Elektronik &amp; Ambient</upnp:genre><dc:date>1977-01-01</dc:date><upnp:album>Trans Europa Express</upnp:album><upnp:originalTrackNumber>4</upnp:originalTrackNumber><ownerUdn>4d696e69-444c-164e-9d41-386077f0be55</ownerUdn><res protocolInfo="http-get:*:audio/mpeg:DLNA.ORG_PN=MP3;DLNA.ORG_OP=01;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=01700000000000000000000000000000" bitrate="128000" sampleFrequency="44100" nrAudioChannels="2" size="6343936" duration="0:06:36.000">http://192.168.0.7:8200/MediaItems/114355.mp3</res></item></DIDL-Lite></Metadata >
</u:Insert >
src/mpdcli.cxx:636::MPDCli::getQueueSongs: 0 songs
src/ohplaylist.cxx:144::OHPlaylist: current ids:
src/ohplaylist.cxx:570::OHPlaylist::insert
src/ohplaylist.cxx:579::OHPlaylist::insert: afterid 0 Uri http://192.168.0.7:8200/MediaItems/114355.mp3 Metadata <DIDL-Lite xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/" xmlns:sec="http://www.sec.co.kr/" ><item id="64$0$2$7$6$13" parentID="64$0$2$7$6" restricted="1" ><upnp:class >object.item.audioItem.musicTrack</upnp:class ><dc:title >Trans Europa Express</dc:title ><dc:creator >Kraftwerk</dc:creator ><upnp:artist >Kraftwerk</upnp:artist ><upnp:albumArtURI >http://192.168.0.7:8200/AlbumArt/430-114355.jpg</upnp:albumArtURI ><upnp:albumArtURI dlna:profileID="JPEG_TN" >http://192.168.0.7:8200/AlbumArt/430-114355.jpg</upnp:albumArtURI ><upnp:genre >Elektronik & Ambient</upnp:genre ><dc:date >1977-01-01</dc:date ><upnp:album >Trans Europa Express</upnp:album ><upnp:originalTrackNumber >4</upnp:originalTrackNumber ><ownerUdn >4d696e69-444c-164e-9d41-386077f0be55</ownerUdn ><res protocolInfo="http-get:*:audio/mpeg:DLNA.ORG_PN=MP3;DLNA.ORG_OP=01;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=01700000000000000000000000000000" bitrate="128000" sampleFrequency="44100" nrAudioChannels="2" size="6343936" duration="0:06:36.000" >http://192.168.0.7:8200/MediaItems/114355.mp3</res ></item ></DIDL-Lite >
src/mpdcli.cxx:540::MPDCli::insertAfterId: id 0 uri http://192.168.0.7:8200/MediaItems/114355.mp3
src/mpdcli.cxx:522::MPDCli::insert at :0 uri http://192.168.0.7:8200/MediaItems/114355.mp3
src/ohplaylist.cxx:585::OHPlaylist::insert: new id: 0
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_CONTROL_ACTION_REQUEST
libupnpp/device/device.cxx:292::UPNP_CONTROL_ACTION_REQUEST: SeekId. Params: <?xml version="1.0"? >
<u:SeekId xmlns:u="urn:av-openhome-org:service:Playlist:1" >
<Value >0</Value >
</u:SeekId >
src/mpdcli.cxx:636::MPDCli::getQueueSongs: 1 songs
src/ohplaylist.cxx:144::OHPlaylist: current ids: 0
src/ohplaylist.cxx:224::OHPlaylist::makeIdArray: saving metacache
src/ohmetacache.cxx:128::dmcacheSave: got save task: 1 entries to /var/cache/upmpdcli//metacache
src/ohplaylist.cxx:417::OHPlaylist::seekId
src/mpdcli.cxx:408::MPDCli::playId(id=0)
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:RenderingControl LastChange
src/avtransport.cxx:288::UpMpdAVTransport::getEventDataTransport: <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT_RCS" >
<InstanceID val="0" >
<RelativeCounterPosition val="0"/ >
<CurrentPlayMode val="NORMAL"/ >
<CurrentTrackDuration val="00:00:00"/ >
<RelativeTimePosition val="0:00:00"/ >
<NumberOfTracks val="1"/ >
<RecordStorageMedium val="NOT_IMPLEMENTED"/ >
<CurrentRecordQualityMode val="NOT_IMPLEMENTED"/ >
<PossiblePlaybackStorageMedia val="HDD,NETWORK"/ >
<RecordMediumWriteStatus val="NOT_IMPLEMENTED"/ >
<PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/ >
<TransportState val="STOPPED"/ >
<CurrentTransportActions val="Next,Previous,Play"/ >
<TransportStatus val="OK"/ >
<TransportPlaySpeed val="1"/ >
<PossibleRecordQualityModes val="NOT_IMPLEMENTED"/ >
<CurrentTrack val="1"/ >
<PlaybackStorageMedium val="NONE"/ >
<CurrentMediaDuration val="00:00:00"/ >
<AbsoluteTimePosition val="0:00:00"/ >
<AbsoluteCounterPosition val="0"/ >
</InstanceID >
</Event >
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:AVTransport LastChange
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:ConnectionManager SinkProtocolInfo
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Product ManufacturerName
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Info DetailsCount
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Seconds
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Volume VolumeMilliDbPerSteps
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Playlist IdArray
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:RenderingControl LastChange
src/avtransport.cxx:288::UpMpdAVTransport::getEventDataTransport: <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT_RCS" >
<InstanceID val="0" >
<RelativeCounterPosition val="0"/ >
<CurrentPlayMode val="NORMAL"/ >
<CurrentTrackDuration val="00:00:00"/ >
<RelativeTimePosition val="0:00:00"/ >
<NumberOfTracks val="1"/ >
<RecordStorageMedium val="NOT_IMPLEMENTED"/ >
<CurrentRecordQualityMode val="NOT_IMPLEMENTED"/ >
<PossiblePlaybackStorageMedia val="HDD,NETWORK"/ >
<RecordMediumWriteStatus val="NOT_IMPLEMENTED"/ >
<PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/ >
<TransportState val="STOPPED"/ >
<CurrentTransportActions val="Next,Previous,Play"/ >
<TransportStatus val="OK"/ >
<TransportPlaySpeed val="1"/ >
<PossibleRecordQualityModes val="NOT_IMPLEMENTED"/ >
<CurrentTrack val="1"/ >
<PlaybackStorageMedium val="NONE"/ >
<CurrentMediaDuration val="00:00:00"/ >
<AbsoluteTimePosition val="0:00:00"/ >
<AbsoluteCounterPosition val="0"/ >
</InstanceID >
</Event >
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:AVTransport LastChange
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:ConnectionManager SinkProtocolInfo
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Product ManufacturerName
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Info DetailsCount
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Seconds
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Volume VolumeMilliDbPerSteps
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Playlist IdArray
src/upmpd.cxx:179::Got sig
src/upmpd.cxx:527::Event loop returned
src/ohmetacache.cxx:123::dmcacheSaveWorker: can't get task from queueAny thoughts on this?
Best regards --
— Torsten
medoc92 writes
src/upmpd.cxx:179::Got sig
upmpdcli catches SIGTERM SIGINT and SIGQUIT (and nothing else as far as I know). So it would seem that something is sending it one of these signals, usually meant to ask the process to terminate (which it does).
You said in an email that upmpdcli was still alive, but is it the same process number ?
From the mopidy log we see that there are 2 localhost sessions near the end: 1741:MpdSession-10 which seems to disconnect, and 1741:MpdSession-11 which seems to appear.
This looks exactly like what would happen when running /etc/init.d/upmpdcli restart .
The only thing that’s a bit weird is why the log is not truncated, this normally happens when upmpdcli starts up. But I guess this may depend on how you were capturing it.
It’s difficult to be sure of what happens, but I’d try to look in this direction.
tcrass writes
Hi,
I must admit that the logs I provided might be a bit confusing. I did indeed (re)start upmpdcli after editing its config file in order to increase the log level, and I omitted the message saying that the log was truncated, assuming that this was just "tail" complaining that the log, well, was truncated.
Here are new logs, documenting the following procedure:
sudo service mopidy start
sudo service upmpdcli start
[selecting the pi as renderer using Bubble]
[trying to play a track served from my desktop computer via minidlna]
sudo service upmpdcli stop
sudo service mopidy stopFirst mopidy’s log:
2015-09-13 20:56:39,821 INFO [3444:MainThread] mopidy.__main__: Starting Mopidy 1.1.0
2015-09-13 20:56:39,948 DEBUG [3444:MainThread] mopidy.ext: Loading entry point: mpd = mopidy.mpd:Extension
2015-09-13 20:56:39,955 DEBUG [3444:MainThread] mopidy.ext: Loaded extension: Mopidy-MPD 1.1.0
2015-09-13 20:56:39,959 DEBUG [3444:MainThread] mopidy.ext: Loading entry point: http = mopidy.http:Extension
2015-09-13 20:56:39,967 DEBUG [3444:MainThread] mopidy.ext: Loaded extension: Mopidy-HTTP 1.1.0
2015-09-13 20:56:39,968 DEBUG [3444:MainThread] mopidy.ext: Loading entry point: stream = mopidy.stream:Extension
2015-09-13 20:56:39,973 DEBUG [3444:MainThread] mopidy.ext: Loaded extension: Mopidy-Stream 1.1.0
2015-09-13 20:56:39,973 DEBUG [3444:MainThread] mopidy.ext: Loading entry point: m3u = mopidy.m3u:Extension
2015-09-13 20:56:39,981 DEBUG [3444:MainThread] mopidy.ext: Loaded extension: Mopidy-M3U 1.1.0
2015-09-13 20:56:39,982 DEBUG [3444:MainThread] mopidy.ext: Loading entry point: softwaremixer = mopidy.softwaremixer:Extension
2015-09-13 20:56:39,988 DEBUG [3444:MainThread] mopidy.ext: Loaded extension: Mopidy-SoftwareMixer 1.1.0
2015-09-13 20:56:39,988 DEBUG [3444:MainThread] mopidy.ext: Loading entry point: file = mopidy.file:Extension
2015-09-13 20:56:39,994 DEBUG [3444:MainThread] mopidy.ext: Loaded extension: Mopidy-File 1.1.0
2015-09-13 20:56:39,995 DEBUG [3444:MainThread] mopidy.ext: Loading entry point: local = mopidy.local:Extension
2015-09-13 20:56:40,037 DEBUG [3444:MainThread] mopidy.ext: Loaded extension: Mopidy-Local 1.1.0
2015-09-13 20:56:40,040 DEBUG [3444:MainThread] mopidy.ext: Discovered extensions: mpd, http, stream, m3u, softwaremixer, file, local
2015-09-13 20:56:40,088 DEBUG [3444:MainThread] mopidy.config.keyring: Fetching passwords from your keyring failed. Any passwords stored in the keyring will not be available. (org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11)
2015-09-13 20:56:40,092 INFO [3444:MainThread] mopidy.config: Loading config from builtin defaults
2015-09-13 20:56:40,141 INFO [3444:MainThread] mopidy.config: Loading config from /etc/mopidy/mopidy.conf
2015-09-13 20:56:40,168 INFO [3444:MainThread] mopidy.config: Loading config from command line options
2015-09-13 20:56:40,316 DEBUG [3444:MainThread] mopidy.ext: Validating extension: mpd
2015-09-13 20:56:40,324 DEBUG [3444:MainThread] mopidy.ext: Validating extension: http
2015-09-13 20:56:40,657 DEBUG [3444:MainThread] mopidy.ext: Validating extension: stream
2015-09-13 20:56:40,665 DEBUG [3444:MainThread] mopidy.ext: Validating extension: m3u
2015-09-13 20:56:40,673 DEBUG [3444:MainThread] mopidy.ext: Validating extension: softwaremixer
2015-09-13 20:56:40,680 DEBUG [3444:MainThread] mopidy.ext: Validating extension: file
2015-09-13 20:56:40,688 DEBUG [3444:MainThread] mopidy.ext: Validating extension: local
2015-09-13 20:56:40,696 INFO [3444:MainThread] mopidy.__main__: Enabled extensions: mpd, http, stream, m3u, softwaremixer, file, local
2015-09-13 20:56:40,700 INFO [3444:MainThread] mopidy.__main__: Disabled extensions: none
2015-09-13 20:56:42,074 DEBUG [3444:MainThread] mopidy.commands: Available Mopidy mixers: SoftwareMixer
2015-09-13 20:56:42,078 INFO [3444:MainThread] mopidy.commands: Starting Mopidy mixer: SoftwareMixer
2015-09-13 20:56:42,088 DEBUG [3444:MainThread] pykka: Registered SoftwareMixer (urn:uuid:fcab7949-63c6-49d9-8178-3e7933710f24)
2015-09-13 20:56:42,094 DEBUG [3444:MainThread] pykka: Starting SoftwareMixer (urn:uuid:fcab7949-63c6-49d9-8178-3e7933710f24)
2015-09-13 20:56:42,116 DEBUG [3444:MainThread] mopidy.commands: Mixer volume left unchanged
2015-09-13 20:56:42,120 INFO [3444:MainThread] mopidy.commands: Starting Mopidy audio
2015-09-13 20:56:42,135 DEBUG [3444:MainThread] pykka: Registered Audio (urn:uuid:3f2bf046-18e2-403f-8af5-4f142f617834)
2015-09-13 20:56:42,140 DEBUG [3444:MainThread] pykka: Starting Audio (urn:uuid:3f2bf046-18e2-403f-8af5-4f142f617834)
2015-09-13 20:56:42,177 INFO [3444:MainThread] mopidy.commands: Starting Mopidy backends: StreamBackend, M3UBackend, FileBackend, LocalBackend
2015-09-13 20:56:42,232 DEBUG [3444:MainThread] pykka: Registered StreamBackend (urn:uuid:e111cf17-b6a9-40ff-b92a-ab8593e3e2af)
2015-09-13 20:56:42,246 DEBUG [3444:MainThread] pykka: Starting StreamBackend (urn:uuid:e111cf17-b6a9-40ff-b92a-ab8593e3e2af)
2015-09-13 20:56:42,331 INFO [3444:Audio-2] mopidy.audio.actor: Audio output set to "autoaudiosink"
2015-09-13 20:56:42,353 INFO [3444:MainThread] mopidy.m3u.playlists: Loaded 0 M3U playlists from /var/lib/mopidy/playlists
2015-09-13 20:56:42,372 DEBUG [3444:MainThread] pykka: Registered M3UBackend (urn:uuid:c979ca1e-8592-46fb-8fd7-d7ece020a966)
2015-09-13 20:56:42,375 DEBUG [3444:MainThread] pykka: Starting M3UBackend (urn:uuid:c979ca1e-8592-46fb-8fd7-d7ece020a966)
2015-09-13 20:56:42,423 WARNING [3444:MainThread] mopidy.file.library: Failed expanding path ($XDG_MUSIC_DIR) fromfile/media_dirs config value.
2015-09-13 20:56:42,452 DEBUG [3444:MainThread] pykka: Registered FileBackend (urn:uuid:dfec6f75-f8db-4d87-8cdd-2e8f1c0ae1f8)
2015-09-13 20:56:42,459 DEBUG [3444:MainThread] pykka: Starting FileBackend (urn:uuid:dfec6f75-f8db-4d87-8cdd-2e8f1c0ae1f8)
2015-09-13 20:56:42,557 DEBUG [3444:MainThread] mopidy.local.actor: Using json as the local library
2015-09-13 20:56:42,563 DEBUG [3444:MainThread] mopidy.local.json: Loading library: /var/lib/mopidy/local/library.json.gz
2015-09-13 20:56:42,568 INFO [3444:MainThread] mopidy.local.json: No local library metadata cache found at /var/lib/mopidy/local/library.json.gz. Please run `mopidy local scan` to index your local music library. If you do not have a local music collection, you can disable the local backend to hide this message.
2015-09-13 20:56:42,577 INFO [3444:MainThread] mopidy.local.library: Loaded 0 local tracks using json
2015-09-13 20:56:42,581 DEBUG [3444:MainThread] pykka: Registered LocalBackend (urn:uuid:973f39aa-9b04-493c-a149-1f9f7b375394)
2015-09-13 20:56:42,586 DEBUG [3444:MainThread] pykka: Starting LocalBackend (urn:uuid:973f39aa-9b04-493c-a149-1f9f7b375394)
2015-09-13 20:56:42,647 INFO [3444:MainThread] mopidy.commands: Starting Mopidy core
2015-09-13 20:56:42,710 DEBUG [3444:MainThread] pykka: Registered Core (urn:uuid:8cd7adf5-fb7f-43d1-ab42-3263735e35fe)
2015-09-13 20:56:42,714 DEBUG [3444:MainThread] pykka: Starting Core (urn:uuid:8cd7adf5-fb7f-43d1-ab42-3263735e35fe)
2015-09-13 20:56:42,893 INFO [3444:MainThread] mopidy.commands: Starting Mopidy frontends: MpdFrontend, HttpFrontend
2015-09-13 20:56:43,008 INFO [3444:MainThread] mopidy.mpd.actor: MPD server running at [::ffff:127.0.0.1]:6600
2015-09-13 20:56:43,014 DEBUG [3444:MainThread] pykka: Registered MpdFrontend (urn:uuid:e5a478ea-4a0f-43b6-a4bc-c6fbdcd7521b)
2015-09-13 20:56:43,021 DEBUG [3444:MainThread] pykka: Starting MpdFrontend (urn:uuid:e5a478ea-4a0f-43b6-a4bc-c6fbdcd7521b)
2015-09-13 20:56:43,035 DEBUG [3444:MainThread] mopidy.http.actor: Starting HTTP server
2015-09-13 20:56:43,051 DEBUG [3444:MainThread] pykka: Registered HttpFrontend (urn:uuid:4fd4b967-5504-4cff-b7ba-6e1d35e8647f)
2015-09-13 20:56:43,065 DEBUG [3444:MainThread] pykka: Starting HttpFrontend (urn:uuid:4fd4b967-5504-4cff-b7ba-6e1d35e8647f)
2015-09-13 20:56:43,087 INFO [3444:HttpFrontend-10] mopidy.http.actor: HTTP server running at [::ffff:192.168.0.19]:6680
2015-09-13 20:56:43,108 DEBUG [3444:HttpServer] mopidy.http.actor: Loaded HTTP extension: mopidy
2015-09-13 20:56:43,128 DEBUG [3444:HttpServer] mopidy.http.actor: HTTP routes from extensions:
u'/mopidy': <class 'mopidy.http.handlers.AddSlashHandler' >
u'/mopidy/ws/?': <class 'mopidy.http.handlers.WebSocketHandler' >
u'/mopidy/rpc': <class 'mopidy.http.handlers.JsonRpcHandler' >
u'/mopidy/(.+)': <class 'mopidy.http.handlers.StaticFileHandler' >
u'/mopidy/': <class 'mopidy.http.handlers.ClientListHandler' >
u'/': <class 'tornado.web.RedirectHandler' >
2015-09-13 20:56:43,253 DEBUG [3444:MpdFrontend-8] mopidy.zeroconf: Zeroconf service _mpd._tcp at [lyra.local]:6600: Published
2015-09-13 20:56:43,286 DEBUG [3444:HttpFrontend-10] mopidy.zeroconf: Zeroconf service _http._tcp at [lyra.local]:6680: Published
2015-09-13 20:56:43,364 DEBUG [3444:HttpFrontend-10] mopidy.zeroconf: Zeroconf service _mopidy-http._tcp at [lyra.local]:6680: Published
2015-09-13 20:56:52,663 DEBUG [3444:MainThread] pykka: Registered MpdSession (urn:uuid:c5090035-08c0-4b32-b05a-bd2f5608004c)
2015-09-13 20:56:52,667 DEBUG [3444:MainThread] pykka: Starting MpdSession (urn:uuid:c5090035-08c0-4b32-b05a-bd2f5608004c)
2015-09-13 20:56:52,676 INFO [3444:MpdSession-11] mopidy.mpd.session: New MPD connection from [::ffff:127.0.0.1]:36029
2015-09-13 20:56:52,689 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36029: commands
2015-09-13 20:56:52,705 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36029:
command: add
command: addid
command: addtagid
command: channels
command: clear
command: clearerror
command: cleartagid
command: close
command: commands
command: consume
command: count
command: crossfade
command: currentsong
command: decoders
command: delete
command: deleteid
command: disableoutput
command: enableoutput
command: find
command: findadd
command: list
command: listall
command: listallinfo
command: listfiles
command: listmounts
command: listneighbors
command: listplaylist
command: listplaylistinfo
command: listplaylists
command: load
command: lsinfo
command: mixrampdb
command: mixrampdelay
command: mount
command: move
command: moveid
command: next
command: notcommands
command: outputs
command: password
command: pause
command: ping
command: play
command: playid
command: playlist
command: playlistadd
command: playlistclear
command: playlistdelete
command: playlistfind
command: playlistid
command: playlistinfo
command: playlistmove
command: playlistsearch
command: plchanges
command: plchangesposid
command: previous
command: prio
command: prioid
command: random
command: rangeid
command: readmessages
command: rename
command: repeat
command: replay_gain_mode
command: replay_gain_status
command: rescan
command: rm
command: save
command: search
command: searchadd
command: searchaddpl
command: seek
command: seekcur
command: seekid
command: sendmessage
command: setvol
command: shuffle
command: single
command: stats
command: status
command: stop
command: subscribe
command: swap
command: swapid
command: tagtypes
command: toggleoutput
command: unmount
command: unsubscribe
command: update
command: urlhandlers
OK
2015-09-13 20:56:52,716 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36029: status
2015-09-13 20:56:53,253 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36029:
volume: 100
repeat: 0
random: 0
single: 0
consume: 0
playlist: 0
playlistlength: 0
xfade: 0
state: stop
OK
2015-09-13 20:56:53,290 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36029: consume "0"
2015-09-13 20:56:53,301 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36029: OK
2015-09-13 20:56:54,495 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36029: status
2015-09-13 20:56:54,550 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36029:
volume: 100
repeat: 0
random: 0
single: 0
consume: 0
playlist: 0
playlistlength: 0
xfade: 0
state: stop
OK
2015-09-13 20:56:54,562 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36029: status
2015-09-13 20:56:54,610 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36029:
volume: 100
repeat: 0
random: 0
single: 0
consume: 0
playlist: 0
playlistlength: 0
xfade: 0
state: stop
OK
2015-09-13 20:56:54,634 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36029: playlistinfo
2015-09-13 20:56:54,644 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36029: OK
2015-09-13 20:56:55,657 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36029: status
2015-09-13 20:56:55,702 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36029:
volume: 100
repeat: 0
random: 0
single: 0
consume: 0
playlist: 0
playlistlength: 0
xfade: 0
state: stop
OK
2015-09-13 20:56:55,710 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36029: status
2015-09-13 20:56:55,759 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36029:
volume: 100
repeat: 0
random: 0
single: 0
consume: 0
playlist: 0
playlistlength: 0
xfade: 0
state: stop
OK
[...]
2015-09-13 20:57:13,693 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36029:
volume: 100
repeat: 0
random: 0
single: 0
consume: 0
playlist: 0
playlistlength: 0
xfade: 0
state: stop
OK
2015-09-13 20:57:14,674 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36029: clear
2015-09-13 20:57:14,687 DEBUG [3444:Core-7] mopidy.core.tracklist: Triggering event: tracklist_changed()
2015-09-13 20:57:14,693 DEBUG [3444:MainThread] mopidy.listener: Sending tracklist_changed to CoreListener: {}
2015-09-13 20:57:14,698 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36029: OK
2015-09-13 20:57:14,719 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36029: status
2015-09-13 20:57:14,774 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36029:
volume: 100
repeat: 0
random: 0
single: 0
consume: 0
playlist: 1
playlistlength: 0
xfade: 0
state: stop
OK
2015-09-13 20:57:14,803 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36029: status
2015-09-13 20:57:14,857 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36029:
volume: 100
repeat: 0
random: 0
single: 0
consume: 0
playlist: 1
playlistlength: 0
xfade: 0
state: stop
OK
2015-09-13 20:57:14,870 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36029: playlistinfo
2015-09-13 20:57:14,879 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36029: OK
2015-09-13 20:57:14,899 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36029: addid "http://192.168.0.7:8200/MediaItems/114355.mp3" "0"
2015-09-13 20:57:15,731 DEBUG [3444:Core-7] mopidy.core.tracklist: Triggering event: tracklist_changed()
2015-09-13 20:57:15,737 DEBUG [3444:MainThread] mopidy.listener: Sending tracklist_changed to CoreListener: {}
2015-09-13 20:57:15,741 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36029:
Id: 0
OK
2015-09-13 20:57:15,761 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36029: addtagid "0" "Artist" "Kraftwerk"
2015-09-13 20:57:15,780 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36029: ACK [0@0] {addtagid} Not implemented
2015-09-13 20:57:15,798 DEBUG [3444:MainThread] pykka: Registered MpdSession (urn:uuid:1d1dcbc4-83e9-48e2-ad2c-57378a68d8bd)
2015-09-13 20:57:15,802 DEBUG [3444:MainThread] pykka: Starting MpdSession (urn:uuid:1d1dcbc4-83e9-48e2-ad2c-57378a68d8bd)
2015-09-13 20:57:15,816 DEBUG [3444:MpdSession-11] mopidy.internal.network: Client most likely disconnected.
2015-09-13 20:57:15,833 DEBUG [3444:MpdSession-11] pykka: Unregistered MpdSession (urn:uuid:c5090035-08c0-4b32-b05a-bd2f5608004c)
2015-09-13 20:57:15,826 INFO [3444:MpdSession-12] mopidy.mpd.session: New MPD connection from [::ffff:127.0.0.1]:36040
2015-09-13 20:57:15,845 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36040: status
2015-09-13 20:57:15,847 DEBUG [3444:MpdSession-11] pykka: Stopped MpdSession (urn:uuid:c5090035-08c0-4b32-b05a-bd2f5608004c)
2015-09-13 20:57:15,855 DEBUG [3444:MpdSession-11] mopidy.internal.network: Already stopping: Actor is shutting down.
2015-09-13 20:57:15,922 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36040:
volume: 100
repeat: 0
random: 0
single: 0
consume: 0
playlist: 2
playlistlength: 1
xfade: 0
state: stop
OK
2015-09-13 20:57:15,934 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36040: status
2015-09-13 20:57:15,986 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36040:
volume: 100
repeat: 0
random: 0
single: 0
consume: 0
playlist: 2
playlistlength: 1
xfade: 0
state: stop
OK
2015-09-13 20:57:15,997 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36040: status
2015-09-13 20:57:16,047 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36040:
volume: 100
repeat: 0
random: 0
single: 0
consume: 0
playlist: 2
playlistlength: 1
xfade: 0
state: stop
OK
2015-09-13 20:57:16,095 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36040: playid "0"
2015-09-13 20:57:16,122 DEBUG [3444:Core-7] mopidy.core.playback: Changing state: stopped - > playing
2015-09-13 20:57:16,126 DEBUG [3444:Core-7] mopidy.core.playback: Triggering playback state change event
2015-09-13 20:57:16,138 DEBUG [3444:MainThread] mopidy.listener: Sending playback_state_changed to CoreListener: {'old_state': u'stopped', 'new_state': u'playing'}
2015-09-13 20:57:16,211 DEBUG [3444:Audio-2] mopidy.audio.gst: State change to GST_STATE_READY: result=GST_STATE_CHANGE_SUCCESS
2015-09-13 20:57:16,235 DEBUG [3444:MainThread] mopidy.audio.gst: Got state-changed message: old=GST_STATE_NULL new=GST_STATE_READY pending=GST_STATE_VOID_PENDING
2015-09-13 20:57:16,636 INFO [3444:StreamBackend-3] urllib3.connectionpool: Starting new HTTP connection (1): 192.168.0.7
2015-09-13 20:57:16,651 DEBUG [3444:StreamBackend-3] urllib3.connectionpool: Setting read timeout to <object object at 0xb6d5a5d8 >
2015-09-13 20:57:16,663 DEBUG [3444:StreamBackend-3] urllib3.connectionpool: "GET /MediaItems/114355.mp3 HTTP/1.1" 200 6343936
2015-09-13 20:57:20,749 DEBUG [3444:StreamBackend-3] mopidy.backend: Backend translated URI from http://192.168.0.7:8200/MediaItems/114355.mp3 to None
2015-09-13 20:57:20,755 WARNING [3444:Core-7] mopidy.core.tracklist: Track is not playable: http://192.168.0.7:8200/MediaItems/114355.mp3
2015-09-13 20:57:20,768 DEBUG [3444:Audio-2] mopidy.audio.actor: Position query failed
2015-09-13 20:57:20,785 DEBUG [3444:Audio-2] mopidy.audio.gst: State change to GST_STATE_NULL: result=GST_STATE_CHANGE_SUCCESS
2015-09-13 20:57:20,792 DEBUG [3444:Core-7] mopidy.core.playback: Changing state: playing - > stopped
2015-09-13 20:57:20,798 DEBUG [3444:Core-7] mopidy.core.playback: Triggering playback state change event
2015-09-13 20:57:20,804 DEBUG [3444:MainThread] mopidy.listener: Sending playback_state_changed to CoreListener: {'old_state': u'playing', 'new_state': u'stopped'}
2015-09-13 20:57:20,817 DEBUG [3444:Core-7] mopidy.core.playback: Triggering track playback ended event
2015-09-13 20:57:20,832 DEBUG [3444:MainThread] mopidy.listener: Sending track_playback_ended to CoreListener: {'time_position': 0, 'tl_track': TlTrack(tlid=0, track=Track(album=Album(artists=[Artist(name=u'Kraftwerk')], name=u'Trans Europa Express'), artists=[Artist(name=u'Kraftwerk')], bitrate=127739L, date='1977-01-01', genre=u'Elektronik & Ambient', length=396016L, name=u'Trans Europa Express', track_no=4L, uri='http://192.168.0.7:8200/MediaItems/114355.mp3'))}
2015-09-13 20:57:20,838 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36040: OK
2015-09-13 20:57:20,864 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36040: status
2015-09-13 20:57:20,914 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36040:
volume: 100
repeat: 0
random: 0
single: 0
consume: 0
playlist: 2
playlistlength: 1
xfade: 0
state: stop
OK
2015-09-13 20:57:20,936 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36040: playlistinfo
2015-09-13 20:57:20,951 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36040:
file: http://192.168.0.7:8200/MediaItems/114355.mp3
Time: 396
Artist: Kraftwerk
Album: Trans Europa Express
Title: Trans Europa Express
Date: 1977-01-01
Track: 4
Pos: 0
Id: 0
AlbumArtist: Kraftwerk
Genre: Elektronik & Ambient
OK
2015-09-13 20:57:21,976 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36040: status
2015-09-13 20:57:22,026 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36040:
volume: 100
repeat: 0
random: 0
single: 0
consume: 0
playlist: 2
playlistlength: 1
xfade: 0
state: stop
OK
2015-09-13 20:57:22,034 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36040: status
2015-09-13 20:57:22,091 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36040:
volume: 100
repeat: 0
random: 0
single: 0
consume: 0
playlist: 2
playlistlength: 1
xfade: 0
state: stop
OK
[...]
2015-09-13 20:57:37,675 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36040: status
2015-09-13 20:57:37,726 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36040:
volume: 100
repeat: 0
random: 0
single: 0
consume: 0
playlist: 2
playlistlength: 1
xfade: 0
state: stop
OK
2015-09-13 20:57:37,735 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36040: status
2015-09-13 20:57:37,780 DEBUG [3444:MpdSession-12] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36040:
volume: 100
repeat: 0
random: 0
single: 0
consume: 0
playlist: 2
playlistlength: 1
xfade: 0
state: stop
OK
2015-09-13 20:57:38,939 DEBUG [3444:MpdSession-12] mopidy.internal.network: Client most likely disconnected.
2015-09-13 20:57:38,961 DEBUG [3444:MpdSession-12] pykka: Unregistered MpdSession (urn:uuid:1d1dcbc4-83e9-48e2-ad2c-57378a68d8bd)
2015-09-13 20:57:38,970 DEBUG [3444:MpdSession-12] pykka: Stopped MpdSession (urn:uuid:1d1dcbc4-83e9-48e2-ad2c-57378a68d8bd)
2015-09-13 20:57:38,976 DEBUG [3444:MpdSession-12] mopidy.internal.network: Already stopping: Actor is shutting down.
2015-09-13 20:57:49,365 INFO [3444:MainThread] mopidy.internal.process: Got SIGTERM signal
2015-09-13 20:57:49,370 DEBUG [3444:MainThread] mopidy.internal.process: Interrupting main...
2015-09-13 20:57:49,375 INFO [3444:MainThread] mopidy.commands: Interrupted. Exiting...
2015-09-13 20:57:49,380 INFO [3444:MainThread] mopidy.commands: Stopping Mopidy frontends
2015-09-13 20:57:49,386 DEBUG [3444:MainThread] mopidy.internal.process: Stopping 1 instance(s) of MpdFrontend
2015-09-13 20:57:49,394 DEBUG [3444:MpdFrontend-8] pykka: Unregistered MpdFrontend (urn:uuid:e5a478ea-4a0f-43b6-a4bc-c6fbdcd7521b)
2015-09-13 20:57:49,399 DEBUG [3444:MpdFrontend-8] pykka: Stopped MpdFrontend (urn:uuid:e5a478ea-4a0f-43b6-a4bc-c6fbdcd7521b)
2015-09-13 20:57:49,421 DEBUG [3444:MpdFrontend-8] mopidy.zeroconf: Zeroconf service _mpd._tcp at [lyra.local]:6600: Unpublished
2015-09-13 20:57:49,425 DEBUG [3444:MpdFrontend-8] mopidy.internal.process: Stopping 0 instance(s) of MpdSession
2015-09-13 20:57:49,433 DEBUG [3444:MainThread] mopidy.internal.process: Stopping 1 instance(s) of HttpFrontend
2015-09-13 20:57:49,442 DEBUG [3444:HttpFrontend-10] pykka: Unregistered HttpFrontend (urn:uuid:4fd4b967-5504-4cff-b7ba-6e1d35e8647f)
2015-09-13 20:57:49,446 DEBUG [3444:HttpFrontend-10] pykka: Stopped HttpFrontend (urn:uuid:4fd4b967-5504-4cff-b7ba-6e1d35e8647f)
2015-09-13 20:57:49,462 DEBUG [3444:HttpFrontend-10] mopidy.zeroconf: Zeroconf service _http._tcp at [lyra.local]:6680: Unpublished
2015-09-13 20:57:49,481 DEBUG [3444:HttpFrontend-10] mopidy.zeroconf: Zeroconf service _mopidy-http._tcp at [lyra.local]:6680: Unpublished
2015-09-13 20:57:49,492 DEBUG [3444:HttpFrontend-10] mopidy.http.actor: Stopping HTTP server
2015-09-13 20:57:49,500 DEBUG [3444:HttpServer] mopidy.http.actor: Stopped HTTP server
2015-09-13 20:57:49,507 INFO [3444:MainThread] mopidy.commands: Stopping Mopidy core
2015-09-13 20:57:49,513 DEBUG [3444:MainThread] mopidy.internal.process: Stopping 1 instance(s) of Core
2015-09-13 20:57:49,523 DEBUG [3444:Core-7] pykka: Unregistered Core (urn:uuid:8cd7adf5-fb7f-43d1-ab42-3263735e35fe)
2015-09-13 20:57:49,527 DEBUG [3444:Core-7] pykka: Stopped Core (urn:uuid:8cd7adf5-fb7f-43d1-ab42-3263735e35fe)
2015-09-13 20:57:49,535 INFO [3444:MainThread] mopidy.commands: Stopping Mopidy backends
2015-09-13 20:57:49,542 DEBUG [3444:MainThread] mopidy.internal.process: Stopping 1 instance(s) of StreamBackend
2015-09-13 20:57:49,558 DEBUG [3444:StreamBackend-3] pykka: Unregistered StreamBackend (urn:uuid:e111cf17-b6a9-40ff-b92a-ab8593e3e2af)
2015-09-13 20:57:49,563 DEBUG [3444:StreamBackend-3] pykka: Stopped StreamBackend (urn:uuid:e111cf17-b6a9-40ff-b92a-ab8593e3e2af)
2015-09-13 20:57:49,571 DEBUG [3444:MainThread] mopidy.internal.process: Stopping 1 instance(s) of M3UBackend
2015-09-13 20:57:49,581 DEBUG [3444:M3UBackend-4] pykka: Unregistered M3UBackend (urn:uuid:c979ca1e-8592-46fb-8fd7-d7ece020a966)
2015-09-13 20:57:49,586 DEBUG [3444:M3UBackend-4] pykka: Stopped M3UBackend (urn:uuid:c979ca1e-8592-46fb-8fd7-d7ece020a966)
2015-09-13 20:57:49,594 DEBUG [3444:MainThread] mopidy.internal.process: Stopping 1 instance(s) of FileBackend
2015-09-13 20:57:49,605 DEBUG [3444:FileBackend-5] pykka: Unregistered FileBackend (urn:uuid:dfec6f75-f8db-4d87-8cdd-2e8f1c0ae1f8)
2015-09-13 20:57:49,609 DEBUG [3444:FileBackend-5] pykka: Stopped FileBackend (urn:uuid:dfec6f75-f8db-4d87-8cdd-2e8f1c0ae1f8)
2015-09-13 20:57:49,617 DEBUG [3444:MainThread] mopidy.internal.process: Stopping 1 instance(s) of LocalBackend
2015-09-13 20:57:49,626 DEBUG [3444:LocalBackend-6] pykka: Unregistered LocalBackend (urn:uuid:973f39aa-9b04-493c-a149-1f9f7b375394)
2015-09-13 20:57:49,632 DEBUG [3444:LocalBackend-6] pykka: Stopped LocalBackend (urn:uuid:973f39aa-9b04-493c-a149-1f9f7b375394)
2015-09-13 20:57:49,646 INFO [3444:MainThread] mopidy.commands: Stopping Mopidy audio
2015-09-13 20:57:49,652 DEBUG [3444:MainThread] mopidy.internal.process: Stopping 1 instance(s) of Audio
2015-09-13 20:57:49,659 DEBUG [3444:Audio-2] pykka: Unregistered Audio (urn:uuid:3f2bf046-18e2-403f-8af5-4f142f617834)
2015-09-13 20:57:49,667 DEBUG [3444:Audio-2] pykka: Stopped Audio (urn:uuid:3f2bf046-18e2-403f-8af5-4f142f617834)
2015-09-13 20:57:49,678 INFO [3444:MainThread] mopidy.commands: Stopping Mopidy mixer
2015-09-13 20:57:49,682 DEBUG [3444:MainThread] mopidy.internal.process: Stopping 1 instance(s) of SoftwareMixer
2015-09-13 20:57:49,692 DEBUG [3444:SoftwareMixer-1] pykka: Unregistered SoftwareMixer (urn:uuid:fcab7949-63c6-49d9-8178-3e7933710f24)
2015-09-13 20:57:49,696 DEBUG [3444:SoftwareMixer-1] pykka: Stopped SoftwareMixer (urn:uuid:fcab7949-63c6-49d9-8178-3e7933710f24)
2015-09-13 20:57:49,707 DEBUG [3444:MainThread] mopidy.internal.process:And here’s upmpdcli’s log:
tail: /var/log/upmpd.log: file truncated
src/mpdcli.cxx:220::MPDCli::checkForCommand: addtagid
libupnpp/upnpplib.cxx:105::LibUPnP: serveronly 1 &hwaddr 0xbe9dab70 ifname [] inip [] port 0
libupnpp/upnpplib.cxx:144::LibUPnP: Using IP 192.168.0.19 port 49152
src/ohproduct.cxx:64::OHProduct::OHProduct: sources: <SourceList >
<Source >
<Name >Playlist</Name >
<Type >Playlist</Type >
<Visible >1</Visible >
</Source >
</SourceList >
src/mpdcli.cxx:461::MPDCli::consume:0
src/ohplaylist.cxx:105::ohPlaylist: cache restore done
src/upmpd.cxx:524::Entering event loop
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_CONTROL_ACTION_REQUEST
libupnpp/device/device.cxx:292::UPNP_CONTROL_ACTION_REQUEST: Characteristics. Params: <?xml version="1.0"? >
<u:Characteristics xmlns:u="urn:av-openhome-org:service:Volume:1" ></u:Characteristics >
src/ohvolume.cxx:108::OHVolume::charact.
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_CONTROL_ACTION_REQUEST
libupnpp/device/device.cxx:292::UPNP_CONTROL_ACTION_REQUEST: SourceXml. Params: <?xml version="1.0"? >
<u:SourceXml xmlns:u="urn:av-openhome-org:service:Product:1" ></u:SourceXml >
src/ohproduct.cxx:191::OHProduct::sourceXML
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_CONTROL_ACTION_REQUEST
libupnpp/device/device.cxx:292::UPNP_CONTROL_ACTION_REQUEST: Product. Params: <?xml version="1.0"? >
<u:Product xmlns:u="urn:av-openhome-org:service:Product:1" ></u:Product >
src/ohproduct.cxx:156::OHProduct::product
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_CONTROL_ACTION_REQUEST
libupnpp/device/device.cxx:292::UPNP_CONTROL_ACTION_REQUEST: ProtocolInfo. Params: <?xml version="1.0"? >
<u:ProtocolInfo xmlns:u="urn:av-openhome-org:service:Playlist:1" ></u:ProtocolInfo >
src/ohplaylist.cxx:715::OHPlaylist::protocolInfo
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:RenderingControl LastChange
src/avtransport.cxx:288::UpMpdAVTransport::getEventDataTransport: <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT_RCS" >
<InstanceID val="0" >
<RelativeCounterPosition val="0"/ >
<CurrentPlayMode val="NORMAL"/ >
<CurrentTrackDuration val="00:00:00"/ >
<RelativeTimePosition val="0:00:00"/ >
<NumberOfTracks val="1"/ >
<RecordStorageMedium val="NOT_IMPLEMENTED"/ >
<CurrentRecordQualityMode val="NOT_IMPLEMENTED"/ >
<PossiblePlaybackStorageMedia val="HDD,NETWORK"/ >
<RecordMediumWriteStatus val="NOT_IMPLEMENTED"/ >
<PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/ >
<TransportState val="STOPPED"/ >
<CurrentTransportActions val="Next,Previous,Play"/ >
<TransportStatus val="OK"/ >
<TransportPlaySpeed val="1"/ >
<PossibleRecordQualityModes val="NOT_IMPLEMENTED"/ >
<CurrentTrack val="1"/ >
<PlaybackStorageMedium val="NONE"/ >
<CurrentMediaDuration val="00:00:00"/ >
<AbsoluteTimePosition val="0:00:00"/ >
<AbsoluteCounterPosition val="0"/ >
</InstanceID >
</Event >
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:AVTransport LastChange
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Info DetailsCount
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Duration
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Volume VolumeMax
src/mpdcli.cxx:636::MPDCli::getQueueSongs: 0 songs
src/ohplaylist.cxx:144::OHPlaylist: current ids:
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Playlist IdArray
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_CONTROL_ACTION_REQUEST
libupnpp/device/device.cxx:292::UPNP_CONTROL_ACTION_REQUEST: SourceIndex. Params: <?xml version="1.0"? >
<u:SourceIndex xmlns:u="urn:av-openhome-org:service:Product:1" ></u:SourceIndex >
src/ohproduct.cxx:198::OHProduct::sourceIndex
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_EVENT_SUBSCRIPTION_REQUEST
libupnpp/device/device.cxx:349::UPNP_EVENT_SUBSCRIPTION_REQUEST: urn:av-openhome-org:serviceId:Playlist
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_EVENT_SUBSCRIPTION_REQUEST
libupnpp/device/device.cxx:349::UPNP_EVENT_SUBSCRIPTION_REQUEST: urn:av-openhome-org:serviceId:Volume
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_EVENT_SUBSCRIPTION_REQUEST
libupnpp/device/device.cxx:349::UPNP_EVENT_SUBSCRIPTION_REQUEST: urn:av-openhome-org:serviceId:Info
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_EVENT_SUBSCRIPTION_REQUEST
libupnpp/device/device.cxx:349::UPNP_EVENT_SUBSCRIPTION_REQUEST: urn:av-openhome-org:serviceId:Product
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:RenderingControl LastChange
src/avtransport.cxx:288::UpMpdAVTransport::getEventDataTransport: <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT_RCS" >
<InstanceID val="0" >
<RelativeCounterPosition val="0"/ >
<CurrentPlayMode val="NORMAL"/ >
<CurrentTrackDuration val="00:00:00"/ >
<RelativeTimePosition val="0:00:00"/ >
<NumberOfTracks val="1"/ >
<RecordStorageMedium val="NOT_IMPLEMENTED"/ >
<CurrentRecordQualityMode val="NOT_IMPLEMENTED"/ >
<PossiblePlaybackStorageMedia val="HDD,NETWORK"/ >
<RecordMediumWriteStatus val="NOT_IMPLEMENTED"/ >
<PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/ >
<TransportState val="STOPPED"/ >
<CurrentTransportActions val="Next,Previous,Play"/ >
<TransportStatus val="OK"/ >
<TransportPlaySpeed val="1"/ >
<PossibleRecordQualityModes val="NOT_IMPLEMENTED"/ >
<CurrentTrack val="1"/ >
<PlaybackStorageMedium val="NONE"/ >
<CurrentMediaDuration val="00:00:00"/ >
<AbsoluteTimePosition val="0:00:00"/ >
<AbsoluteCounterPosition val="0"/ >
</InstanceID >
</Event >
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:AVTransport LastChange
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:ConnectionManager SinkProtocolInfo
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Product ManufacturerName
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Info DetailsCount
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Seconds
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Volume VolumeMilliDbPerSteps
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Playlist IdArray
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_CONTROL_ACTION_REQUEST
libupnpp/device/device.cxx:292::UPNP_CONTROL_ACTION_REQUEST: DeleteAll. Params: <?xml version="1.0"? >
<u:DeleteAll xmlns:u="urn:av-openhome-org:service:Playlist:1" ></u:DeleteAll >
src/ohplaylist.cxx:635::OHPlaylist::deleteAll
src/mpdcli.cxx:574::MPDCli::clearQueue
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_CONTROL_ACTION_REQUEST
libupnpp/device/device.cxx:292::UPNP_CONTROL_ACTION_REQUEST: Insert. Params: <?xml version="1.0"? >
<u:Insert xmlns:u="urn:av-openhome-org:service:Playlist:1" >
<AfterId >0</AfterId >
<Uri >http://192.168.0.7:8200/MediaItems/114355.mp3</Uri >
<Metadata ><DIDL-Lite xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/" xmlns:sec="http://www.sec.co.kr/"><item id="64$0$2$7$6$13" parentID="64$0$2$7$6" restricted="1"><upnp:class>object.item.audioItem.musicTrack</upnp:class><dc:title>Trans Europa Express</dc:title><dc:creator>Kraftwerk</dc:creator><upnp:artist>Kraftwerk</upnp:artist><upnp:albumArtURI>http://192.168.0.7:8200/AlbumArt/430-114355.jpg</upnp:albumArtURI><upnp:albumArtURI dlna:profileID="JPEG_TN">http://192.168.0.7:8200/AlbumArt/430-114355.jpg</upnp:albumArtURI><upnp:genre>Elektronik &amp; Ambient</upnp:genre><dc:date>1977-01-01</dc:date><upnp:album>Trans Europa Express</upnp:album><upnp:originalTrackNumber>4</upnp:originalTrackNumber><ownerUdn>4d696e69-444c-164e-9d41-386077f0be55</ownerUdn><res protocolInfo="http-get:*:audio/mpeg:DLNA.ORG_PN=MP3;DLNA.ORG_OP=01;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=01700000000000000000000000000000" bitrate="128000" sampleFrequency="44100" nrAudioChannels="2" size="6343936" duration="0:06:36.000">http://192.168.0.7:8200/MediaItems/114355.mp3</res></item></DIDL-Lite></Metadata >
</u:Insert >
src/mpdcli.cxx:636::MPDCli::getQueueSongs: 0 songs
src/ohplaylist.cxx:144::OHPlaylist: current ids:
src/ohplaylist.cxx:570::OHPlaylist::insert
src/ohplaylist.cxx:579::OHPlaylist::insert: afterid 0 Uri http://192.168.0.7:8200/MediaItems/114355.mp3 Metadata <DIDL-Lite xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/" xmlns:sec="http://www.sec.co.kr/" ><item id="64$0$2$7$6$13" parentID="64$0$2$7$6" restricted="1" ><upnp:class >object.item.audioItem.musicTrack</upnp:class ><dc:title >Trans Europa Express</dc:title ><dc:creator >Kraftwerk</dc:creator ><upnp:artist >Kraftwerk</upnp:artist ><upnp:albumArtURI >http://192.168.0.7:8200/AlbumArt/430-114355.jpg</upnp:albumArtURI ><upnp:albumArtURI dlna:profileID="JPEG_TN" >http://192.168.0.7:8200/AlbumArt/430-114355.jpg</upnp:albumArtURI ><upnp:genre >Elektronik & Ambient</upnp:genre ><dc:date >1977-01-01</dc:date ><upnp:album >Trans Europa Express</upnp:album ><upnp:originalTrackNumber >4</upnp:originalTrackNumber ><ownerUdn >4d696e69-444c-164e-9d41-386077f0be55</ownerUdn ><res protocolInfo="http-get:*:audio/mpeg:DLNA.ORG_PN=MP3;DLNA.ORG_OP=01;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=01700000000000000000000000000000" bitrate="128000" sampleFrequency="44100" nrAudioChannels="2" size="6343936" duration="0:06:36.000" >http://192.168.0.7:8200/MediaItems/114355.mp3</res ></item ></DIDL-Lite >
src/mpdcli.cxx:540::MPDCli::insertAfterId: id 0 uri http://192.168.0.7:8200/MediaItems/114355.mp3
src/mpdcli.cxx:522::MPDCli::insert at :0 uri http://192.168.0.7:8200/MediaItems/114355.mp3
src/ohplaylist.cxx:585::OHPlaylist::insert: new id: 0
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:RenderingControl LastChange
src/avtransport.cxx:288::UpMpdAVTransport::getEventDataTransport: <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT_RCS" >
<InstanceID val="0" >
<RelativeCounterPosition val="0"/ >
<CurrentPlayMode val="NORMAL"/ >
<CurrentTrackDuration val="00:00:00"/ >
<RelativeTimePosition val="0:00:00"/ >
<NumberOfTracks val="1"/ >
<RecordStorageMedium val="NOT_IMPLEMENTED"/ >
<CurrentRecordQualityMode val="NOT_IMPLEMENTED"/ >
<PossiblePlaybackStorageMedia val="HDD,NETWORK"/ >
<RecordMediumWriteStatus val="NOT_IMPLEMENTED"/ >
<PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/ >
<TransportState val="STOPPED"/ >
<CurrentTransportActions val="Next,Previous,Play"/ >
<TransportStatus val="OK"/ >
<TransportPlaySpeed val="1"/ >
<PossibleRecordQualityModes val="NOT_IMPLEMENTED"/ >
<CurrentTrack val="1"/ >
<PlaybackStorageMedium val="NONE"/ >
<CurrentMediaDuration val="00:00:00"/ >
<AbsoluteTimePosition val="0:00:00"/ >
<AbsoluteCounterPosition val="0"/ >
</InstanceID >
</Event >
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:AVTransport LastChange
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:ConnectionManager SinkProtocolInfo
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Product ManufacturerName
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Info DetailsCount
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Info DetailsCount
libupnpp/upnpplib.cxx:255::LibUPnP::o_callback: event type: UPNP_CONTROL_ACTION_REQUEST
libupnpp/device/device.cxx:292::UPNP_CONTROL_ACTION_REQUEST: SeekId. Params: <?xml version="1.0"? >
<u:SeekId xmlns:u="urn:av-openhome-org:service:Playlist:1" >
<Value >0</Value >
</u:SeekId >
src/ohplaylist.cxx:417::OHPlaylist::seekId
src/mpdcli.cxx:408::MPDCli::playId(id=0)
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Seconds
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Volume VolumeMilliDbPerSteps
src/mpdcli.cxx:636::MPDCli::getQueueSongs: 1 songs
src/ohplaylist.cxx:144::OHPlaylist: current ids: 0
src/ohplaylist.cxx:224::OHPlaylist::makeIdArray: saving metacache
src/ohmetacache.cxx:128::dmcacheSave: got save task: 1 entries to /var/cache/upmpdcli//metacache
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Playlist IdArray
stolibupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:RenderingControl LastChange
psrc/avtransport.cxx:288::UpMpdAVTransport::getEventDataTransport: <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT_RCS" >
<InstanceID val="0" >
<RelativeCounterPosition val="0"/ >
<CurrentPlayMode val="NORMAL"/ >
<CurrentTrackDuration val="00:00:00"/ >
<RelativeTimePosition val="0:00:00"/ >
<NumberOfTracks val="1"/ >
<RecordStorageMedium val="NOT_IMPLEMENTED"/ >
<CurrentRecordQualityMode val="NOT_IMPLEMENTED"/ >
<PossiblePlaybackStorageMedia val="HDD,NETWORK"/ >
<RecordMediumWriteStatus val="NOT_IMPLEMENTED"/ >
<PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/ >
<TransportState val="STOPPED"/ >
<CurrentTransportActions val="Next,Previous,Play"/ >
<TransportStatus val="OK"/ >
<TransportPlaySpeed val="1"/ >
<PossibleRecordQualityModes val="NOT_IMPLEMENTED"/ >
<CurrentTrack val="1"/ >
<PlaybackStorageMedium val="NONE"/ >
<CurrentMediaDuration val="00:00:00"/ >
<AbsoluteTimePosition val="0:00:00"/ >
<AbsoluteCounterPosition val="0"/ >
</InstanceID >
</Event >
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:AVTransport LastChange
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:upnp-org:serviceId:ConnectionManager SinkProtocolInfo
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Product ManufacturerName
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Info DetailsCount
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Seconds
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Volume VolumeMilliDbPerSteps
libupnpp/device/device.cxx:410::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Playlist IdArray
src/upmpd.cxx:179::Got sig
src/upmpd.cxx:527::Event loop returned
src/ohmetacache.cxx:123::dmcacheSaveWorker: can't get task from queueI hope the logs make more sense this time…
And yes, upmpdcli retains the same process number all the time.
Cheers --
— Torsten
medoc92 writes
Hi,
I just tried on a Raspbian Raspberry Pi with mopidy 1.1.1-1 (just installed from the mopidy apt repo), and upmpdcli 0.11.2-1 (just upgraded from the upmpdcli apt repo). Both with default configs.
I am seeing the same error as you the first time I try to add a track.
If I then clear the (apparently empty) playlist from the client (upplay), and retry the add, it works, and goes on working further on (I can add and play tracks without further issues).
The strange thing in the log is that mopidy claims to support the addtagid command:
2015-09-13 20:56:52,689 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36029: commands
2015-09-13 20:56:52,705 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36029:
command: add
command: addid
command: addtagid
command: channelsThen claims later that it does not support it, quite suspiciously, just before the "client most likely disconnected" message.
DEBUG [3444:MpdSession-11] mopidy.mpd.session: Request from [::ffff:127.0.0.1]:36029: addtagid "0" "Artist" "Kraftwerk"
2015-09-13 20:57:15,780 DEBUG [3444:MpdSession-11] mopidy.mpd.session: Response to [::ffff:127.0.0.1]:36029: ACK [0@0] {addtagid} Not implemented
2015-09-13 20:57:15,798 DEBUG [3444:MainThread] pykka: Registered MpdSession (urn:uuid:1d1dcbc4-83e9-48e2-ad2c-57378a68d8bd)
2015-09-13 20:57:15,802 DEBUG [3444:MainThread] pykka: Starting MpdSession (urn:uuid:1d1dcbc4-83e9-48e2-ad2c-57378a68d8bd)
2015-09-13 20:57:15,816 DEBUG [3444:MpdSession-11] mopidy.internal.network: Client most likely disconnected.upmpdcli does not even check the return from this command, so I don’t know who does the disconnecting here, a quick check seems to indicate that libmpdclient does not do it, so it might be worth it to check if mopidy disconnects clients which send unsupported commands.
Unfortunately, I won’t be able to work on this further this week, but it would be interesting to verify if the problem would change with restoring the protocol consistency by not sending addtagid in the list of supported commands, so that upmpdcli will not try to use it.
tcrass writes
Hi,
> I am seeing the same error as you the first time I try to add a track.kinda "glad" to hear this — so it’s not just me being too stupid to set up mopidy/upmpdcli…
> If I then clear the (apparently empty) playlist from the client (upplay), and retry the add, it works, and goes on working further on (I can add and play tracks without further issues).I can’t reproduce this behavior since BubbleUPnP (version 2.5.1.2) doesn’t offer me an option to clear the playlist if it’s empty.
(My mopidy is at version 1.1.0, and upmpdcli is at 0.11.2-1)
> The strange thing in the log is that mopidy claims to support the addtagid command:
> [...]
> so it might be worth it to check if mopidy disconnects clients which send unsupported commands.Should we inform the mopidy people about this finding? If you considered this appropriate, I’d just copy our conversation to a new ticket on mopidy’s issue tracker.
> Unfortunately, I won't be able to work on this further this week,No problem — I’m happy already knowing that you care about this problem! :)
Best regards --
— Torsten
medoc92 writes
Yes, the part about addtagid seems like a mopidy issue, it may be related or not to the upmpdcli one, I think that informing the mopidy developers can’t hurt, maybe they’ll have an insight.
On Mon, 14 Sep 2015 13:29:30 -0700, tcrass notifications@github.com wrote:
> Hi,
>
> > I am seeing the same error as you the first time I try to add a track.
>
> kinda "glad" to hear this -- so it's not just me being too stupid to set up mopidy/upmpdcli...
>
> > If I then clear the (apparently empty) playlist from the client (upplay), and retry the add, it works, and goes on working further on (I can add and play tracks without further issues).
>
> I can't reproduce this behavior since BubbleUPnP (version 2.5.1.2) doesn't offer me an option to clear the playlist if it's empty.
>
> (My mopidy is at version 1.1.0, and upmpdcli is at 0.11.2-1)
>
> > The strange thing in the log is that mopidy claims to support the addtagid command:
> > [...]
> > so it might be worth it to check if mopidy disconnects clients which send unsupported commands.
>
> Should we inform the mopidy people about this finding? If you considered this appropriate, I'd just copy our conversation to a new ticket on mopidy's issue tracker.
>
> > Unfortunately, I won't be able to work on this further this week,
>
> No problem -- I'm happy already knowing that you care about this problem! :)
>
> Best regards --
>
> -- Torsten
>
> ---
>
> Reply to this email directly or view it on GitHub:
> https://www.lesbonscomptes.com/upmpdcli/github-issues/upmpdcli-html/issue-17.html#issuecomment-140196957medoc92 writes
tcrass writes:
> Hi,
>
> > I am seeing the same error as you the first time I try to add a
> track.
>>
> kinda "glad" to hear this -- so it's not just me being too stupid to
> set up mopidy/upmpdcli...
>
> > If I then clear the (apparently empty) playlist from the client
> (upplay), and retry the add, it works, and goes on working further
> on (I can add and play tracks without further issues).
>>
> I can't reproduce this behavior since BubbleUPnP (version 2.5.1.2)
> doesn't offer me an option to clear the playlist if it's empty.
>
> (My mopidy is at version 1.1.0, and upmpdcli is at 0.11.2-1)I was testing this with the latest mopidy and upmpdcli I think.
> > The strange thing in the log is that mopidy claims to support the
> addtagid command:
> [...]
> so it might be worth it to check if mopidy disconnects clients which
> send unsupported commands.
>>
> Should we inform the mopidy people about this finding? If you
> considered this appropriate, I'd just copy our conversation to a new
> ticket on mopidy's issue tracker.I think I already answered yes to this ? Not too sure, I was tired yday. So, in any case: yes…
> > Unfortunately, I won't be able to work on this further this week,
>>
> No problem -- I'm happy already knowing that you care about this
> problem! :)Well, this seems relatively simple, and hopefully, with a bit of cooperation from the Mopidy guys we will be able to sort it out !
Cheers,
jf
tcrass writes
Hi Jean-Francois,
> Should we inform the mopidy people about this finding? If you considered this appropriate, I'd just copy our conversation to a new ticket on mopidy's issue tracker.
>
> > Yes, the part about addtagid seems like a mopidy issue, it may be related or not to the upmpdcli one, I think that informing the mopidy developers can't hurt, maybe they'll have an insight.Cheers --
— Torsten
tcrass writes
Hi Jean-Francois,
according to the latest comment on the mopidy issue tracker, mopidy doesn’t actively disconnect clients:
> We do not disconnect clients using unsupported commands, but simply return the error like any other response and continue on. This is probably the client library that does a reconnect-on-error, as you can see the requests switches from coming from port 36029 before the error to 36040 after the error.Regarding the unsupported addtagid command:
> Our commands implementation lists all commands we know about and that you have access to, also those that are not implemented, which is quite a lot of them.
> addtagid was added as an empty shell of a command in Mopidy 1.1, IIRC, and was thus not listed in the commands output before that.Can you make sense of this?
Cheers --
— Torsten
medoc92 writes
Thanks a lot for the new info. I won’t be able to work on this till mid-week, but I’ll then try to trace precisely what happens.
tcrass writes
Jean-Francois,
thanks a lot for your efforts to resolve this issue! I am looking forward to hear from you.
Best regards --
— Torsten
medoc92 writes
After some more testing, it seems to me that the cause of the problem is that mopidy uses an initial songid of 0. As far as I know, mpd never uses songid 0.
upmpdcli does a direct translation from mpd songids to OpenHome queue Ids. Queue Id 0 is invalid for OpenHome (it’s used to mean an empty queue in some places).
I have found a workaround, maybe you could try it to confirm: - Add a song with bubble: won’t appear - run "mpc clear". This resets the Mopidy queue, but not the base songid (song ids are mostly not reused). - Add a song with bubble: now works.
Assuming that this works and that your problem is not different from what I am seeing (else we’ll have to do some more work):
I am wary of changing the upmpdcli code. I guess that I could just add 1 to any songid from mpd/mopidy, and things would just work, but the code works fine with mpd, and I don’t want to break it.
So I guess that the easiest change would be for the mopidy people to avoid using 0 as a songid (just start at 1 or whatever). This would just improve compatibility with mpd, which does not use 0, and seems like a really simple change.
Else, I guess that a workaround would be to add / delete a song with mpc every time mopidy starts.
The weird thing is that upmpdcli works fine with piMusicBox as far as I know (it’s part of the distribution actually). I am a bit too lazy to check why.
Anyway, I also verified that the following complex patch fixed the problem for me:
diff --git a/mopidy/core/tracklist.py b/mopidy/core/tracklist.py
index 13efe32..4729ab8 100644
--- a/mopidy/core/tracklist.py
+++ b/mopidy/core/tracklist.py
@@ -16,7 +16,7 @@ class TracklistController(object):
def __init__(self, core):
self.core = core
- self._next_tlid = 0
+ self._next_tlid = 1
self._tl_tracks = []
self._version = 0tcrass writes
Hi Jean-Francois,
> Anyway, I also verified that the following complex patch fixed the problem for me:this is it! :)
BTW, meanwhile I upgraded my system and now I’m also on mopidy 1.1.1. The error(s) described in my original report vanished, and now I observe similar issues like you. In particular, after a mopidy restart, when adding the first song, it doesn’t show up in Bubble (neither the playlist, nor the now-playing-screen), but it starts actually playing! (I didn’t realize earlier since I didn’t even bother to switch on the amplifier without any indication in Bubble that the song was playing). When adding another song, it does show up in Bubble, and so do all further songs.
When, however, applying your complex patch, songs show up in Bubble right from the beginning.
So, would you like to inform the mopidy folks about your findings, or do you want me to beg them to include your patch into the next release?
Thank you so much for your efforts!
Best regards --
— Torsten
medoc92 writes
I created a topic on the Mopidy discussion list. Thanks for your help in solving this.