search

masmu / pulseaudio-dlna

A lightweight streaming server which brings DLNA / UPNP and Chromecast support to PulseAudio and Linux
GNU General Public License v3.0
1.25k stars 162 forks source link

closing pavucontrol stops playback #77

Closed rommon closed 9 years ago

rommon commented 9 years ago

I open pavucontrol to select the audio device for the application (e.g. Spotify client). When I close pavucontrol the stream immediately stops and is not coming back when reopening pavucontrol.

masmu commented 9 years ago

That sounds like a bug in your OS. Closing pavucontrol should not have any influence at all.

What does say the pulseaudio-dlna log when you close it?

rommon commented 9 years ago

I am using Fedora 22 KDE 64 Bit with disabled firewalld. It is not printing something directly after closing. After it switched switched to local audio it prints:

08-26 20:05:39 pulseaudio_dlna.streamserver                   INFO     Client 192.168.2.42 unregistered stream /192168242sonosplay3_dlna.flac using method 2.
08-26 20:05:39 pulseaudio_dlna.streamserver                   DEBUG    Socket died, releasing request thread.
08-26 20:05:41 pulseaudio_dlna.streamserver                   INFO     Stream closed. Cleaning up remaining processes ...
08-26 20:05:41 pulseaudio_dlna.streamserver                   INFO     Device "192.168.2.42 - Sonos PLAY:3" disconnected.
08-26 20:05:41 pulseaudio_dlna.pulseaudio                     INFO     on_device_updated "/org/pulseaudio/core1/sink0"
08-26 20:05:42 pulseaudio_dlna.pulseaudio                     INFO     _handle_sink_update /org/pulseaudio/core1/sink0
rommon commented 9 years ago

this log is to a pioneer VSX-930

08-26 20:12:11 pulseaudio_dlna.pulseaudio                     INFO     on_device_updated "/org/pulseaudio/core1/sink76"
08-26 20:12:12 pulseaudio_dlna.pulseaudio                     INFO     _handle_sink_update /org/pulseaudio/core1/sink76
08-26 20:12:12 pulseaudio_dlna.pulseaudio                     DEBUG    
<Bridge>
    <PulseSink path="/org/pulseaudio/core1/sink73" label="max2play-dlna (DLNA)" name="max2playdlna_dlna" index="73" module="99">
        -- no streams --
    <CoinedUpnpMediaRenderer name="max2play-dlna" short="max2playdlna_dlna" state="idle" protocols="audio/x-private1-dts,audio/x-private1-lpcm,audio/x-wav,audio/x-amr-wb-sh,audio/x-amr-nb-sh,audio/x-vgm,audio/x-spc,audio/x-sap,audio/x-kss,audio/x-hes,audio/x-gym,audio/x-gbs,audio/x-ay,audio/riff-midi,audio/midi,audio/mp4,audio/m4a,audio/x-m4a,audio/x-stm,audio/x-s3m,audio/x-it,audio/x-xm,audio/x-mod,audio/x-iec958,audio/x-lpcm,audio/x-private1-ac3,audio/x-nsf,audio/x-wavpack-correction,audio/x-wavpack,audio/x-sid,audio/ac3,audio/x-bv,audio/x-celt,audio/x-iLBC,audio/G723,audio/G729,audio/x-siren,audio/alac,audio/x-alac,audio/x-ffmpeg-parsed-ape,audio/x-vnd.sony.atrac1,audio/x-gsm,audio/ms-gsm,audio/x-imc,audio/x-mlp,audio/x-gst_ff-mp3adu,audio/x-gst_ff-mp3on4,audio/x-ffmpeg-parsed-musepack,audio/x-nellymoser,audio/qcelp,audio/x-qdm2,audio/x-shorten,audio/x-sipro,audio/x-true-hd,audio/x-truespeech,audio/x-twin-vq,audio/x-gst_ff-vmdaudio,audio/x-wms,audio/x-gst_ff-ws_snd1,audio/x-dpcm,audio/G722,audio/aiff,audio/x-aiff,audio/x-musepack,audio/x-mace,audio/x-vnd.sony.atrac3,audio/AMR,audio/x-adpcm,audio/x-alaw,audio/x-wma,audio/x-pn-realaudio,audio/x-speex,audio/x-flac,audio/x-dts,audio/x-eac3,audio/x-ac3,audio/x-mulaw,audio/x-vorbis,audio/x-opus,audio/AMR-WB,audio/L16;rate=44100;channels=2,audio/x-scpls,audio/x-mpeg,audio/mpeg,audio/x-au,audio/x-ttafile,audio/x-tta,audio/x-raw-int,audio/x-raw-float,audio/*">

08-26 20:12:12 pulseaudio_dlna.pulseaudio                     DEBUG    
<Bridge>
    <PulseSink path="/org/pulseaudio/core1/sink74" label="Roms CC (Chromecast)" name="romscc_chromecast" index="74" module="100">
        -- no streams --
    <CoinedChromecastRenderer name="Roms CC" short="romscc_chromecast" state="idle" protocols="audio/mp3,audio/mp4,audio/ogg,audio/wav">

08-26 20:12:12 pulseaudio_dlna.pulseaudio                     DEBUG    
<Bridge>
    <PulseSink path="/org/pulseaudio/core1/sink75" label="192.168.2.42 - Sonos PLAY:3 (DLNA)" name="192168242sonosplay3_dlna" index="75" module="101">
        -- no streams --
    <CoinedUpnpMediaRenderer name="192.168.2.42 - Sonos PLAY:3" short="192168242sonosplay3_dlna" state="idle" protocols="audio/mp3,audio/mp4,audio/mpeg,audio/mpegurl,audio/mpeg3,audio/wav,audio/wma,audio/x-ms-wma,audio/aiff,audio/flac,audio/audible,audio/x-spotify,audio/x-sonos-recent,audio/x-rhap-radio,audio/x-pandora-radio,audio/x-sirius-radio,audio/x-sonosapi-radio,audio/x-sonosapi-iqradio,audio/x-lastfm-radio">

08-26 20:12:12 pulseaudio_dlna.pulseaudio                     DEBUG    
<Bridge>
    <PulseSink path="/org/pulseaudio/core1/sink76" label="VSX-930 (DLNA)" name="vsx930_dlna.2" index="76" module="102">
        <PulseStream path="/org/pulseaudio/core1/playback_stream0" device="/org/pulseaudio/core1/sink76" index="0">

    <CoinedUpnpMediaRenderer name="VSX-930" short="vsx930_dlna" state="idle" protocols="audio/L16;rate=44100;channels=1,audio/L16;rate=44100;channels=2,audio/L16;rate=48000;channels=1,audio/L16;rate=48000;channels=2,audio/mpeg,audio/vnd.dlna.adts,audio/mp4,audio/3gpp,audio/x-ms-wma,audio/wav,audio/x-wav,audio/flac,audio/x-flac,audio/m4a,audio/x-m4a,audio/x-caf,audio/x-aiff,audio/aiff,audio/dsd,audio/x-dsd">

08-26 20:12:12 pulseaudio_dlna.pulseaudio                     INFO     Instructing the device "VSX-930 (DLNA)" to play ...
08-26 20:12:12 requests.packages.urllib3.connectionpool       INFO     Starting new HTTP connection (1): 192.168.2.51
08-26 20:12:12 requests.packages.urllib3.connectionpool       DEBUG    "POST /AVTransport/ctrl HTTP/1.1" 200 288
08-26 20:12:12 pulseaudio_dlna.plugins.upnp.renderer          DEBUG    sending REGISTER to http://192.168.2.51:8080/AVTransport/ctrl:
 - headers:
{u'SOAPAction': u'"urn:schemas-upnp-org:service:AVTransport:1#SetAVTransportURI"', u'Content-Type': u'text/xml; charset="utf-8"'}
 - data:
<?xml version="1.0" encoding="utf-8" standalone="yes"?>
<s:Envelope s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/" xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">
    <s:Body>
        <u:SetAVTransportURI xmlns:u="urn:schemas-upnp-org:service:AVTransport:1">
            <InstanceID>0</InstanceID>
            <CurrentURI>http://192.168.2.69:8080/vsx930_dlna.flac</CurrentURI>
            <CurrentURIMetaData>&lt;?xml version="1.0" encoding="utf-8"?&gt;
&lt;DIDL-Lite xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/" 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/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/"&gt;
    &lt;item id="0" parentID="0" restricted="1"&gt;
        &lt;upnp:class&gt;object.item.audioItem.musicTrack&lt;/upnp:class&gt;
        &lt;dc:title&gt;Live Audio&lt;/dc:title&gt;
        &lt;dc:creator&gt;PulseAudio&lt;/dc:creator&gt;
        &lt;upnp:artist&gt;PulseAudio on i5&lt;/upnp:artist&gt;
        &lt;upnp:albumArtURI&gt;&lt;/upnp:albumArtURI&gt;
        &lt;upnp:album&gt;Stream&lt;/upnp:album&gt;
        &lt;res protocolInfo="http-get:*:audio/flac:DLNA.ORG_OP=00;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=01700000000000000000000000000000"&gt;http://192.168.2.69:8080/vsx930_dlna.flac&lt;/res&gt;
    &lt;/item&gt;
&lt;/DIDL-Lite&gt;
</CurrentURIMetaData>
        </u:SetAVTransportURI>
    </s:Body>
</s:Envelope>
 - result: 200
<s:Envelope
                xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"
                s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
        <s:Body>
                <u:SetAVTransportURIResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1">
                </u:SetAVTransportURIResponse>
        </s:Body>
</s:Envelope>
08-26 20:12:12 requests.packages.urllib3.connectionpool       INFO     Starting new HTTP connection (1): 192.168.2.51
08-26 20:12:12 requests.packages.urllib3.connectionpool       DEBUG    "POST /AVTransport/ctrl HTTP/1.1" 200 262
08-26 20:12:12 pulseaudio_dlna.plugins.upnp.renderer          DEBUG    sending PLAY to http://192.168.2.51:8080/AVTransport/ctrl:
 - headers:
{u'SOAPAction': u'"urn:schemas-upnp-org:service:AVTransport:1#Play"', u'Content-Type': u'text/xml; charset="utf-8"'}
 - data:
<?xml version="1.0" encoding="utf-8" standalone="yes"?>
<s:Envelope s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/" xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">
    <s:Body>
        <u:Play xmlns:u="urn:schemas-upnp-org:service:AVTransport:1">
            <InstanceID>0</InstanceID>
            <Speed>1</Speed>
        </u:Play>
    </s:Body>
</s:Envelope>
 - result: 200
<s:Envelope
                xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"
                s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
        <s:Body>
                <u:PlayResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1">
                </u:PlayResponse>
        </s:Body>
</s:Envelope>
08-26 20:12:12 pulseaudio_dlna.pulseaudio                     INFO     The device "VSX-930 (DLNA)" is playing.
08-26 20:12:12 pulseaudio_dlna.streamserver                   DEBUG    Got the following GET request:
[
  [
    "connection", 
    "close"
  ], 
  [
    "accept", 
    "*/*"
  ], 
  [
    "user-agent", 
    "WinampMPEG/2.8"
  ], 
  [
    "host", 
    "192.168.2.69:8080"
  ], 
  [
    "icy-metadata", 
    "1"
  ], 
  [
    "transfermode.dlna.org", 
    "Streaming"
  ]
]
08-26 20:12:12 pulseaudio_dlna.streamserver                   INFO     Requested streaming URL was: /vsx930_dlna.flac (HTTP/1.1)
08-26 20:12:12 pulseaudio_dlna.streamserver                   INFO     Got request from 192.168.2.51 - GET /vsx930_dlna.flac HTTP/1.1,200,-
08-26 20:12:12 pulseaudio_dlna.streamserver                   DEBUG    Sending header:
{
  "transferMode.dlna.org": "Streaming", 
  "Content-Length": 107374182400, 
  "Content-Type": "audio/flac", 
  "Ext": "", 
  "contentFeatures.dlna.org": "DLNA.ORG_OP=00;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=01700000000000000000000000000000"
}
08-26 20:12:12 pulseaudio_dlna.streamserver                   INFO     Client 192.168.2.51 registered to stream /vsx930_dlna.flac.
08-26 20:12:12 pulseaudio_dlna.streamserver                   DEBUG    Starting processes "parec --format=s16le -d vsx930_dlna.2.monitor | flac - -c --channels 2 --bps 16 --sample-rate 44100 --endian little --sign signed -s"
08-26 20:12:12 pulseaudio_dlna.streamserver                   INFO     Processes of /vsx930_dlna.flac initialized ...
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:53 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:54 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:54 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:54 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:54 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:54 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:54 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:54 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:54 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:54 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:54 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:54 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:54 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:54 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:54 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:54 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:54 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-26 20:12:54 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
rommon commented 9 years ago

I also have to close pa-dlna and restart it to get it working again.

masmu commented 9 years ago

But it is working in the first place?

When exactly did you close pavucontrol?

rommon commented 9 years ago

shortly before 08-26 20:12:53 I stopped pavucontrol. It was working until I close pavucontrol

is there an other way to switch the sinks for an application?

masmu commented 9 years ago

Yes by commandline. man pactl

rommon commented 9 years ago

with pactl I can switch back and forth without any problems (ogg).

With other local sound cards like USB speaker or USB headset I didn't see such a problem with pavucontrol.

I just tested wav with sonos and the cli switching. Sonos is just making one noise and than it switches back to local sound. With pavucontrol open it smoothly plays wav.

I will test everything tomorrow with Debian Jessie, lets see if it behaves differently.

rommon commented 9 years ago

just tested it with debian jessie, everything works well. It really is a problem of Fedora 22 KDE 64Bit.

masmu commented 9 years ago

Good for me :wink: The fedora pavucontrol must change some stream or sink properties when closing.

But there is one thing in your log, which got my in attention. Those many Read data from socket lines... Normally when you can read from a socket but the length of the recieved data is zero you should close the connection. But I removed that part some time ago...

rommon commented 9 years ago

I figured out that it was a problem of the spotify client. Sorry. I also tested it now with vlc and it works.

masmu commented 9 years ago

I am using spotify myself. Whats the problem with the client?

masmu commented 9 years ago

If you want you can try the sound-vanishes branch. It has a few new fixes and it will close the connection when recieving 0 bytes from the client.

rommon commented 9 years ago

I have no idea what the problem of spotify is. I am using _spotify-client-1.0.11.131.gf4d47cb0-1.fc22.x8664 .

The sound-vanishes branch is not solving the problem, but the whole systems feels more robust.

When streaming Spotify to Sonos to pa-dlna and closing pavucontrol it seams to work now (but I tested it before and it "crashed" too) (maybe it has something to do with timing? need to test it a little bit more)

With the VSX-930 it results in the following:

08-27 21:08:50 pulseaudio_dlna.streamserver                   INFO     Processes of /vsx930_dlna.flac initialized ...
08-27 21:08:53 pulseaudio_dlna.plugins.upnp.renderer          ERROR    Could no connect to http://192.168.2.42:1400/MediaRenderer/AVTransport/Control. Connection timeout.
08-27 21:08:53 pulseaudio_dlna.pulseaudio                     ERROR    The device "192.168.2.42 - Sonos PLAY:3 (DLNA)" failed to stop!
08-27 21:09:44 pulseaudio_dlna.streamserver                   INFO     Client 192.168.2.51 unregistered stream /vsx930_dlna.flac using method 2.
08-27 21:09:45 pulseaudio_dlna.streamserver                   DEBUG    Socket died, releasing request thread.
08-27 21:09:46 pulseaudio_dlna.streamserver                   INFO     Stream closed. Cleaning up remaining processes ...
08-27 21:09:46 pulseaudio_dlna.streamserver                   INFO     Device "VSX-930" disconnected.

second try

08-27 21:14:05 pulseaudio_dlna.streamserver                   INFO     Processes of /vsx930_dlna.flac reinitialized ...
08-27 21:15:43 pulseaudio_dlna.streamserver                   INFO     Read data from socket ""
08-27 21:15:43 pulseaudio_dlna.streamserver                   INFO     Client 192.168.2.51 unregistered stream /vsx930_dlna.flac using method 3.
08-27 21:15:43 pulseaudio_dlna.streamserver                   DEBUG    Socket died, releasing request thread.
08-27 21:15:45 pulseaudio_dlna.streamserver                   INFO     Stream closed. Cleaning up remaining processes ...
08-27 21:15:45 pulseaudio_dlna.streamserver                   INFO     Device "VSX-930" disconnected.
enyone commented 9 years ago

This happens also for me so you are not alone :) It is somehow related to spotify-pavucontrol-parec combination, not pulseaudio-dlna itself. Of course parec is used by pulseaudio-dlna.

Linux Mint 17.2
Linux rnetl34 3.13.0-37-generic #64-Ubuntu SMP Mon Sep 22 21:28:38 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux
Spotify version 1.0.11.131.gf4d47cb0
pulseaudio 4.0
masmu commented 9 years ago

I am still using spotify 0.9.17.1.g9b85d436 and pulseaudio 4.0.

@rommon This is odd.

08-27 21:08:53 pulseaudio_dlna.plugins.upnp.renderer          ERROR    Could no connect to http://192.168.2.42:1400/MediaRenderer/AVTransport/Control. Connection timeout.

means that the HTTP request which normally sends the PLAY or STOP command timed out. There is nothing what i can do about that. Do you have a very complicated or slow network? The timeout is about 3 seconds. Should be more than enough in a LAN for a HTTP request.

rommon commented 9 years ago

I think whatever happens is not showing in the logs.

Somehow it seams to work with the mp3 encoder. I can close pavucontrol without any problem.

masmu commented 9 years ago

Closed due to inactivity.