Sonos-Devices can't be found, after fix sound distored about pulseaudio-dlna

[masmu]

Yes, i need additional log output. I placed a special log in a branch regarding that problem.

What you can do is:

• Use git to test the branch:

  git clone https://github.com/masmu/pulseaudio-dlna.git
  cd pulseaudio-dlna/
  git checkout bug/reliable-discovery
  make
  bin/pulseaudio-dlna --debug 2>&1 | tee -a debug.log

  (You will need the python-dev package and the virtualenv binary installed on your system.)

• Or change discover.py manually:
  Basically you just need to add that commit to your discover.py. Instead of editing you also can replace the discovery.py of your installation with that one.

  pulseaudio-dlna --debug 2>&1 | tee -a debug.log
  

[linuxundich]

Here you go... http://pastebin.com/U7UyAcGj

[masmu]

Thank you! I think I found the problem.

Could you test it by replacing the renderers.py with that one? (commit)

If you went for the git way:

cd pulseaudio-dlna/
git pull
bin/pulseaudio-dlna --debug 2>&1 | tee -a debug.log

[linuxundich]

Hi Massimo, the discovery works again, but as with version 0.3.5, i can't stream to my sonos devices. After a short moment PulseAudio-DLNA switches back to internal audio.

08-12 09:44:55 pulseaudio_dlna.plugins.chromecast.renderer    INFO     The Chromecast seems not to be an original Chromecast! Model name: "FireTV" Skipping device ...
08-12 09:44:56 pulseaudio_dlna.plugins.chromecast.renderer    INFO     The Chromecast seems not to be an original Chromecast! Model name: "FireTV" Skipping device ...
08-12 09:45:01 pulseaudio_dlna.listener                       INFO     Discovery complete.
08-12 09:45:02 pulseaudio_dlna.pulseaudio                     INFO     Added the device "192.168.178.58 - Sonos PLAY:3 (DLNA)".
08-12 09:45:02 pulseaudio_dlna.pulseaudio                     INFO     Added the device "192.168.178.43 - Sonos CONNECT:AMP (DLNA)".
08-12 09:45:03 pulseaudio_dlna.pulseaudio                     INFO     Added the device "192.168.178.42 - Sonos PLAY:3 (DLNA)".
08-12 09:46:23 pulseaudio_dlna.pulseaudio                     INFO     on_new_playback_stream "/org/pulseaudio/core1/playback_stream5"
08-12 09:46:23 pulseaudio_dlna.pulseaudio                     INFO     on_playback_stream_removed "/org/pulseaudio/core1/playback_stream5"
08-12 09:46:23 pulseaudio_dlna.pulseaudio                     INFO     on_new_playback_stream "/org/pulseaudio/core1/playback_stream6"
08-12 09:46:24 pulseaudio_dlna.pulseaudio                     INFO     _handle_sink_update /org/pulseaudio/core1/sink0
08-12 09:46:29 pulseaudio_dlna.pulseaudio                     INFO     on_new_playback_stream "/org/pulseaudio/core1/playback_stream7"
08-12 09:46:29 pulseaudio_dlna.pulseaudio                     INFO     on_playback_stream_removed "/org/pulseaudio/core1/playback_stream7"
08-12 09:46:29 pulseaudio_dlna.pulseaudio                     INFO     _handle_sink_update /org/pulseaudio/core1/sink0
08-12 09:46:29 pulseaudio_dlna.pulseaudio                     INFO     on_new_playback_stream "/org/pulseaudio/core1/playback_stream8"
08-12 09:46:29 pulseaudio_dlna.pulseaudio                     INFO     on_playback_stream_removed "/org/pulseaudio/core1/playback_stream8"
08-12 09:46:30 pulseaudio_dlna.pulseaudio                     INFO     _handle_sink_update /org/pulseaudio/core1/sink0
08-12 09:46:30 pulseaudio_dlna.pulseaudio                     INFO     on_new_playback_stream "/org/pulseaudio/core1/playback_stream9"
08-12 09:46:30 pulseaudio_dlna.pulseaudio                     INFO     on_playback_stream_removed "/org/pulseaudio/core1/playback_stream9"
08-12 09:46:31 pulseaudio_dlna.pulseaudio                     INFO     _handle_sink_update /org/pulseaudio/core1/sink0
08-12 09:46:41 pulseaudio_dlna.pulseaudio                     INFO     on_device_updated "/org/pulseaudio/core1/sink2"
08-12 09:46:42 pulseaudio_dlna.pulseaudio                     INFO     _handle_sink_update /org/pulseaudio/core1/sink2
08-12 09:46:42 pulseaudio_dlna.pulseaudio                     INFO     Instructing the device "192.168.178.43 - Sonos CONNECT:AMP (DLNA)" to play ...
08-12 09:46:42 pulseaudio_dlna.pulseaudio                     INFO     The device "192.168.178.43 - Sonos CONNECT:AMP (DLNA)" is playing.
08-12 09:46:42 pulseaudio_dlna.streamserver                   INFO     Requested streaming URL was: /19216817843sonosconnectamp_dlna.mp3 (HTTP/1.1)
08-12 09:46:42 pulseaudio_dlna.streamserver                   INFO     Got request from SonosZP.fritz.box - GET /19216817843sonosconnectamp_dlna.mp3 HTTP/1.1,200,-
08-12 09:46:42 pulseaudio_dlna.streamserver                   INFO     Client 192.168.178.43 registered to stream /19216817843sonosconnectamp_dlna.mp3.
08-12 09:46:42 pulseaudio_dlna.streamserver                   INFO     Processes of /19216817843sonosconnectamp_dlna.mp3 initialized ...
08-12 09:46:43 pulseaudio_dlna.streamserver                   INFO     Requested streaming URL was: /19216817843sonosconnectamp_dlna.mp3 (HTTP/1.1)
08-12 09:46:43 pulseaudio_dlna.streamserver                   INFO     Got request from SonosZP.fritz.box - HEAD /19216817843sonosconnectamp_dlna.mp3 HTTP/1.1,200,-
08-12 09:46:43 pulseaudio_dlna.streamserver                   INFO     Client 192.168.178.43 unregistered stream /19216817843sonosconnectamp_dlna.mp3 using method 2.
08-12 09:46:45 pulseaudio_dlna.streamserver                   INFO     Stream closed. Cleaning up remaining processes ...
08-12 09:46:45 pulseaudio_dlna.streamserver                   INFO     Device "192.168.178.43 - Sonos CONNECT:AMP" disconnected.
08-12 09:46:45 pulseaudio_dlna.pulseaudio                     INFO     on_device_updated "/org/pulseaudio/core1/sink0"
08-12 09:46:46 pulseaudio_dlna.pulseaudio                     INFO     _handle_sink_update /org/pulseaudio/core1/sink0
08-12 09:46:46 pulseaudio_dlna.pulseaudio                     INFO     Instructing the device "192.168.178.43 - Sonos CONNECT:AMP (DLNA)" to stop ...
08-12 09:46:46 pulseaudio_dlna.pulseaudio                     INFO     The device "192.168.178.43 - Sonos CONNECT:AMP (DLNA)" was stopped.
08-12 09:46:50 pulseaudio_dlna.pulseaudio                     INFO     on_device_updated "/org/pulseaudio/core1/sink3"
08-12 09:46:51 pulseaudio_dlna.pulseaudio                     INFO     _handle_sink_update /org/pulseaudio/core1/sink3
08-12 09:46:51 pulseaudio_dlna.pulseaudio                     INFO     Instructing the device "192.168.178.42 - Sonos PLAY:3 (DLNA)" to play ...
08-12 09:46:51 pulseaudio_dlna.pulseaudio                     INFO     The device "192.168.178.42 - Sonos PLAY:3 (DLNA)" is playing.
08-12 09:46:51 pulseaudio_dlna.streamserver                   INFO     Requested streaming URL was: /19216817842sonosplay3_dlna.mp3 (HTTP/1.1)
08-12 09:46:51 pulseaudio_dlna.streamserver                   INFO     Got request from SonosZP.fritz.box - GET /19216817842sonosplay3_dlna.mp3 HTTP/1.1,200,-
08-12 09:46:51 pulseaudio_dlna.streamserver                   INFO     Client 192.168.178.42 registered to stream /19216817842sonosplay3_dlna.mp3.
08-12 09:46:51 pulseaudio_dlna.streamserver                   INFO     Processes of /19216817842sonosplay3_dlna.mp3 initialized ...
08-12 09:46:52 pulseaudio_dlna.streamserver                   INFO     Requested streaming URL was: /19216817842sonosplay3_dlna.mp3 (HTTP/1.1)
08-12 09:46:52 pulseaudio_dlna.streamserver                   INFO     Got request from SonosZP.fritz.box - HEAD /19216817842sonosplay3_dlna.mp3 HTTP/1.1,200,-
08-12 09:46:52 pulseaudio_dlna.streamserver                   INFO     Client 192.168.178.42 unregistered stream /19216817842sonosplay3_dlna.mp3 using method 2.
08-12 09:46:54 pulseaudio_dlna.streamserver                   INFO     Stream closed. Cleaning up remaining processes ...
08-12 09:46:54 pulseaudio_dlna.streamserver                   INFO     Device "192.168.178.42 - Sonos PLAY:3" disconnected.
08-12 09:46:55 pulseaudio_dlna.pulseaudio                     INFO     on_device_updated "/org/pulseaudio/core1/sink0"
08-12 09:46:55 pulseaudio_dlna.pulseaudio                     INFO     _handle_sink_update /org/pulseaudio/core1/sink0
08-12 09:46:55 pulseaudio_dlna.pulseaudio                     INFO     Instructing the device "192.168.178.42 - Sonos PLAY:3 (DLNA)" to stop ...
08-12 09:46:55 pulseaudio_dlna.pulseaudio                     INFO     The device "192.168.178.42 - Sonos PLAY:3 (DLNA)" was stopped.

[masmu]

From what i can see, everything looks ok. Its just, that the device refuses to play the actual stream content and therefore it terminates the connection.

I compared both code states, the one which was reported to be working and the current one for major differences, but they are not that different.

Could you replace your streamserver.py with that one. (commit)

After that please paste a debug.log with the --debug flag.

[linuxundich]

OK, here's the log... http://pastebin.com/QgwBUrSu

[masmu]

It seems as Sonos devices in general have issues with the lame encoder.

Those two encoders were reported to be working:

bin/pulseaudio-dlna --encoder wav
bin/pulseaudio-dlna --encoder flac

Could you give them a try?

[linuxundich]

Hi Massimo, that works... in a way. When i switch to wav or flac, i get sound, but it's very scrambled. Here's an example: The first secons are with "pulseaudio-dlna --encoder wav", after 12 secons i quit pulseaudio-dlna and you here my internal speakers... https://dl.dropboxusercontent.com/u/107860/Audio-Aufnahme-2015-08-16%2019-29-08.wav

[masmu]

I can reproduce that behaviour using the flac encoder.

The scrambling is a result of the used encoder to adjust to volume changes.
Try to pause / resume the playback. Also setting the volumes helps. I recommend to set the volume of the stream always to 100% and just change the actual volume of the device using the hardware buttons or the android app.
I looked into that type of issue before and until now i have no idea to fix this.
There is a parec option which allows to set the initial volume, but this has just an effect on the first stream which is created. And it would not permit the user to change the volume himself.
To really fix that problem with flac the stream volume has to be on a constant level all the time.

There are encoders which handle volume changes very well or much better than the flac encoder. Such as lame or wav.

I took a look on how commercial products like the android app AirAudio does it. It turned out that despite Sonos devices are DLNA certified they are not handled as generic DLNA devices by that application.
They are handled as "Sonos Devices". In the options of the application you can choose the encoder for DLNA devices, but not for Sonos ones.
And if you sniff the network traffic you see, that they are also using wav as codec.

But the wav encoder is working fine here. Could you give him another try?

[linuxundich]

I get the scrambled sound with flac and wav. But with wav, when i change the volume of the stream a little bit, the distortions go away and the sound is fine. Thanks for your work!

[rommon]

I have exactly the same problem with my Sonos Play3. The described way is solving the issues for me too. I can also confirm the the scrambled audio and that changing the volume temporarily solves this issue; annoying.

Thanks.

[rommon]

I am currently testing it over and over again with wav encoder. It looks like the sound changing way is not reliable fixing the distortion. It can happen that in the "middle" of the song the distortion starts again. Also after a while of playing the distorted audio pulseaudio is switching back to local audio.

I am using spotify on my fedora machine for music playing.

[masmu]

I just pushed some new code to this branch. If you use the --fake-http-content-length option the mp3 encoder will work. Could you both test this please?

Replace

• __main__.py with that one
• application.py with that one
• streamserver.py with that one

I had no issues with distortion, but the delay is much longer than with wav.
I have almost no delay with wav, but a 5-6 seconds delay with mp3. Connected via cable.

[masmu]

If you also replace the following files, also ogg will work. But it has the same delay as mp3 and you also have to specify the --fake-http-content-length option.

• plugins/upnp/renderer.py with that one
• encoders.py with that one

I am currently asking the Sonos devs why wav and flac work without the flag, but it is needed for mp3 and ogg. Lets see what they say ...

[rommon]

I am now using the code in the master branch. I can confirm that mp3 and ogg has no scrambled audio. There is indeed a delay of about 5 seconds until playback starts at the sonos device.

I also tried it again with flac. now it seams to work (with --fake-http-content-length). I didn't change the volume of the device. At some point it stops playback, but maybe that is because my laptop is connected through Wi-Fi. The delay until playback is about 500ms - 1s.

[rommon]

I tested it with flac and without --fake-http-content-length. With these settings the scrambled audio is happening. After that I put in the fake option again and it worked again, but the sound often stops. After some tries it works like a charm.

[masmu]

What does mean "at some point"? Are we talking about minutes, hours?
How often does this happen? Does is happen on a regular basis?

I am that curious because another user reported sudden disconnects, but i am not experiencing them at all. But everything here is connected via cable...

[rommon]

there are no fixed times. sometimes it is immediately after switching to Sonos. Currently it is already playing for about 20 min. So I guess it may really be the Wi-Fi connection, not sure why because I am only setting 3 meters away.

I tested some more with flac and the delay is about 2-3 seconds.

[masmu]

This release also contains some automatic rules for Sonos devices so that the --fake-http-content-length option is not needed any more.

• 0.4.5 - (2015-09-20)
  • Exceptions while updating sink and device information from pulseaudio are now handled better
  • Changed --fake-http10-content-length flag to --fake-http-content-length to also support HTTP 1.1 requests
  • Fixed a bug where the supported device mime types could not get parsed correctly
  • Fixed a bug where the device UUID was not parsed correctly
  • Fixed a bug where just mime types beginning with audio/ where accepted, but not e.g. application/ogg
  • The stream server will now respond with 206 when receiving requests with range header
  • UPNP control commands have now a timeout of 10 seconds
  • Fixed a bug where the wrong stream was removed from the stream manager
  • Fixed several bugs caused by purely relying on stopping actions for the devices idle state
  • Added L16 Encoder
  • The encoder option can now handle multiple options separated by comma
  • Added the --create-device-config flag
  • Fixed a bug where the dbus session was bound from the wrong process
  • Fix a bug where the wrong device UDN was retrieved from XML documents containing multiple devices