joerg-krause writes

When using the Play/Stop button of the Linn Songcast tool (Version 4.8.535) while playing, the streams stops. Pressing the button again, does not resume playback.

This is some log of upmpdcli:

:4:src/ohreceiver.cxx:178::OHReceiver: sc2mpd sent: CONNECTED
:4:src/ohplaylist.cxx:744::OHPlaylist::idArray (internal)
:4:src/ohplaylist.cxx:747::OHPlaylist::idArray: qvers 48
:3:libupnpp/control/cdircontent.cxx:108::checkobjok: found object of unknown class: [object.item.audioItem]
:4:src/mpdcli.cxx:697::MPDCli::insertAfterId: id 0 uri http://localhost:8768/Songcast.wav
:4:src/mpdcli.cxx:679::MPDCli::insert at :0 uri http://localhost:8768/Songcast.wav
LATENCY 326
:4:src/mpdcli.cxx:557::MPDCli::playId(id=7)
:3:sc2src/httpgate.cpp:149::data_generator: first buf
:4:src/mpdcli.cxx:809::MPDCli::getQueueData
:4:src/mpdcli.cxx:794::MPDCli::getQueueSongs: 1 songs
:4:src/ohplaylist.cxx:146::OHPlaylist::translateIdArray: current ids: 7
:4:libupnpp/device/device.cxx:318::UPNP_CONTROL_ACTION_REQUEST: Stop. Params: <?xml version="1.0"? >
<u:Stop xmlns:u="urn:av-openhome-org:service:Receiver:1" ></u:Stop >

:4:src/ohreceiver.cxx:256::OHReceiver::stop
:4:src/ohreceiver.cxx:231::OHReceiver::iStop()
:4:src/execmd-fixed.cpp:274::ExecCmd: killpg(1257, SIGTERM)
:4:src/mpdcli.cxx:570::MPDCli::stop
:4:src/ohplaylist.cxx:744::OHPlaylist::idArray (internal)
:4:src/ohplaylist.cxx:747::OHPlaylist::idArray: qvers 54
:4:src/mpdcli.cxx:741::MPDCli::deleteId 7
:4:src/ohproduct.cxx:321::OHProduct::iSetSourceIndexByName: Playlist
:4:src/ohproduct.cxx:244::OHProduct::iSetSourceIndex: current 1 new 0
:4:src/ohreceiver.cxx:231::OHReceiver::iStop()
:4:src/mpdcli.cxx:570::MPDCli::stop
:4:src/ohplaylist.cxx:744::OHPlaylist::idArray (internal)
:4:src/ohplaylist.cxx:747::OHPlaylist::idArray: qvers 54
:2:src/mpdcli.cxx:146::song = mpd_run_get_queue_song_id(M_CONN, (unsigned int)pos) failed: No such song
:2:src/mpdcli.cxx:149::song = mpd_run_get_queue_song_id(M_CONN, (unsigned int)pos) server error: 50
:4:src/ohplaylist.cxx:598::OHPlaylist::readList:stat failed for 7
:4:src/mpdcli.cxx:731::MPDCli::clearQueue
:2:src/mpdcli.cxx:146::mpd_run_clear(M_CONN) failed: No such song
:2:src/mpdcli.cxx:149::mpd_run_clear(M_CONN) server error: 50
:4:src/mpdcli.cxx:332::MPDCli::restoreState: seekms 0
:4:src/mpdcli.cxx:731::MPDCli::clearQueue
:2:src/mpdcli.cxx:146::mpd_run_clear(M_CONN) failed: No such song
:2:src/mpdcli.cxx:149::mpd_run_clear(M_CONN) server error: 50
:4:src/mpdcli.cxx:603::MPDCli::repeat:0
:2:src/mpdcli.cxx:146::mpd_run_repeat(M_CONN, on) failed: No such song
:2:src/mpdcli.cxx:149::mpd_run_repeat(M_CONN, on) server error: 50
:4:src/mpdcli.cxx:621::MPDCli::random:0
:2:src/mpdcli.cxx:146::mpd_run_random(M_CONN, on) failed: No such song
:2:src/mpdcli.cxx:149::mpd_run_random(M_CONN, on) server error: 50
:4:src/mpdcli.cxx:629::MPDCli::single:0
:2:src/mpdcli.cxx:146::mpd_run_single(M_CONN, on) failed: No such song
:2:src/mpdcli.cxx:149::mpd_run_single(M_CONN, on) server error: 50
:4:src/mpdcli.cxx:612::MPDCli::consume:0
:2:src/mpdcli.cxx:146::mpd_run_consume(M_CONN, on) failed: No such song
:2:src/mpdcli.cxx:149::mpd_run_consume(M_CONN, on) server error: 50
:4:src/mpdcli.cxx:809::MPDCli::getQueueData
:2:src/mpdcli.cxx:146::mpd_send_list_queue_meta(M_CONN) failed: No such song
:2:src/mpdcli.cxx:149::mpd_send_list_queue_meta(M_CONN) server error: 50
:2:src/ohplaylist.cxx:179::OHPlaylist::makeIdArray: getQueueData failed.metacache size 0
:4:src/mpdcli.cxx:128::MPDCLi::openconn: mpd protocol version: 0.19.0
:4:src/mpdcli.cxx:809::MPDCli::getQueueData
:4:src/mpdcli.cxx:794::MPDCli::getQueueSongs: 0 songs
:4:src/ohplaylist.cxx:146::OHPlaylist::translateIdArray: current ids:
:4:src/mpdcli.cxx:809::MPDCli::getQueueData
:4:src/mpdcli.cxx:794::MPDCli::getQueueSongs: 0 songs
:4:src/ohplaylist.cxx:146::OHPlaylist::translateIdArray: current ids:
:4:libupnpp/device/device.cxx:318::UPNP_CONTROL_ACTION_REQUEST: Play. Params: <?xml version="1.0"? >
<u:Play xmlns:u="urn:av-openhome-org:service:Receiver:1" ></u:Play >

:4:src/ohreceiver.cxx:221::OHReceiver::play
:4:src/ohproduct.cxx:321::OHProduct::iSetSourceIndexByName: Receiver
:4:src/ohproduct.cxx:244::OHProduct::iSetSourceIndex: current 0 new 1
:4:src/mpdcli.cxx:313::MPDCli::saveState: seekms 0
:4:libupnpp/device/device.cxx:318::UPNP_CONTROL_ACTION_REQUEST: SetSender. Params: <?xml version="1.0"? >
<u:SetSender xmlns:u="urn:av-openhome-org:service:Receiver:1" >
<Uri >ohz://239.255.255.250:51972/575e95641e7106b60cf76e91ebc94919</Uri >
<Metadata >&lt;DIDL-Lite xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot;&gt;&lt;item id=&quot;0&quot; restricted=&quot;True&quot;&gt;&lt;dc:title&gt;WIN7PRO&lt;/dc:title&gt;&lt;res protocolInfo=&quot;ohz:*:*:u&quot;&gt;ohz://239.255.255.250:51972/575e95641e7106b60cf76e91ebc94919&lt;/res&gt;&lt;upnp:class&gt;object.item.audioItem&lt;/upnp:class&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;</Metadata >
</u:SetSender >

:4:src/mpdcli.cxx:809::MPDCli::getQueueData
:4:src/mpdcli.cxx:794::MPDCli::getQueueSongs: 0 songs
:4:src/mpdcli.cxx:570::MPDCli::stop
:4:src/ohreceiver.cxx:156::OHReceiver::play: executing /usr/bin/sc2mpd
:4:src/execmd-fixed.cpp:454::ExecCmd::startExec: (0|1) /usr/bin/sc2mpd {-u} {ohz://239.255.255.250:51972/575e95641e7106b60cf76e91ebc94919} {-c} {/etc/upmpdcli.conf}
:4:src/ohreceiver.cxx:163::OHReceiver::play: sc2mpd pid 1307
:4:src/mpdcli.cxx:570::MPDCli::stop
:3:sc2src/sc2mpd.cpp:545::scmpdcli: using subnet 192.168.178.0
LATENCY 326
:2:src/ohreceiver.cxx:175::OHReceiver: mpd mode: sc2mpd still not ready to play after 15 seconds
:4:src/ohreceiver.cxx:290::OHReceiver::setSender
:4:src/ohreceiver.cxx:231::OHReceiver::iStop()
:4:src/execmd-fixed.cpp:274::ExecCmd: killpg(1307, SIGTERM)
:4:libupnpp/device/device.cxx:318::UPNP_CONTROL_ACTION_REQUEST: SetSourceIndex. Params: <?xml version="1.0"? >
<u:SetSourceIndex xmlns:u="urn:av-openhome-org:service:Product:1" >
<Value >1</Value >
</u:SetSourceIndex >

:4:src/mpdcli.cxx:570::MPDCli::stop
:4:src/ohplaylist.cxx:744::OHPlaylist::idArray (internal)
:4:src/ohplaylist.cxx:747::OHPlaylist::idArray: qvers 55
:4:src/ohproduct.cxx:311::OHProduct::setSourceIndex
:4:src/ohproduct.cxx:244::OHProduct::iSetSourceIndex: current 1 new 1

medoc92 writes

Are you using scplaymethod mpd or alsa ?

joerg-krause writes

I used unintentionally the mpd method. However, if I switch to alsa it does not work ether. The playback continues after pressing the stop button. This is the log message for the alsa message:

:4:libupnpp/device/device.cxx:318::UPNP_CONTROL_ACTION_REQUEST: Stop. Params: <?xml version="1.0"? >
<u:Stop xmlns:u="urn:av-openhome-org:service:Receiver:1" ></u:Stop >

:4:src/ohreceiver.cxx:256::OHReceiver::stop
:4:src/ohreceiver.cxx:231::OHReceiver::iStop()
:4:src/ohproduct.cxx:321::OHProduct::iSetSourceIndexByName: Playlist
:4:src/ohproduct.cxx:244::OHProduct::iSetSourceIndex: current 0 new 0

medoc92 writes

It’s weird, the sc2cmd process should be killed after the iStop() trace. Here is what I get:

`:4:src/ohreceiver.cxx:256::OHReceiver::stop :4:src/ohreceiver.cxx:231::OHReceiver::iStop() :4:src/execmd-fixed.cpp:274::ExecCmd: killpg(27473, SIGTERM) :4:src/ohproduct.cxx:321::OHProduct::iSetSourceIndexByName: Playlist ` I have no idea what may cause the difference, looking at the code, the process should always be killed… Except if the getpgid() call in execmd.cpp at line 273 fails. I have a note in the code that this sometimes happen, but I actually have no idea why if the process exists, which is the case here.

Maybe add a trace before this line:

----` diff --git a/src/execmd.cpp b/src/execmd.cpp index c27eeae..6a32aab 100644 --- a/src/execmd.cpp + b/src/execmd.cpp @@ -270,6 +270,8 @@ public: // not exist. Not too sure what causes this, but the previous code // definitely tried to call killpg(-1,) from time to time. pid_t grp; + LOGDEB("ExecCmd: before kill: pid " << m_parent- >m_pid << " grp " << + getpgid(m_parent- >m_pid) << endl); if (m_parent- >m_pid > 0 && (grp = getpgid(m_parent- >m_pid)) > 0) { LOGDEB("ExecCmd: killpg(" << (grp) << ", SIGTERM)\n"); int ret = killpg(grp, SIGTERM);

----`

And here is how it looks for me then:

----` :4:libupnpp/device/device.cxx:318::UPNP_CONTROL_ACTION_REQUEST: Stop. Params: <?xml version="1.0"? > <u:Stop xmlns:u="urn:av-openhome-org:service:Receiver:1" ></u:Stop >

:4:/y/home/dockes/projets/mpdupnp/upmpdcli/src/ohreceiver.cxx:256::OHReceiver::stop :4:/y/home/dockes/projets/mpdupnp/upmpdcli/src/ohreceiver.cxx:231::OHReceiver::iStop() :4:src/execmd-fixed.cpp:274::ExecCmd: before kill: pid 28040 grp 28040 :4:src/execmd-fixed.cpp:276::ExecCmd: killpg(28040, SIGTERM) :4:src/execmd-fixed.cpp:274::ExecCmd: before kill: pid -1 grp -1 :4:/y/home/dockes/projets/mpdupnp/upmpdcli/src/ohproduct.cxx:321::OHProduct::iSetSourceIndexByName: Playlist

----`

The second line (pid -1) is probably for an empty object, but the process (28040) does get killed.

joerg-krause writes

Turns out, it was an issue with an ALSA plugin hook which I’m using to toggle a GPIO. As upmpdcli runs as non-root, the plugin failed to access the GPIOs, but instead of returning the error to ALSA properly, it exited, making ALSA unresponsive.

Sorry for the noise!