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 ><DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/"><item id="0" restricted="True"><dc:title>WIN7PRO</dc:title><res protocolInfo="ohz:*:*:u">ohz://239.255.255.250:51972/575e95641e7106b60cf76e91ebc94919</res><upnp:class>object.item.audioItem</upnp:class></item></DIDL-Lite></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 1medoc92 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 0medoc92 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!