Autoresume not working with BubbleUPNP and Nest Audio

Silun commented 3 years ago

I use this chain to play audio:

Audio Player -> VB-Audio Virtual HiFi Cable -> SWYH-RS -> BubbleUPNP (DLNA mode) -> Google Nest Audio Stereo Pair

When swyh-rs is started, it works correctly and audio plays just like it should. However, after about ~20 minutes of having no music playing in my audio player, something breaks and there will be no more sound coming from my speakers. In fact, the debug log generates no entry at all for when audio is resumed after that time, so I added something manually.

swyh-rs is configured like so:

Autoresume is enabled
Autoreconnect is enabled
SSDP is at 10 minutes, but same issue existed with it at 1 minute
Disable Chunked TransferEncoding is disabled
Source is Hi-Fi Cable Input
Output is BubbleUPNP

This is the debug log, generated with the standard version and log level set to debug.

17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices: Supported hosts:
  [Wasapi]
17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices: Available hosts:
  [Wasapi]
17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices: WASAPI
17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices:   Default Output Device:
    Some("Soundkarte (ASUS Xonar D2X Audio Device)")
17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices:   Devices: 
17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices:   1. "Hi-Fi Cable Input (VB-Audio Hi-Fi Cable)"
17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices:     All supported output stream configs:
17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices:       1.1. SupportedStreamConfigRange { channels: 2, min_sample_rate: SampleRate(44100), max_sample_rate: SampleRate(44100), buffer_size: Unknown, sample_format: F32 }
17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices:     Default output stream config:
      SupportedStreamConfig { channels: 2, sample_rate: SampleRate(44100), buffer_size: Unknown, sample_format: F32 }
17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices:   2. "Soundkarte (ASUS Xonar D2X Audio Device)"
17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices:     All supported output stream configs:
17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices:       2.1. SupportedStreamConfigRange { channels: 2, min_sample_rate: SampleRate(96000), max_sample_rate: SampleRate(96000), buffer_size: Unknown, sample_format: F32 }
17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices:     Default output stream config:
      SupportedStreamConfig { channels: 2, sample_rate: SampleRate(96000), buffer_size: Unknown, sample_format: F32 }
17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices:   3. "Mikrofon (ASUS Xonar D2X Audio Device)"
17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices:   4. "Wave (ASUS Xonar D2X Audio Device)"
17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices:   5. "Hi-Fi Cable Output (VB-Audio Hi-Fi Cable)"
17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices:   6. "Mikrofon (Steam Streaming Microphone)"
17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices:   7. "SPDIF In (ASUS Xonar D2X Audio Device)"
17:27:48 [DEBUG] (1) swyh_rs::utils::audiodevices:   8. "Stereo Mix (ASUS Xonar D2X Audio Device)"
17:27:48 [INFO] Selected audio source: Hi-Fi Cable Input (VB-Audio Hi-Fi Cable)
17:27:48 [INFO] tb_log: Setup audio sources
17:27:48 [INFO] tb_log: Now running at ABOVE_NORMAL_PRIORITY_CLASS
17:27:48 [DEBUG] (1) swyh_rs: Try capturing system audio
17:27:48 [INFO] tb_log: Capturing audio from: Hi-Fi Cable Input (VB-Audio Hi-Fi Cable)
17:27:48 [INFO] tb_log: Default audio SupportedStreamConfig { channels: 2, sample_rate: SampleRate(44100), buffer_size: Unknown, sample_format: F32 }
17:27:48 [INFO] tb_log: Starting SSDP discovery
17:27:48 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery started
17:27:48 [INFO] tb_log: The streaming server is listening on http://192.168.1.99:5901/stream/swyh.wav
17:27:48 [INFO] tb_log: Sample rate: 44100, sample format: audio/l16 (PCM)
17:27:48 [DEBUG] (5) tiny_http: Server listening on 192.168.1.99:5901
17:27:48 [DEBUG] (6) tiny_http: Running accept thread
17:27:51 [DEBUG] (4) swyh_rs::openhome::avmedia: UDP response at 2631 from 192.168.1.99:50826: 
HTTP/1.1 200 OK
Ext: 
St: urn:schemas-upnp-org:service:RenderingControl:1
Server: Windows10/10.0 UPnP/1.0 BubbleUPnPServer/0.9-update38
Usn: uuid:a650210f-9d3e-1235-0000-00004d059e7e::urn:schemas-upnp-org:service:RenderingControl:1
Cache-control: max-age=1800
Location: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml

17:27:51 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP Discovery: AV renderer: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
17:27:51 [INFO] SSDP discovery: new Renderer found at : http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
17:27:51 [DEBUG] (4) swyh_rs::openhome::avmedia: Getting new renderer descriptions
17:27:51 [DEBUG] (4) swyh_rs::openhome::avmedia: Get service description for http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
17:27:51 [INFO] sending request GET http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
17:27:51 [DEBUG] (4) ureq::unit: writing prelude: GET /dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml HTTP/1.1
Host: 192.168.1.99:49836
Accept: */*
User-Agent: swyh-rs-Rust
Content-Type: text/xml
Content-Length: 0

17:27:51 [DEBUG] (4) ureq::unit: response 200 to GET http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
17:27:51 [DEBUG] (4) swyh_rs::openhome::avmedia: Service description:
17:27:51 [DEBUG] (4) swyh_rs::openhome::avmedia: <?xml version="1.0" encoding="utf-8" standalone="yes"?><root xmlns="urn:schemas-upnp-org:device-1-0"><specVersion><major>1</major><minor>0</minor></specVersion><device><deviceType>urn:schemas-upnp-org:device:MediaRenderer:1</deviceType><UDN>uuid:a650210f-9d3e-1235-0000-00004d059e7e</UDN><friendlyName>Nest Audios (DLNA)</friendlyName><manufacturer>Bubblesoft</manufacturer><manufacturerURL>http://forum.xda-developers.com/showthread.php?t=1118891</manufacturerURL><modelDescription>BubbleUPnP Google Cast DLNA renderer</modelDescription><modelName>BubbleUPnP Google Cast DLNA renderer</modelName><modelNumber>0.9-update38</modelNumber><modelURL></modelURL><serialNumber>0.9-update38</serialNumber><presentationURL>http://192.168.1.99:58050</presentationURL><dlna:X_DLNADOC xmlns:dlna="urn:schemas-dlna-org:device-1-0">DMR-1.50</dlna:X_DLNADOC><iconList><icon><mimetype>image/png</mimetype><width>98</width><height>55</height><depth>32</depth><url>/dev/a650210f-9d3e-1235-0000-00004d059e7e/icon.png</url></icon></iconList><serviceList><service><serviceType>urn:schemas-upnp-org:service:AVTransport:1</serviceType><serviceId>urn:upnp-org:serviceId:AVTransport</serviceId><controlURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action</controlURL><eventSubURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/event</eventSubURL><SCPDURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/desc.xml</SCPDURL></service><service><serviceType>urn:schemas-upnp-org:service:RenderingControl:1</serviceType><serviceId>urn:upnp-org:serviceId:RenderingControl</serviceId><controlURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/RenderingControl/action</controlURL><eventSubURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/RenderingControl/event</eventSubURL><SCPDURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/RenderingControl/desc.xml</SCPDURL></service><service><serviceType>urn:schemas-upnp-org:service:ConnectionManager:1</serviceType><serviceId>urn:upnp-org:serviceId:ConnectionManager</serviceId><controlURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/ConnectionManager/action</controlURL><eventSubURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/ConnectionManager/event</eventSubURL><SCPDURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/ConnectionManager/desc.xml</SCPDURL></service></serviceList></device></root>
17:27:51 [DEBUG] (4) swyh_rs::openhome::avmedia: Renderer Nest Audios (DLNA) BubbleUPnP Google Cast DLNA renderer ip 192.168.1.99 at urlbase http://192.168.1.99:49836/ has 3 services
17:27:51 [DEBUG] (4) swyh_rs::openhome::avmedia:   => OpenHome Playlist control url: '', AvTransport url: '/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action'
17:27:51 [DEBUG] (4) swyh_rs::openhome::avmedia: .. urn:schemas-upnp-org:service:AVTransport:1 urn:upnp-org:serviceId:AVTransport /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
17:27:51 [DEBUG] (4) swyh_rs::openhome::avmedia: .. urn:schemas-upnp-org:service:RenderingControl:1 urn:upnp-org:serviceId:RenderingControl /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/RenderingControl/action
17:27:51 [DEBUG] (4) swyh_rs::openhome::avmedia: .. urn:schemas-upnp-org:service:ConnectionManager:1 urn:upnp-org:serviceId:ConnectionManager /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/ConnectionManager/action
17:27:51 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery complete
17:27:51 [INFO] Found new renderer Nest Audios (DLNA) BubbleUPnP Google Cast DLNA renderer  at 192.168.1.99
17:27:51 [DEBUG] (1) swyh_rs: Pushed renderer #0 BubbleUPnP Google Cast DLNA renderer Nest Audios (DLNA), state = ON
17:27:51 [INFO] tb_log: AV Stop playing on Nest Audios (DLNA) host=192.168.1.99 port=49836
17:27:51 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#Stop,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><s:Envelope s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/" xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"><s:Body><u:Stop xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"><InstanceID>0</InstanceID></u:Stop></s:Body></s:Envelope>
17:27:51 [INFO] sending request POST http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
17:27:51 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49836
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#Stop"
Content-Type: text/xml; charset="utf-8"
Content-Length: 288

17:27:51 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
17:27:51 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:StopResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

17:27:51 [INFO] tb_log: AV Start playing on Nest Audios (DLNA) host=192.168.1.99 port=49836 from 192.168.1.99 using AvTransport Play
17:27:51 [DEBUG] (1) swyh_rs::openhome::avmedia: AvTransport server URL: http://192.168.1.99:5901/stream/swyh.wav
17:27:51 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#SetAVTransportURI,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:SetAVTransportURI xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"><InstanceID>0</InstanceID><CurrentURI>http://192.168.1.99:5901/stream/swyh.wav</CurrentURI><CurrentURIMetaData>&lt;DIDL-Lite xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot; xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot;&gt;&lt;item id=&quot;1&quot; parentID=&quot;0&quot; restricted=&quot;0&quot;&gt;&lt;dc:title&gt;swyh-rs&lt;/dc:title&gt;&lt;res bitsPerSample=&quot;16&quot; nrAudioChannels=&quot;2&quot; protocolInfo=&quot;http-get:*:audio/l16;rate=44100;channels=2:DLNA.ORG_PN=LPCM&quot; sampleFrequency=&quot;44100&quot; duration=&quot;0&quot; &gt;http://192.168.1.99:5901/stream/swyh.wav&lt;/res&gt;&lt;upnp:class&gt;object.item.audioItem.musicTrack&lt;/upnp:class&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;</CurrentURIMetaData></u:SetAVTransportURI></s:Body></s:Envelope>
17:27:51 [INFO] sending request POST http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
17:27:51 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49836
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#SetAVTransportURI"
Content-Type: text/xml; charset="utf-8"
Content-Length: 1099

17:27:51 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
17:27:51 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:SetAVTransportURIResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

17:27:51 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#Play,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><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>
17:27:51 [INFO] sending request POST http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
17:27:51 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49836
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#Play"
Content-Type: text/xml; charset="utf-8"
Content-Length: 304

17:27:51 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
17:27:51 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:PlayResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

17:27:52 [INFO] tb_log: Received request /stream/swyh.wav from 192.168.1.99:55306
17:27:52 [DEBUG] (8) swyh_rs: Now have 1 streaming clients
17:28:12 [INFO] tb_log: The wave_reader is now receiving samples
17:37:51 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery started
17:37:53 [DEBUG] (4) swyh_rs::openhome::avmedia: UDP response at 2181 from 192.168.1.99:50826: 
HTTP/1.1 200 OK
Ext: 
St: urn:schemas-upnp-org:service:RenderingControl:1
Server: Windows10/10.0 UPnP/1.0 BubbleUPnPServer/0.9-update38
Usn: uuid:a650210f-9d3e-1235-0000-00004d059e7e::urn:schemas-upnp-org:service:RenderingControl:1
Cache-control: max-age=1800
Location: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml

17:37:53 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP Discovery: AV renderer: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
17:37:54 [INFO] SSDP discovery: Skipping known Renderer at http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
17:37:54 [DEBUG] (4) swyh_rs::openhome::avmedia: Getting new renderer descriptions
17:37:54 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery complete
17:47:54 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery started
17:47:56 [DEBUG] (4) swyh_rs::openhome::avmedia: UDP response at 1845 from 192.168.1.99:50826: 
HTTP/1.1 200 OK
Ext: 
St: urn:schemas-upnp-org:service:RenderingControl:1
Server: Windows10/10.0 UPnP/1.0 BubbleUPnPServer/0.9-update38
Usn: uuid:a650210f-9d3e-1235-0000-00004d059e7e::urn:schemas-upnp-org:service:RenderingControl:1
Cache-control: max-age=1800
Location: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml

17:47:56 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP Discovery: AV renderer: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
17:47:57 [INFO] SSDP discovery: Skipping known Renderer at http://192.168.1.99:49836/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
17:47:57 [DEBUG] (4) swyh_rs::openhome::avmedia: Getting new renderer descriptions
17:47:57 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery complete

------------------------
Manual entry - music resumes playing around 17:57:00 but log generates no entry for that. No sound is coming from the speakers.
------------------------
17:57:22

Also, I noticed the time in the logs is off by 1 hour, but that isn't really a problem I guess :)

Silun commented 3 years ago

I thought it might have something to do with DLNA vs OpenHome, but the same problem exists when I disable DLNA in BubbleUPNP and use OpenHome instead.

In any case, here's the log of that:

18:17:08 [INFO] swyh-rs Logging started.
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices: Supported hosts:
  [Wasapi]
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices: Available hosts:
  [Wasapi]
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices: WASAPI
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices:   Default Output Device:
    Some("Soundkarte (ASUS Xonar D2X Audio Device)")
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices:   Devices: 
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices:   1. "Hi-Fi Cable Input (VB-Audio Hi-Fi Cable)"
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices:     All supported output stream configs:
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices:       1.1. SupportedStreamConfigRange { channels: 2, min_sample_rate: SampleRate(44100), max_sample_rate: SampleRate(44100), buffer_size: Unknown, sample_format: F32 }
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices:     Default output stream config:
      SupportedStreamConfig { channels: 2, sample_rate: SampleRate(44100), buffer_size: Unknown, sample_format: F32 }
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices:   2. "Soundkarte (ASUS Xonar D2X Audio Device)"
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices:     All supported output stream configs:
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices:       2.1. SupportedStreamConfigRange { channels: 2, min_sample_rate: SampleRate(96000), max_sample_rate: SampleRate(96000), buffer_size: Unknown, sample_format: F32 }
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices:     Default output stream config:
      SupportedStreamConfig { channels: 2, sample_rate: SampleRate(96000), buffer_size: Unknown, sample_format: F32 }
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices:   3. "Mikrofon (ASUS Xonar D2X Audio Device)"
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices:   4. "Wave (ASUS Xonar D2X Audio Device)"
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices:   5. "Hi-Fi Cable Output (VB-Audio Hi-Fi Cable)"
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices:   6. "Mikrofon (Steam Streaming Microphone)"
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices:   7. "SPDIF In (ASUS Xonar D2X Audio Device)"
18:17:08 [DEBUG] (1) swyh_rs::utils::audiodevices:   8. "Stereo Mix (ASUS Xonar D2X Audio Device)"
18:17:08 [INFO] Selected audio source: Hi-Fi Cable Input (VB-Audio Hi-Fi Cable)
18:17:08 [INFO] tb_log: Setup audio sources
18:17:08 [INFO] tb_log: Now running at ABOVE_NORMAL_PRIORITY_CLASS
18:17:08 [DEBUG] (1) swyh_rs: Try capturing system audio
18:17:08 [INFO] tb_log: Capturing audio from: Hi-Fi Cable Input (VB-Audio Hi-Fi Cable)
18:17:08 [INFO] tb_log: Default audio SupportedStreamConfig { channels: 2, sample_rate: SampleRate(44100), buffer_size: Unknown, sample_format: F32 }
18:17:09 [INFO] tb_log: Starting SSDP discovery
18:17:09 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery started
18:17:09 [INFO] tb_log: The streaming server is listening on http://192.168.1.99:5901/stream/swyh.wav
18:17:09 [INFO] tb_log: Sample rate: 44100, sample format: audio/l16 (PCM)
18:17:09 [DEBUG] (5) tiny_http: Server listening on 192.168.1.99:5901
18:17:09 [DEBUG] (6) tiny_http: Running accept thread
18:17:11 [DEBUG] (4) swyh_rs::openhome::avmedia: UDP response at 2235 from 192.168.1.99:50826: 
HTTP/1.1 200 OK
Ext: 
St: urn:av-openhome-org:service:Product:1
Server: Windows10/10.0 UPnP/1.0 BubbleUPnPServer/0.9-update38
Usn: uuid:a650210f-9d3e-1235-ffff-ffffe284001a::urn:av-openhome-org:service:Product:1
Cache-control: max-age=1800
Location: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml

18:17:11 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP Discovery: OH renderer: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml
18:17:12 [INFO] SSDP discovery: new Renderer found at : http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml
18:17:12 [DEBUG] (4) swyh_rs::openhome::avmedia: Getting new renderer descriptions
18:17:12 [DEBUG] (4) swyh_rs::openhome::avmedia: Get service description for http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml
18:17:12 [INFO] sending request GET http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml
18:17:12 [DEBUG] (4) ureq::unit: writing prelude: GET /dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml HTTP/1.1
Host: 192.168.1.99:49836
Accept: */*
User-Agent: swyh-rs-Rust
Content-Type: text/xml
Content-Length: 0

18:17:12 [DEBUG] (4) ureq::unit: response 200 to GET http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml
18:17:12 [DEBUG] (4) swyh_rs::openhome::avmedia: Service description:
18:17:12 [DEBUG] (4) swyh_rs::openhome::avmedia: <?xml version="1.0" encoding="utf-8" standalone="yes"?><root xmlns="urn:schemas-upnp-org:device-1-0"><specVersion><major>1</major><minor>0</minor></specVersion><device><deviceType>urn:linn-co-uk:device:Source:1</deviceType><UDN>uuid:a650210f-9d3e-1235-ffff-ffffe284001a</UDN><friendlyName>Nest Audios (OpenHome)</friendlyName><manufacturer>Bubblesoft</manufacturer><manufacturerURL>http://forum.xda-developers.com/showthread.php?t=1118891</manufacturerURL><modelDescription>BubbleUPnP Google Cast DLNA renderer (OpenHome)</modelDescription><modelName>BubbleUPnP Google Cast DLNA renderer (OpenHome)</modelName><modelNumber>0.9-update38</modelNumber><modelURL></modelURL><iconList><icon><mimetype>image/png</mimetype><width>98</width><height>55</height><depth>32</depth><url>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/con.png</url></icon></iconList><serviceList><service><serviceType>urn:av-openhome-org:service:Product:1</serviceType><serviceId>urn:av-openhome-org:serviceId:Product</serviceId><controlURL>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Product/action</controlURL><eventSubURL>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Product/event</eventSubURL><SCPDURL>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Product/desc.xml</SCPDURL></service><service><serviceType>urn:av-openhome-org:service:Volume:1</serviceType><serviceId>urn:av-openhome-org:serviceId:Volume</serviceId><controlURL>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Volume/action</controlURL><eventSubURL>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Volume/event</eventSubURL><SCPDURL>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Volume/desc.xml</SCPDURL></service><service><serviceType>urn:av-openhome-org:service:Time:1</serviceType><serviceId>urn:av-openhome-org:serviceId:Time</serviceId><controlURL>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Time/action</controlURL><eventSubURL>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Time/event</eventSubURL><SCPDURL>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Time/desc.xml</SCPDURL></service><service><serviceType>urn:av-openhome-org:service:Info:1</serviceType><serviceId>urn:av-openhome-org:serviceId:Info</serviceId><controlURL>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Info/action</controlURL><eventSubURL>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Info/event</eventSubURL><SCPDURL>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Info/desc.xml</SCPDURL></service><service><serviceType>urn:av-openhome-org:service:Playlist:1</serviceType><serviceId>urn:av-openhome-org:serviceId:Playlist</serviceId><controlURL>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action</controlURL><eventSubURL>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/event</eventSubURL><SCPDURL>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/desc.xml</SCPDURL></service><service><serviceType>urn:av-openhome-org:service:Credentials:1</serviceType><serviceId>urn:av-openhome-org:serviceId:Credentials</serviceId><controlURL>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Credentials/action</controlURL><eventSubURL>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Credentials/event</eventSubURL><SCPDURL>/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Credentials/desc.xml</SCPDURL></service></serviceList></device></root>
18:17:12 [DEBUG] (4) swyh_rs::openhome::avmedia: Renderer Nest Audios (OpenHome) BubbleUPnP Google Cast DLNA renderer (OpenHome) ip 192.168.1.99 at urlbase http://192.168.1.99:49836/ has 6 services
18:17:12 [DEBUG] (4) swyh_rs::openhome::avmedia:   => OpenHome Playlist control url: '/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action', AvTransport url: ''
18:17:12 [DEBUG] (4) swyh_rs::openhome::avmedia: .. urn:av-openhome-org:service:Product:1 urn:av-openhome-org:serviceId:Product /dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Product/action
18:17:12 [DEBUG] (4) swyh_rs::openhome::avmedia: .. urn:av-openhome-org:service:Volume:1 urn:av-openhome-org:serviceId:Volume /dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Volume/action
18:17:12 [DEBUG] (4) swyh_rs::openhome::avmedia: .. urn:av-openhome-org:service:Time:1 urn:av-openhome-org:serviceId:Time /dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Time/action
18:17:12 [DEBUG] (4) swyh_rs::openhome::avmedia: .. urn:av-openhome-org:service:Info:1 urn:av-openhome-org:serviceId:Info /dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Info/action
18:17:12 [DEBUG] (4) swyh_rs::openhome::avmedia: .. urn:av-openhome-org:service:Playlist:1 urn:av-openhome-org:serviceId:Playlist /dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action
18:17:12 [DEBUG] (4) swyh_rs::openhome::avmedia: .. urn:av-openhome-org:service:Credentials:1 urn:av-openhome-org:serviceId:Credentials /dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Credentials/action
18:17:12 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery complete
18:17:12 [INFO] Found new renderer Nest Audios (OpenHome) BubbleUPnP Google Cast DLNA renderer (OpenHome)  at 192.168.1.99
18:17:15 [DEBUG] (1) swyh_rs: Pushed renderer #0 BubbleUPnP Google Cast DLNA renderer (OpenHome) Nest Audios (OpenHome), state = ON
18:17:15 [INFO] tb_log: OH Start playing on Nest Audios (OpenHome) host=192.168.1.99 port=49836 from 192.168.1.99 using OpenHome Playlist
18:17:15 [DEBUG] (1) swyh_rs::openhome::avmedia: OHPlaylist server URL: http://192.168.1.99:5901/stream/swyh.wav
18:17:15 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action,
=>SOAP Action: urn:av-openhome-org:service:Playlist:1#DeleteAll,
=>SOAP xml: 
<?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:DeleteAll xmlns:u="urn:av-openhome-org:service:Playlist:1"/></s:Body></s:Envelope>
18:17:15 [INFO] sending request POST http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action
18:17:15 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action HTTP/1.1
Host: 192.168.1.99:49836
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:av-openhome-org:service:Playlist:1#DeleteAll"
Content-Type: text/xml; charset="utf-8"
Content-Length: 272

18:17:15 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action
18:17:15 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:DeleteAllResponse xmlns:u="urn:av-openhome-org:service:Playlist:1"/></s:Body></s:Envelope>

18:17:15 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action,
=>SOAP Action: urn:av-openhome-org:service:Playlist:1#Insert,
=>SOAP xml: 
<?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:Insert xmlns:u="urn:av-openhome-org:service:Playlist:1"><AfterId>0</AfterId><Uri>http://192.168.1.99:5901/stream/swyh.wav</Uri><Metadata>&lt;DIDL-Lite xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot; xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot;&gt;&lt;item id=&quot;1&quot; parentID=&quot;0&quot; restricted=&quot;0&quot;&gt;&lt;dc:title&gt;swyh-rs&lt;/dc:title&gt;&lt;res bitsPerSample=&quot;16&quot; nrAudioChannels=&quot;2&quot; protocolInfo=&quot;http-get:*:audio/l16;rate=44100;channels=2:DLNA.ORG_PN=LPCM&quot; sampleFrequency=&quot;44100&quot; duration=&quot;0&quot; &gt;http://192.168.1.99:5901/stream/swyh.wav&lt;/res&gt;&lt;upnp:class&gt;object.item.audioItem.musicTrack&lt;/upnp:class&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;</Metadata></u:Insert></s:Body></s:Envelope>
18:17:15 [INFO] sending request POST http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action
18:17:15 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action HTTP/1.1
Host: 192.168.1.99:49836
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:av-openhome-org:service:Playlist:1#Insert"
Content-Type: text/xml; charset="utf-8"
Content-Length: 1050

18:17:15 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action
18:17:15 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:InsertResponse xmlns:u="urn:av-openhome-org:service:Playlist:1"><NewId>1</NewId></u:InsertResponse></s:Body></s:Envelope>

18:17:15 [DEBUG] (1) swyh_rs::openhome::avmedia: SeekId: 1
18:17:15 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action,
=>SOAP Action: urn:av-openhome-org:service:Playlist:1#SeekId,
=>SOAP xml: 
<?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:SeekId xmlns:u="urn:av-openhome-org:service:Playlist:1"><Value>1</Value></u:SeekId></s:Body></s:Envelope>
18:17:15 [INFO] sending request POST http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action
18:17:15 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action HTTP/1.1
Host: 192.168.1.99:49836
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:av-openhome-org:service:Playlist:1#SeekId"
Content-Type: text/xml; charset="utf-8"
Content-Length: 295

18:17:16 [INFO] tb_log: Received request /stream/swyh.wav from 192.168.1.99:53888
18:17:16 [DEBUG] (7) swyh_rs: Now have 1 streaming clients
18:17:30 [DEBUG] (1) ureq::unit: response 500 to POST http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action
18:17:30 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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><s:Fault><faultcode>s:Client</faultcode><faultstring>UPnPError</faultstring><detail><UPnPError xmlns="urn:schemas-upnp-org:control-1-0"><errorCode>501</errorCode><errorDescription>Current state of service prevents invoking that action. timeout waiting for Playing.</errorDescription></UPnPError></detail></s:Fault></s:Body></s:Envelope>

18:17:30 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action,
=>SOAP Action: urn:av-openhome-org:service:Playlist:1#Play,
=>SOAP xml: 
<?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:av-openhome-org:service:Playlist:1"/></s:Body></s:Envelope>
18:17:30 [INFO] sending request POST http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action
18:17:30 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action HTTP/1.1
Host: 192.168.1.99:49836
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:av-openhome-org:service:Playlist:1#Play"
Content-Type: text/xml; charset="utf-8"
Content-Length: 267

18:17:31 [INFO] tb_log: Received request /stream/swyh.wav from 192.168.1.99:53919
18:17:31 [DEBUG] (8) swyh_rs: Now have 1 streaming clients
18:17:46 [DEBUG] (1) ureq::unit: response 500 to POST http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action
18:17:46 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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><s:Fault><faultcode>s:Client</faultcode><faultstring>UPnPError</faultstring><detail><UPnPError xmlns="urn:schemas-upnp-org:control-1-0"><errorCode>501</errorCode><errorDescription>Current state of service prevents invoking that action. timeout waiting for Playing.</errorDescription></UPnPError></detail></s:Fault></s:Body></s:Envelope>

18:17:56 [INFO] tb_log: The wave_reader is now receiving samples
18:27:12 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery started
18:27:14 [DEBUG] (4) swyh_rs::openhome::avmedia: UDP response at 2416 from 192.168.1.99:50826: 
HTTP/1.1 200 OK
Ext: 
St: urn:av-openhome-org:service:Product:1
Server: Windows10/10.0 UPnP/1.0 BubbleUPnPServer/0.9-update38
Usn: uuid:a650210f-9d3e-1235-ffff-ffffe284001a::urn:av-openhome-org:service:Product:1
Cache-control: max-age=1800
Location: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml

18:27:14 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP Discovery: OH renderer: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml
18:27:15 [INFO] SSDP discovery: Skipping known Renderer at http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml
18:27:15 [DEBUG] (4) swyh_rs::openhome::avmedia: Getting new renderer descriptions
18:27:15 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery complete
18:37:15 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery started
18:37:16 [DEBUG] (4) swyh_rs::openhome::avmedia: UDP response at 890 from 192.168.1.99:50826: 
HTTP/1.1 200 OK
Ext: 
St: urn:av-openhome-org:service:Product:1
Server: Windows10/10.0 UPnP/1.0 BubbleUPnPServer/0.9-update38
Usn: uuid:a650210f-9d3e-1235-ffff-ffffe284001a::urn:av-openhome-org:service:Product:1
Cache-control: max-age=1800
Location: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml

18:37:16 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP Discovery: OH renderer: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml
18:37:18 [INFO] SSDP discovery: Skipping known Renderer at http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml
18:37:18 [DEBUG] (4) swyh_rs::openhome::avmedia: Getting new renderer descriptions
18:37:18 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery complete
18:47:18 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery started
18:47:20 [DEBUG] (4) swyh_rs::openhome::avmedia: UDP response at 1819 from 192.168.1.99:50826: 
HTTP/1.1 200 OK
Ext: 
St: urn:av-openhome-org:service:Product:1
Server: Windows10/10.0 UPnP/1.0 BubbleUPnPServer/0.9-update38
Usn: uuid:a650210f-9d3e-1235-ffff-ffffe284001a::urn:av-openhome-org:service:Product:1
Cache-control: max-age=1800
Location: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml

18:47:20 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP Discovery: OH renderer: http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml
18:47:21 [INFO] SSDP discovery: Skipping known Renderer at http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml
18:47:21 [DEBUG] (4) swyh_rs::openhome::avmedia: Getting new renderer descriptions
18:47:21 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery complete

------------------------
Manual entry - music resumes playing around 18:52:00 but log generates no entry for that. No sound is coming from the speakers.
------------------------

18:52:25 [ERROR] Error accepting new client: Ein Blockierungsvorgang wurde durch einen Aufruf von WSACancelBlockingCall unterbrochen. (os error 10004)
18:52:25 [DEBUG] (6) tiny_http: Terminating accept thread

dheijl commented 3 years ago

I'm afraid that's how WasApi works - it only starts capturing audio when something is actually playing (and at that moment swyh-rs will output a "the wave reader is receiving samples" message), but when playing stops it just outputs silence without any notice that sound has actually stopped. When the interruption in the playing is short, it resumes sending sound instead of silence and everything works as expected, but I have never tried using long playing pauses while swyh-rs remains active. So you may have hit a WasApi limitation here, or a limitation in the Rust CPAL library implementation of WasApi sound capture. Documentation for WasApi sound capture is not bad, but it does not cover your scenario I'm afraid. I'll try to find some information on this topic but don't expect anything...

Edit: is the WSaCancelBlockingCall (OS error 10004) the result of you stopping Bubble UPNP, or did it happen without any action from you?

dheijl commented 3 years ago

This may related:

18:17:31 [DEBUG] (8) swyh_rs: Now have 1 streaming clients 18:17:46 [DEBUG] (1) ureq::unit: response 500 to POST http://192.168.1.99:49836/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action 18:17:46 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?xml version="1.0" encoding="utf-8" standalone="yes"?>s:ClientUPnPError501Current state of service prevents invoking that action. timeout waiting for Playing.</s:Fault></s:Body></s:Envelope>

Apparently Bubble-UPNP goes into a time-out if you ask it to play and there's no sound coming from the server. Other UPNP/DLNA devices do not appear to have this behaviour (at least not from my experience).

Silun commented 3 years ago

WSACancelBlockingCall (os error 10004) happened when I closed swyh-rs by pressing the X button. When using DLNA, it just logged 17:57:22 and when I used OpenHome, it logged WSACancelBlockingCall (os error 10004). I did not change anything in BubbleUPNP during the tests, only between them (switch from DLNA to OpenHome).

I just did some testing with foobar2000, I recorded the sound from VB-Audio and played it back over BubbleUPNP (so, basically what swyh-rs does). When doing that, playback stops after around 2-3 minutes of silence, after which point it won't resume without restarting the stream manually. That seems like it would be consistent with what you say - that it's BubbleUPNP that's stopping the playback.

So, what do you reckon would be ways to deal with this? I suppose either the developer of BubbleUPNP could add the option to change the timeout value or I would need to use some form of keepalive. I think when Logitech had a set of speakers that would turn itself off after a while, people used to constantly send silence (or inaudible near silence) to the speakers just to keep them alive.

Would that be something you'd consider adding to swyh-rs? Could be a tickable option like Autoresume that sends some minimal, inaudible sample every 30 seconds or so if the input has been silent for that amount of time. Without this option, the connection of swyh-rs might go stale without any indicator inside its window, and people might need to restart it regularly. It might be advantageous in any case to have some kind of handling for the error ClientUPnPError501 that you rightfully pointed out.

dheijl commented 3 years ago

I had already considered sending (near) silence when no sound is present, so that's what I'll try.

dheijl commented 3 years ago

There is a beta available that tries to implement this, it works for me but then my renderers do not disconnect anyway...

Silun commented 3 years ago

I tested it, the connection appears to be stable now and the renderer doesn't disconnect. However, there is some weird behaviour.

A couple of notes:

The first time, I got silence interrupting the music every couple of seconds. That is log #1.
The second time, I started it, played some music immediately, then stopped for 5 minutes. When I resumed playing music, it did not interrupt every few seconds any more.
In subsequent tests I was not able to reliably reproduce the issue from the first time, so I can't say under which conditions exactly it occurs.
I can clearly hear the beeping sound every 10/20 seconds. Not sure if that is intended. Couldn't it send digital silence? It seems to me that swyh-rs keeps sending silence for a few seconds after the audio stops anyway, and then after some seconds stops sending anything at all. If it could just send digital silence every couple of seconds, or alternatively just never stop sending even when the source audio is silence, that would probably be optimal. Could be a toggle to continuously send, perhaps.

Log #1

16:55:04 [INFO] swyh-rs Logging started.
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices: Supported hosts:
  [Wasapi]
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices: Available hosts:
  [Wasapi]
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices: WASAPI
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices:   Default Output Device:
    Some("Soundkarte (ASUS Xonar D2X Audio Device)")
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices:   Devices: 
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices:   1. "Hi-Fi Cable Input (VB-Audio Hi-Fi Cable)"
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices:     All supported output stream configs:
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices:       1.1. SupportedStreamConfigRange { channels: 2, min_sample_rate: SampleRate(44100), max_sample_rate: SampleRate(44100), buffer_size: Unknown, sample_format: F32 }
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices:     Default output stream config:
      SupportedStreamConfig { channels: 2, sample_rate: SampleRate(44100), buffer_size: Unknown, sample_format: F32 }
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices:   2. "Soundkarte (ASUS Xonar D2X Audio Device)"
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices:     All supported output stream configs:
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices:       2.1. SupportedStreamConfigRange { channels: 2, min_sample_rate: SampleRate(96000), max_sample_rate: SampleRate(96000), buffer_size: Unknown, sample_format: F32 }
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices:     Default output stream config:
      SupportedStreamConfig { channels: 2, sample_rate: SampleRate(96000), buffer_size: Unknown, sample_format: F32 }
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices:   3. "Mikrofon (ASUS Xonar D2X Audio Device)"
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices:   4. "Wave (ASUS Xonar D2X Audio Device)"
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices:   5. "Hi-Fi Cable Output (VB-Audio Hi-Fi Cable)"
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices:   6. "Mikrofon (Steam Streaming Microphone)"
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices:   7. "SPDIF In (ASUS Xonar D2X Audio Device)"
16:55:04 [DEBUG] (1) swyh_rs::utils::audiodevices:   8. "Stereo Mix (ASUS Xonar D2X Audio Device)"
16:55:04 [INFO] Selected audio source: Hi-Fi Cable Input (VB-Audio Hi-Fi Cable)
16:55:04 [INFO] tb_log: Setup audio sources
16:55:04 [INFO] tb_log: Now running at ABOVE_NORMAL_PRIORITY_CLASS
16:55:04 [DEBUG] (1) swyh_rs: Try capturing system audio
16:55:04 [INFO] tb_log: Capturing audio from: Hi-Fi Cable Input (VB-Audio Hi-Fi Cable)
16:55:04 [INFO] tb_log: Default audio SupportedStreamConfig { channels: 2, sample_rate: SampleRate(44100), buffer_size: Unknown, sample_format: F32 }
16:55:04 [INFO] tb_log: Starting SSDP discovery
16:55:04 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery started
16:55:04 [INFO] tb_log: The streaming server is listening on http://192.168.1.99:5901/stream/swyh.wav
16:55:04 [INFO] tb_log: Sample rate: 44100, sample format: audio/l16 (PCM)
16:55:04 [DEBUG] (5) tiny_http: Server listening on 192.168.1.99:5901
16:55:04 [DEBUG] (6) tiny_http: Running accept thread
16:55:06 [DEBUG] (4) swyh_rs::openhome::avmedia: UDP response at 1737 from 192.168.1.99:53738: 
HTTP/1.1 200 OK
Ext: 
St: urn:schemas-upnp-org:service:RenderingControl:1
Server: Windows10/10.0 UPnP/1.0 BubbleUPnPServer/0.9-update38
Usn: uuid:a650210f-9d3e-1235-0000-00004d059e7e::urn:schemas-upnp-org:service:RenderingControl:1
Cache-control: max-age=1800
Location: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml

16:55:06 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP Discovery: AV renderer: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
16:55:07 [INFO] SSDP discovery: new Renderer found at : http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
16:55:07 [DEBUG] (4) swyh_rs::openhome::avmedia: Getting new renderer descriptions
16:55:07 [DEBUG] (4) swyh_rs::openhome::avmedia: Get service description for http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
16:55:07 [INFO] sending request GET http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
16:55:07 [DEBUG] (4) ureq::unit: writing prelude: GET /dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml HTTP/1.1
Host: 192.168.1.99:49855
Accept: */*
User-Agent: swyh-rs-Rust
Content-Type: text/xml
Content-Length: 0

16:55:07 [DEBUG] (4) ureq::unit: response 200 to GET http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
16:55:07 [DEBUG] (4) swyh_rs::openhome::avmedia: Service description:
16:55:07 [DEBUG] (4) swyh_rs::openhome::avmedia: <?xml version="1.0" encoding="utf-8" standalone="yes"?><root xmlns="urn:schemas-upnp-org:device-1-0"><specVersion><major>1</major><minor>0</minor></specVersion><device><deviceType>urn:schemas-upnp-org:device:MediaRenderer:1</deviceType><UDN>uuid:a650210f-9d3e-1235-0000-00004d059e7e</UDN><friendlyName>Nest Audios (DLNA)</friendlyName><manufacturer>Bubblesoft</manufacturer><manufacturerURL>http://forum.xda-developers.com/showthread.php?t=1118891</manufacturerURL><modelDescription>BubbleUPnP Google Cast DLNA renderer</modelDescription><modelName>BubbleUPnP Google Cast DLNA renderer</modelName><modelNumber>0.9-update38</modelNumber><modelURL></modelURL><serialNumber>0.9-update38</serialNumber><presentationURL>http://192.168.1.99:58050</presentationURL><dlna:X_DLNADOC xmlns:dlna="urn:schemas-dlna-org:device-1-0">DMR-1.50</dlna:X_DLNADOC><iconList><icon><mimetype>image/png</mimetype><width>98</width><height>55</height><depth>32</depth><url>/dev/a650210f-9d3e-1235-0000-00004d059e7e/icon.png</url></icon></iconList><serviceList><service><serviceType>urn:schemas-upnp-org:service:AVTransport:1</serviceType><serviceId>urn:upnp-org:serviceId:AVTransport</serviceId><controlURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action</controlURL><eventSubURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/event</eventSubURL><SCPDURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/desc.xml</SCPDURL></service><service><serviceType>urn:schemas-upnp-org:service:RenderingControl:1</serviceType><serviceId>urn:upnp-org:serviceId:RenderingControl</serviceId><controlURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/RenderingControl/action</controlURL><eventSubURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/RenderingControl/event</eventSubURL><SCPDURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/RenderingControl/desc.xml</SCPDURL></service><service><serviceType>urn:schemas-upnp-org:service:ConnectionManager:1</serviceType><serviceId>urn:upnp-org:serviceId:ConnectionManager</serviceId><controlURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/ConnectionManager/action</controlURL><eventSubURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/ConnectionManager/event</eventSubURL><SCPDURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/ConnectionManager/desc.xml</SCPDURL></service></serviceList></device></root>
16:55:07 [DEBUG] (4) swyh_rs::openhome::avmedia: Renderer Nest Audios (DLNA) BubbleUPnP Google Cast DLNA renderer ip 192.168.1.99 at urlbase http://192.168.1.99:49855/ has 3 services
16:55:07 [DEBUG] (4) swyh_rs::openhome::avmedia:   => OpenHome Playlist control url: '', AvTransport url: '/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action'
16:55:07 [DEBUG] (4) swyh_rs::openhome::avmedia: .. urn:schemas-upnp-org:service:AVTransport:1 urn:upnp-org:serviceId:AVTransport /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:07 [DEBUG] (4) swyh_rs::openhome::avmedia: .. urn:schemas-upnp-org:service:RenderingControl:1 urn:upnp-org:serviceId:RenderingControl /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/RenderingControl/action
16:55:07 [DEBUG] (4) swyh_rs::openhome::avmedia: .. urn:schemas-upnp-org:service:ConnectionManager:1 urn:upnp-org:serviceId:ConnectionManager /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/ConnectionManager/action
16:55:07 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery complete
16:55:07 [INFO] Found new renderer Nest Audios (DLNA) BubbleUPnP Google Cast DLNA renderer  at 192.168.1.99
16:55:07 [DEBUG] (1) swyh_rs: Pushed renderer #0 BubbleUPnP Google Cast DLNA renderer Nest Audios (DLNA), state = ON
16:55:07 [INFO] tb_log: AV Stop playing on Nest Audios (DLNA) host=192.168.1.99 port=49855
16:55:07 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#Stop,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><s:Envelope s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/" xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"><s:Body><u:Stop xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"><InstanceID>0</InstanceID></u:Stop></s:Body></s:Envelope>
16:55:07 [INFO] sending request POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:07 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49855
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#Stop"
Content-Type: text/xml; charset="utf-8"
Content-Length: 288

16:55:07 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:07 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:StopResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

16:55:07 [INFO] tb_log: AV Start playing on Nest Audios (DLNA) host=192.168.1.99 port=49855 from 192.168.1.99 using AvTransport Play
16:55:07 [DEBUG] (1) swyh_rs::openhome::avmedia: AvTransport server URL: http://192.168.1.99:5901/stream/swyh.wav
16:55:07 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#SetAVTransportURI,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:SetAVTransportURI xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"><InstanceID>0</InstanceID><CurrentURI>http://192.168.1.99:5901/stream/swyh.wav</CurrentURI><CurrentURIMetaData>&lt;DIDL-Lite xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot; xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot;&gt;&lt;item id=&quot;1&quot; parentID=&quot;0&quot; restricted=&quot;0&quot;&gt;&lt;dc:title&gt;swyh-rs&lt;/dc:title&gt;&lt;res bitsPerSample=&quot;16&quot; nrAudioChannels=&quot;2&quot; protocolInfo=&quot;http-get:*:audio/l16;rate=44100;channels=2:DLNA.ORG_PN=LPCM&quot; sampleFrequency=&quot;44100&quot; duration=&quot;0&quot; &gt;http://192.168.1.99:5901/stream/swyh.wav&lt;/res&gt;&lt;upnp:class&gt;object.item.audioItem.musicTrack&lt;/upnp:class&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;</CurrentURIMetaData></u:SetAVTransportURI></s:Body></s:Envelope>
16:55:07 [INFO] sending request POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:07 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49855
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#SetAVTransportURI"
Content-Type: text/xml; charset="utf-8"
Content-Length: 1099

16:55:07 [INFO] tb_log: Received request /stream/swyh.wav from 192.168.1.99:54895
16:55:07 [DEBUG] (7) swyh_rs: Now have 1 streaming clients
16:55:12 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:12 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:SetAVTransportURIResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

16:55:12 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#Play,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><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>
16:55:12 [INFO] sending request POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:12 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49855
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#Play"
Content-Type: text/xml; charset="utf-8"
Content-Length: 304

16:55:12 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:12 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:PlayResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

16:55:18 [INFO] tb_log: Received request /stream/swyh.wav from 192.168.1.99:54901
16:55:18 [DEBUG] (8) swyh_rs: Now have 1 streaming clients
16:55:25 [INFO] tb_log: The wave_reader is now receiving samples
16:55:27 [INFO] tb_log: =>Http connection with 192.168.1.99:54895 terminated [Eine bestehende Verbindung wurde softwaregesteuert
durch den Hostcomputer abgebrochen. (os error 10053)]
16:55:27 [DEBUG] (7) swyh_rs: Now have 0 streaming clients left
16:55:27 [INFO] tb_log: Streaming to 192.168.1.99:54895 has ended
16:55:27 [DEBUG] (1) swyh_rs: Autoresume: AV Stop playing on Nest Audios (DLNA) host=192.168.1.99 port=49855
16:55:27 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#Stop,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><s:Envelope s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/" xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"><s:Body><u:Stop xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"><InstanceID>0</InstanceID></u:Stop></s:Body></s:Envelope>
16:55:27 [INFO] sending request POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:27 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49855
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#Stop"
Content-Type: text/xml; charset="utf-8"
Content-Length: 288

16:55:27 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:27 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:StopResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

16:55:27 [DEBUG] (1) swyh_rs: Autoresume: AV Start playing on Nest Audios (DLNA) host=192.168.1.99 port=49855 from 192.168.1.99 using AvTransport Play
16:55:27 [DEBUG] (1) swyh_rs::openhome::avmedia: AvTransport server URL: http://192.168.1.99:5901/stream/swyh.wav
16:55:27 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#SetAVTransportURI,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:SetAVTransportURI xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"><InstanceID>0</InstanceID><CurrentURI>http://192.168.1.99:5901/stream/swyh.wav</CurrentURI><CurrentURIMetaData>&lt;DIDL-Lite xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot; xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot;&gt;&lt;item id=&quot;1&quot; parentID=&quot;0&quot; restricted=&quot;0&quot;&gt;&lt;dc:title&gt;swyh-rs&lt;/dc:title&gt;&lt;res bitsPerSample=&quot;16&quot; nrAudioChannels=&quot;2&quot; protocolInfo=&quot;http-get:*:audio/l16;rate=44100;channels=2:DLNA.ORG_PN=LPCM&quot; sampleFrequency=&quot;44100&quot; duration=&quot;0&quot; &gt;http://192.168.1.99:5901/stream/swyh.wav&lt;/res&gt;&lt;upnp:class&gt;object.item.audioItem.musicTrack&lt;/upnp:class&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;</CurrentURIMetaData></u:SetAVTransportURI></s:Body></s:Envelope>
16:55:27 [INFO] sending request POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:27 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49855
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#SetAVTransportURI"
Content-Type: text/xml; charset="utf-8"
Content-Length: 1099

16:55:27 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:27 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:SetAVTransportURIResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

16:55:28 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#Play,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><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>
16:55:28 [INFO] sending request POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:28 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49855
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#Play"
Content-Type: text/xml; charset="utf-8"
Content-Length: 304

16:55:28 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:28 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:PlayResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

16:55:28 [INFO] tb_log: Received request /stream/swyh.wav from 192.168.1.99:54908
16:55:28 [DEBUG] (9) swyh_rs: Now have 1 streaming clients
16:55:47 [INFO] tb_log: =>Http connection with 192.168.1.99:54901 terminated [Eine vorhandene Verbindung wurde vom Remotehost geschlossen. (os error 10054)]
16:55:47 [DEBUG] (8) swyh_rs: Now have 0 streaming clients left
16:55:47 [INFO] tb_log: Streaming to 192.168.1.99:54901 has ended
16:55:47 [DEBUG] (1) swyh_rs: Autoresume: AV Stop playing on Nest Audios (DLNA) host=192.168.1.99 port=49855
16:55:47 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#Stop,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><s:Envelope s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/" xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"><s:Body><u:Stop xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"><InstanceID>0</InstanceID></u:Stop></s:Body></s:Envelope>
16:55:47 [INFO] sending request POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:47 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49855
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#Stop"
Content-Type: text/xml; charset="utf-8"
Content-Length: 288

16:55:47 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:47 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:StopResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

16:55:47 [DEBUG] (1) swyh_rs: Autoresume: AV Start playing on Nest Audios (DLNA) host=192.168.1.99 port=49855 from 192.168.1.99 using AvTransport Play
16:55:47 [DEBUG] (1) swyh_rs::openhome::avmedia: AvTransport server URL: http://192.168.1.99:5901/stream/swyh.wav
16:55:47 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#SetAVTransportURI,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:SetAVTransportURI xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"><InstanceID>0</InstanceID><CurrentURI>http://192.168.1.99:5901/stream/swyh.wav</CurrentURI><CurrentURIMetaData>&lt;DIDL-Lite xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot; xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot;&gt;&lt;item id=&quot;1&quot; parentID=&quot;0&quot; restricted=&quot;0&quot;&gt;&lt;dc:title&gt;swyh-rs&lt;/dc:title&gt;&lt;res bitsPerSample=&quot;16&quot; nrAudioChannels=&quot;2&quot; protocolInfo=&quot;http-get:*:audio/l16;rate=44100;channels=2:DLNA.ORG_PN=LPCM&quot; sampleFrequency=&quot;44100&quot; duration=&quot;0&quot; &gt;http://192.168.1.99:5901/stream/swyh.wav&lt;/res&gt;&lt;upnp:class&gt;object.item.audioItem.musicTrack&lt;/upnp:class&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;</CurrentURIMetaData></u:SetAVTransportURI></s:Body></s:Envelope>
16:55:47 [INFO] sending request POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:47 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49855
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#SetAVTransportURI"
Content-Type: text/xml; charset="utf-8"
Content-Length: 1099

16:55:47 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:47 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:SetAVTransportURIResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

16:55:47 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#Play,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><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>
16:55:47 [INFO] sending request POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:47 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49855
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#Play"
Content-Type: text/xml; charset="utf-8"
Content-Length: 304

16:55:47 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:55:47 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:PlayResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

16:55:48 [INFO] tb_log: Received request /stream/swyh.wav from 192.168.1.99:54916
16:55:48 [DEBUG] (10) swyh_rs: Now have 1 streaming clients
16:56:07 [INFO] tb_log: =>Http connection with 192.168.1.99:54908 terminated [Eine vorhandene Verbindung wurde vom Remotehost geschlossen. (os error 10054)]
16:56:07 [DEBUG] (9) swyh_rs: Now have 0 streaming clients left
16:56:07 [INFO] tb_log: Streaming to 192.168.1.99:54908 has ended
16:56:07 [DEBUG] (1) swyh_rs: Autoresume: AV Stop playing on Nest Audios (DLNA) host=192.168.1.99 port=49855
16:56:07 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#Stop,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><s:Envelope s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/" xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"><s:Body><u:Stop xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"><InstanceID>0</InstanceID></u:Stop></s:Body></s:Envelope>
16:56:07 [INFO] sending request POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:56:07 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49855
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#Stop"
Content-Type: text/xml; charset="utf-8"
Content-Length: 288

16:56:07 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:56:07 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:StopResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

16:56:07 [DEBUG] (1) swyh_rs: Autoresume: AV Start playing on Nest Audios (DLNA) host=192.168.1.99 port=49855 from 192.168.1.99 using AvTransport Play
16:56:07 [DEBUG] (1) swyh_rs::openhome::avmedia: AvTransport server URL: http://192.168.1.99:5901/stream/swyh.wav
16:56:07 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#SetAVTransportURI,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:SetAVTransportURI xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"><InstanceID>0</InstanceID><CurrentURI>http://192.168.1.99:5901/stream/swyh.wav</CurrentURI><CurrentURIMetaData>&lt;DIDL-Lite xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot; xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot;&gt;&lt;item id=&quot;1&quot; parentID=&quot;0&quot; restricted=&quot;0&quot;&gt;&lt;dc:title&gt;swyh-rs&lt;/dc:title&gt;&lt;res bitsPerSample=&quot;16&quot; nrAudioChannels=&quot;2&quot; protocolInfo=&quot;http-get:*:audio/l16;rate=44100;channels=2:DLNA.ORG_PN=LPCM&quot; sampleFrequency=&quot;44100&quot; duration=&quot;0&quot; &gt;http://192.168.1.99:5901/stream/swyh.wav&lt;/res&gt;&lt;upnp:class&gt;object.item.audioItem.musicTrack&lt;/upnp:class&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;</CurrentURIMetaData></u:SetAVTransportURI></s:Body></s:Envelope>
16:56:07 [INFO] sending request POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:56:07 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49855
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#SetAVTransportURI"
Content-Type: text/xml; charset="utf-8"
Content-Length: 1099

16:56:07 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:56:07 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:SetAVTransportURIResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

16:56:07 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#Play,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><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>
16:56:07 [INFO] sending request POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:56:07 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49855
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#Play"
Content-Type: text/xml; charset="utf-8"
Content-Length: 304

16:56:07 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:56:07 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:PlayResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

16:56:08 [INFO] tb_log: Received request /stream/swyh.wav from 192.168.1.99:54923
16:56:08 [DEBUG] (11) swyh_rs: Now have 1 streaming clients
16:56:15 [ERROR] Error accepting new client: Ein Blockierungsvorgang wurde durch einen Aufruf von WSACancelBlockingCall unterbrochen. (os error 10004)
16:56:15 [DEBUG] (6) tiny_http: Terminating accept thread

And log #2

16:57:30 [INFO] swyh-rs Logging started.
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices: Supported hosts:
  [Wasapi]
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices: Available hosts:
  [Wasapi]
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices: WASAPI
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices:   Default Output Device:
    Some("Soundkarte (ASUS Xonar D2X Audio Device)")
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices:   Devices: 
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices:   1. "Hi-Fi Cable Input (VB-Audio Hi-Fi Cable)"
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices:     All supported output stream configs:
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices:       1.1. SupportedStreamConfigRange { channels: 2, min_sample_rate: SampleRate(44100), max_sample_rate: SampleRate(44100), buffer_size: Unknown, sample_format: F32 }
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices:     Default output stream config:
      SupportedStreamConfig { channels: 2, sample_rate: SampleRate(44100), buffer_size: Unknown, sample_format: F32 }
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices:   2. "Soundkarte (ASUS Xonar D2X Audio Device)"
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices:     All supported output stream configs:
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices:       2.1. SupportedStreamConfigRange { channels: 2, min_sample_rate: SampleRate(96000), max_sample_rate: SampleRate(96000), buffer_size: Unknown, sample_format: F32 }
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices:     Default output stream config:
      SupportedStreamConfig { channels: 2, sample_rate: SampleRate(96000), buffer_size: Unknown, sample_format: F32 }
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices:   3. "Mikrofon (ASUS Xonar D2X Audio Device)"
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices:   4. "Wave (ASUS Xonar D2X Audio Device)"
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices:   5. "Hi-Fi Cable Output (VB-Audio Hi-Fi Cable)"
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices:   6. "Mikrofon (Steam Streaming Microphone)"
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices:   7. "SPDIF In (ASUS Xonar D2X Audio Device)"
16:57:30 [DEBUG] (1) swyh_rs::utils::audiodevices:   8. "Stereo Mix (ASUS Xonar D2X Audio Device)"
16:57:30 [INFO] Selected audio source: Hi-Fi Cable Input (VB-Audio Hi-Fi Cable)
16:57:30 [INFO] tb_log: Setup audio sources
16:57:30 [INFO] tb_log: Now running at ABOVE_NORMAL_PRIORITY_CLASS
16:57:30 [DEBUG] (1) swyh_rs: Try capturing system audio
16:57:30 [INFO] tb_log: Capturing audio from: Hi-Fi Cable Input (VB-Audio Hi-Fi Cable)
16:57:30 [INFO] tb_log: Default audio SupportedStreamConfig { channels: 2, sample_rate: SampleRate(44100), buffer_size: Unknown, sample_format: F32 }
16:57:30 [INFO] tb_log: Starting SSDP discovery
16:57:30 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery started
16:57:30 [INFO] tb_log: The streaming server is listening on http://192.168.1.99:5901/stream/swyh.wav
16:57:30 [INFO] tb_log: Sample rate: 44100, sample format: audio/l16 (PCM)
16:57:30 [DEBUG] (5) tiny_http: Server listening on 192.168.1.99:5901
16:57:30 [DEBUG] (6) tiny_http: Running accept thread
16:57:32 [DEBUG] (4) swyh_rs::openhome::avmedia: UDP response at 1373 from 192.168.1.99:53738: 
HTTP/1.1 200 OK
Ext: 
St: urn:schemas-upnp-org:service:RenderingControl:1
Server: Windows10/10.0 UPnP/1.0 BubbleUPnPServer/0.9-update38
Usn: uuid:a650210f-9d3e-1235-0000-00004d059e7e::urn:schemas-upnp-org:service:RenderingControl:1
Cache-control: max-age=1800
Location: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml

16:57:32 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP Discovery: AV renderer: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
16:57:33 [INFO] SSDP discovery: new Renderer found at : http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
16:57:33 [DEBUG] (4) swyh_rs::openhome::avmedia: Getting new renderer descriptions
16:57:33 [DEBUG] (4) swyh_rs::openhome::avmedia: Get service description for http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
16:57:33 [INFO] sending request GET http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
16:57:33 [DEBUG] (4) ureq::unit: writing prelude: GET /dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml HTTP/1.1
Host: 192.168.1.99:49855
Accept: */*
User-Agent: swyh-rs-Rust
Content-Type: text/xml
Content-Length: 0

16:57:33 [DEBUG] (4) ureq::unit: response 200 to GET http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
16:57:33 [DEBUG] (4) swyh_rs::openhome::avmedia: Service description:
16:57:33 [DEBUG] (4) swyh_rs::openhome::avmedia: <?xml version="1.0" encoding="utf-8" standalone="yes"?><root xmlns="urn:schemas-upnp-org:device-1-0"><specVersion><major>1</major><minor>0</minor></specVersion><device><deviceType>urn:schemas-upnp-org:device:MediaRenderer:1</deviceType><UDN>uuid:a650210f-9d3e-1235-0000-00004d059e7e</UDN><friendlyName>Nest Audios (DLNA)</friendlyName><manufacturer>Bubblesoft</manufacturer><manufacturerURL>http://forum.xda-developers.com/showthread.php?t=1118891</manufacturerURL><modelDescription>BubbleUPnP Google Cast DLNA renderer</modelDescription><modelName>BubbleUPnP Google Cast DLNA renderer</modelName><modelNumber>0.9-update38</modelNumber><modelURL></modelURL><serialNumber>0.9-update38</serialNumber><presentationURL>http://192.168.1.99:58050</presentationURL><dlna:X_DLNADOC xmlns:dlna="urn:schemas-dlna-org:device-1-0">DMR-1.50</dlna:X_DLNADOC><iconList><icon><mimetype>image/png</mimetype><width>98</width><height>55</height><depth>32</depth><url>/dev/a650210f-9d3e-1235-0000-00004d059e7e/icon.png</url></icon></iconList><serviceList><service><serviceType>urn:schemas-upnp-org:service:AVTransport:1</serviceType><serviceId>urn:upnp-org:serviceId:AVTransport</serviceId><controlURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action</controlURL><eventSubURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/event</eventSubURL><SCPDURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/desc.xml</SCPDURL></service><service><serviceType>urn:schemas-upnp-org:service:RenderingControl:1</serviceType><serviceId>urn:upnp-org:serviceId:RenderingControl</serviceId><controlURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/RenderingControl/action</controlURL><eventSubURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/RenderingControl/event</eventSubURL><SCPDURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/RenderingControl/desc.xml</SCPDURL></service><service><serviceType>urn:schemas-upnp-org:service:ConnectionManager:1</serviceType><serviceId>urn:upnp-org:serviceId:ConnectionManager</serviceId><controlURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/ConnectionManager/action</controlURL><eventSubURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/ConnectionManager/event</eventSubURL><SCPDURL>/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/ConnectionManager/desc.xml</SCPDURL></service></serviceList></device></root>
16:57:33 [DEBUG] (4) swyh_rs::openhome::avmedia: Renderer Nest Audios (DLNA) BubbleUPnP Google Cast DLNA renderer ip 192.168.1.99 at urlbase http://192.168.1.99:49855/ has 3 services
16:57:33 [DEBUG] (4) swyh_rs::openhome::avmedia:   => OpenHome Playlist control url: '', AvTransport url: '/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action'
16:57:33 [DEBUG] (4) swyh_rs::openhome::avmedia: .. urn:schemas-upnp-org:service:AVTransport:1 urn:upnp-org:serviceId:AVTransport /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:57:33 [DEBUG] (4) swyh_rs::openhome::avmedia: .. urn:schemas-upnp-org:service:RenderingControl:1 urn:upnp-org:serviceId:RenderingControl /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/RenderingControl/action
16:57:33 [DEBUG] (4) swyh_rs::openhome::avmedia: .. urn:schemas-upnp-org:service:ConnectionManager:1 urn:upnp-org:serviceId:ConnectionManager /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/ConnectionManager/action
16:57:33 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery complete
16:57:33 [INFO] Found new renderer Nest Audios (DLNA) BubbleUPnP Google Cast DLNA renderer  at 192.168.1.99
16:57:33 [DEBUG] (1) swyh_rs: Pushed renderer #0 BubbleUPnP Google Cast DLNA renderer Nest Audios (DLNA), state = ON
16:57:33 [INFO] tb_log: AV Stop playing on Nest Audios (DLNA) host=192.168.1.99 port=49855
16:57:33 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#Stop,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><s:Envelope s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/" xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"><s:Body><u:Stop xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"><InstanceID>0</InstanceID></u:Stop></s:Body></s:Envelope>
16:57:33 [INFO] sending request POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:57:33 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49855
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#Stop"
Content-Type: text/xml; charset="utf-8"
Content-Length: 288

16:57:33 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:57:33 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:StopResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

16:57:33 [INFO] tb_log: AV Start playing on Nest Audios (DLNA) host=192.168.1.99 port=49855 from 192.168.1.99 using AvTransport Play
16:57:33 [DEBUG] (1) swyh_rs::openhome::avmedia: AvTransport server URL: http://192.168.1.99:5901/stream/swyh.wav
16:57:33 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#SetAVTransportURI,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:SetAVTransportURI xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"><InstanceID>0</InstanceID><CurrentURI>http://192.168.1.99:5901/stream/swyh.wav</CurrentURI><CurrentURIMetaData>&lt;DIDL-Lite xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot; xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot;&gt;&lt;item id=&quot;1&quot; parentID=&quot;0&quot; restricted=&quot;0&quot;&gt;&lt;dc:title&gt;swyh-rs&lt;/dc:title&gt;&lt;res bitsPerSample=&quot;16&quot; nrAudioChannels=&quot;2&quot; protocolInfo=&quot;http-get:*:audio/l16;rate=44100;channels=2:DLNA.ORG_PN=LPCM&quot; sampleFrequency=&quot;44100&quot; duration=&quot;0&quot; &gt;http://192.168.1.99:5901/stream/swyh.wav&lt;/res&gt;&lt;upnp:class&gt;object.item.audioItem.musicTrack&lt;/upnp:class&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;</CurrentURIMetaData></u:SetAVTransportURI></s:Body></s:Envelope>
16:57:33 [INFO] sending request POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:57:33 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49855
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#SetAVTransportURI"
Content-Type: text/xml; charset="utf-8"
Content-Length: 1099

16:57:33 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:57:33 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:SetAVTransportURIResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

16:57:33 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#Play,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><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>
16:57:33 [INFO] sending request POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:57:33 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49855
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#Play"
Content-Type: text/xml; charset="utf-8"
Content-Length: 304

16:57:33 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
16:57:33 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:PlayResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

16:57:34 [INFO] tb_log: Received request /stream/swyh.wav from 192.168.1.99:54948
16:57:34 [DEBUG] (7) swyh_rs: Now have 1 streaming clients
16:57:44 [INFO] tb_log: The wave_reader is now receiving samples
17:07:33 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery started
17:07:34 [DEBUG] (4) swyh_rs::openhome::avmedia: UDP response at 971 from 192.168.1.99:53738: 
HTTP/1.1 200 OK
Ext: 
St: urn:schemas-upnp-org:service:RenderingControl:1
Server: Windows10/10.0 UPnP/1.0 BubbleUPnPServer/0.9-update38
Usn: uuid:a650210f-9d3e-1235-0000-00004d059e7e::urn:schemas-upnp-org:service:RenderingControl:1
Cache-control: max-age=1800
Location: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml

17:07:34 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP Discovery: AV renderer: http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
17:07:36 [INFO] SSDP discovery: Skipping known Renderer at http://192.168.1.99:49855/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
17:07:36 [DEBUG] (4) swyh_rs::openhome::avmedia: Getting new renderer descriptions
17:07:36 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery complete
17:10:04 [ERROR] Error accepting new client: Ein Blockierungsvorgang wurde durch einen Aufruf von WSACancelBlockingCall unterbrochen. (os error 10004

dheijl commented 3 years ago

I can send anything you want, I'll make a version (tomorrow) that continuously sends silence for you to test.

dheijl commented 3 years ago

This new beta sends continuous silence after 30 seconds of no-capture until capture is resumed.

I could not see any side-effects in my testing.

Silun commented 3 years ago

Thank you so much! On my first test, it worked just like it should. No disconnect after 25 minutes!

However, the weird issue from beta1 persists. It seems that when swyh-rs is run, the problem is either there or it isn't - but it will not develop later on if it didn't start with it, and it won't stop being there if it was present on startup. At least I have not seen either case yet.

It can clearly be seen in the log: The http connection is terminated and the audio abruptly goes silent for about 3 seconds. It matches up with the keepalive signal intervals of beta1, so I assume it has something to do with that.

Here's the log, the terminations and reconnects are what's being written to the log as it happens.

Configuration { auto_resume: true, sound_source: "Hi-Fi Cable Input (VB-Audio Hi-Fi Cable)", log_level: Debug, ssdp_interval_mins: 10.0, auto_reconnect: true, disable_chunked: false, last_renderer: "BubbleUPnP Google Cast DLNA renderer Nest Audios (DLNA)", config_dir: "C:\\Users\\acrel\\swyh-rs" }
Setup audio sources
Now running at ABOVE_NORMAL_PRIORITY_CLASS
Capturing audio from: Hi-Fi Cable Input (VB-Audio Hi-Fi Cable)
Default audio SupportedStreamConfig { channels: 2, sample_rate: SampleRate(44100), buffer_size: Unknown, sample_format: F32 }
The wave_reader is now receiving samples
Starting SSDP discovery
The streaming server is listening on http://192.168.1.99:5901/stream/swyh.wav
Sample rate: 44100, sample format: audio/l16 (PCM)
AV Stop playing on Nest Audios (DLNA) host=192.168.1.99 port=49855
AV Start playing on Nest Audios (DLNA) host=192.168.1.99 port=49855 from 192.168.1.99 using AvTransport Play
Received request /stream/swyh.wav from 192.168.1.99:52718
=>Http connection with 192.168.1.99:52718 terminated [Eine bestehende Verbindung wurde softwaregesteuert
durch den Hostcomputer abgebrochen. (os error 10053)]
Streaming to 192.168.1.99:52718 has ended
Received request /stream/swyh.wav from 192.168.1.99:52725
Received request /stream/swyh.wav from 192.168.1.99:52726
=>Http connection with 192.168.1.99:52725 terminated [Eine vorhandene Verbindung wurde vom Remotehost geschlossen. (os error 10054)]
Streaming to 192.168.1.99:52725 has ended
Received request /stream/swyh.wav from 192.168.1.99:52732
=>Http connection with 192.168.1.99:52726 terminated [Eine vorhandene Verbindung wurde vom Remotehost geschlossen. (os error 10054)]
Streaming to 192.168.1.99:52726 has ended
Received request /stream/swyh.wav from 192.168.1.99:52775
=>Http connection with 192.168.1.99:52732 terminated [Eine vorhandene Verbindung wurde vom Remotehost geschlossen. (os error 10054)]
Streaming to 192.168.1.99:52732 has ended
Received request /stream/swyh.wav from 192.168.1.99:52784
=>Http connection with 192.168.1.99:52775 terminated [Eine vorhandene Verbindung wurde vom Remotehost geschlossen. (os error 10054)]
Streaming to 192.168.1.99:52775 has ended
Received request /stream/swyh.wav from 192.168.1.99:52801
=>Http connection with 192.168.1.99:52784 terminated [Eine vorhandene Verbindung wurde vom Remotehost geschlossen. (os error 10054)]
Streaming to 192.168.1.99:52784 has ended
Received request /stream/swyh.wav from 192.168.1.99:52811

dheijl commented 3 years ago

Could you disable auto-resume and disable chunked transfer encoding and try again? Auto-resume should not be needed if you disable chunked transfer encoding, and chunked transfer encoding is best disabled for av-transport renderers. Chunked transfer can be disabled for openhome renderers too, but it should not matter for openhome. I have not experienced your problems but that is probably because I do not use auto-resume, as it should really not be needed anymore now that you can disable chunked transfer.

Silun commented 3 years ago

OK, I will try that. It won't be easy to tell if that fixes it though, since it happens seemingly at random.

Silun commented 3 years ago

It works almost perfectly now with disabled autoresume and chunked recording! I have not had the audio cut out in my testing, and it keeps sending silence and the connection stays up for a long time. After a couple of hours though, it still does disconnect. I am not sure what the problem is honestly. I have the debug log and I marked the positions where it stopped sending silence (around 20:30 as seen in my network monitoring) and where I manually reconnected by pressing the button in the window (around 20:56, the yellow indicator had gone grey).

Do you have any idea what could be going on? I have heard about infinitely long streams sometimes being an issue, but my limit for that is at 2h4m16s as per my testing, which is much shorter than what happened here. Weird.

Here's the full log, but since that one is 1000 lines long I have copied the parts that are probably the most interesting:



20:20:07 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP Discovery: AV renderer: http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
20:20:08 [INFO] SSDP discovery: Skipping known Renderer at http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
20:20:08 [DEBUG] (4) swyh_rs::openhome::avmedia: Getting new renderer descriptions
20:20:08 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery complete
20:30:08 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery started
20:30:11 [DEBUG] (4) swyh_rs::openhome::avmedia: UDP response at 2894 from 192.168.1.99:55534: 
HTTP/1.1 200 OK
Ext: 
St: urn:schemas-upnp-org:service:RenderingControl:1
Server: Windows10/10.0 UPnP/1.0 BubbleUPnPServer/0.9-update38
Usn: uuid:a650210f-9d3e-1235-0000-00004d059e7e::urn:schemas-upnp-org:service:RenderingControl:1
Cache-control: max-age=1800
Location: http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml

-----------------------------------------------
This is where it stopped sending, at 20:30 as per my network monitoring.
-----------------------------------------------

20:30:11 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP Discovery: AV renderer: http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
20:30:11 [INFO] SSDP discovery: Skipping known Renderer at http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
20:30:11 [DEBUG] (4) swyh_rs::openhome::avmedia: Getting new renderer descriptions
20:30:11 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery complete
20:30:30 [DEBUG] (14) swyh_rs: Now have 0 streaming clients left
20:30:30 [INFO] tb_log: Streaming to 192.168.1.99:50166 has ended
20:40:11 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery started
20:40:12 [DEBUG] (4) swyh_rs::openhome::avmedia: UDP response at 764 from 192.168.1.99:55534: 
HTTP/1.1 200 OK
Ext: 
St: urn:schemas-upnp-org:service:RenderingControl:1
Server: Windows10/10.0 UPnP/1.0 BubbleUPnPServer/0.9-update38
Usn: uuid:a650210f-9d3e-1235-0000-00004d059e7e::urn:schemas-upnp-org:service:RenderingControl:1
Cache-control: max-age=1800
Location: http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml

20:40:12 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP Discovery: AV renderer: http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
20:40:14 [INFO] SSDP discovery: Skipping known Renderer at http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
20:40:14 [DEBUG] (4) swyh_rs::openhome::avmedia: Getting new renderer descriptions
20:40:14 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery complete
20:50:14 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery started
20:50:17 [DEBUG] (4) swyh_rs::openhome::avmedia: UDP response at 2397 from 192.168.1.99:55534: 
HTTP/1.1 200 OK
Ext: 
St: urn:schemas-upnp-org:service:RenderingControl:1
Server: Windows10/10.0 UPnP/1.0 BubbleUPnPServer/0.9-update38
Usn: uuid:a650210f-9d3e-1235-0000-00004d059e7e::urn:schemas-upnp-org:service:RenderingControl:1
Cache-control: max-age=1800
Location: http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml

20:50:17 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP Discovery: AV renderer: http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
20:50:18 [INFO] SSDP discovery: Skipping known Renderer at http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/desc.xml
20:50:18 [DEBUG] (4) swyh_rs::openhome::avmedia: Getting new renderer descriptions
20:50:18 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery complete

-----------------------------------------------
This is where I manually clicked the button to reconnect, and music started playing again after this.
-----------------------------------------------

20:55:53 [DEBUG] (1) swyh_rs: Pushed renderer #0 BubbleUPnP Google Cast DLNA renderer Nest Audios (DLNA), state = ON
20:55:53 [INFO] tb_log: AV Stop playing on Nest Audios (DLNA) host=192.168.1.99 port=49840
20:55:53 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#Stop,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><s:Envelope s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/" xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"><s:Body><u:Stop xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"><InstanceID>0</InstanceID></u:Stop></s:Body></s:Envelope>
20:55:53 [INFO] sending request POST http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
20:55:53 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49840
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#Stop"
Content-Type: text/xml; charset="utf-8"
Content-Length: 288

20:55:54 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
20:55:54 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:StopResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

20:55:54 [INFO] tb_log: AV Start playing on Nest Audios (DLNA) host=192.168.1.99 port=49840 from 192.168.1.99 using AvTransport Play
20:55:54 [DEBUG] (1) swyh_rs::openhome::avmedia: AvTransport server URL: http://192.168.1.99:5901/stream/swyh.wav
20:55:54 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#SetAVTransportURI,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:SetAVTransportURI xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"><InstanceID>0</InstanceID><CurrentURI>http://192.168.1.99:5901/stream/swyh.wav</CurrentURI><CurrentURIMetaData>&lt;DIDL-Lite xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot; xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot;&gt;&lt;item id=&quot;1&quot; parentID=&quot;0&quot; restricted=&quot;0&quot;&gt;&lt;dc:title&gt;swyh-rs&lt;/dc:title&gt;&lt;res bitsPerSample=&quot;16&quot; nrAudioChannels=&quot;2&quot; protocolInfo=&quot;http-get:*:audio/l16;rate=44100;channels=2:DLNA.ORG_PN=LPCM&quot; sampleFrequency=&quot;44100&quot; duration=&quot;0&quot; &gt;http://192.168.1.99:5901/stream/swyh.wav&lt;/res&gt;&lt;upnp:class&gt;object.item.audioItem.musicTrack&lt;/upnp:class&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;</CurrentURIMetaData></u:SetAVTransportURI></s:Body></s:Envelope>
20:55:54 [INFO] sending request POST http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
20:55:54 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49840
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#SetAVTransportURI"
Content-Type: text/xml; charset="utf-8"
Content-Length: 1099

20:55:54 [INFO] tb_log: Received request /stream/swyh.wav from 192.168.1.99:58234
20:55:54 [DEBUG] (16) swyh_rs: Now have 1 streaming clients
20:55:59 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
20:55:59 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:SetAVTransportURIResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

20:55:59 [DEBUG] (1) swyh_rs::openhome::avmedia: url: http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action,
=>SOAP Action: urn:schemas-upnp-org:service:AVTransport:1#Play,
=>SOAP xml: 
<?xml version="1.0" encoding="utf-8"?><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>
20:55:59 [INFO] sending request POST http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
20:55:59 [DEBUG] (1) ureq::unit: writing prelude: POST /dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action HTTP/1.1
Host: 192.168.1.99:49840
Connection: close
User-Agent: swyh-rs-Rust/0.x
Accept: */*
SOAPAction: "urn:schemas-upnp-org:service:AVTransport:1#Play"
Content-Type: text/xml; charset="utf-8"
Content-Length: 304

20:55:59 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49840/dev/a650210f-9d3e-1235-0000-00004d059e7e/svc/upnp-org/AVTransport/action
20:55:59 [DEBUG] (1) swyh_rs::openhome::avmedia: <=SOAP response: <?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:PlayResponse xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"/></s:Body></s:Envelope>

20:56:07 [DEBUG] (16) swyh_rs: Now have 0 streaming clients left
20:56:07 [INFO] tb_log: Streaming to 192.168.1.99:58234 has ended
20:56:07 [INFO] tb_log: Received request /stream/swyh.wav from 192.168.1.99:58241
20:56:07 [DEBUG] (17) swyh_rs: Now have 1 streaming clients

Silun commented 3 years ago

Oh, since you mentioned there wasn't really a good way to add a tray icon to swyh-rs, I took that as a cue to make something to work around this general problem. So I made Trayify, a small windows utility to run any program while hiding its window, and also add a tray icon to quickly toggle the window's visibility.

dheijl commented 3 years ago

Oh, since you mentioned there wasn't really a good way to add a tray icon to swyh-rs, I took that as a cue to make something to work around this general problem. So I made Trayify, a small windows utility to run any program while hiding its window, and also add a tray icon to quickly toggle the window's visibility.

Thanks! I'll add it to the wiki.

dheijl commented 3 years ago

Here's the full log, but since that one is 1000 lines long I have copied the parts that are probably the most interesting:

The full log is no longer available at Pastebin, could you zip it and upload it here?

Is there a reason you're not using the Chromecast in OpenHome mode? In OpenHome mode AutoResume should reconnect without problems when Bubble or the Chromecast decide to disconnect for some reason.

This problem with "infinitely long streams" may be specific to Bubble or to the Chromecast, it has not been reported before here and I have never experienced it myself (using OpenHome renderers).

Edit: But I do know from experience that a Chromecast Audio will randomly disconnect from Spotify Connect, while it never does this when casting from Chrome. That's why I ditched my Chromecast Audio's for home-brew RPI 4 Volumio devices.

Silun commented 3 years ago

Weird how that log disappeared. Also, I wasn't aware I could upload files to messages here.

log_disconnect.zip

I was using DLNA mode because in my previous testing there were issues with OpenHome and the foobar2000 upnp module. I will enable OpenHome as well, IIRC swyh-rs will just ignore the DLNA renderer and go with OpenHome if both are available anyway. I will test and report back!

As far as settings go, I should use:

OpenHome in BubbleUPNP
Autoresume CHECKED
Autoreconnect CHECKED
Disable Chunked TransferEncoding UNCHECKED

Is that right?

Silun commented 3 years ago

Okay, interesting. There was a serious problem with the configuration as outlined in my last post. Here's a recap:

swyh-rs configured as above
OpenHome enabled in BubbleUPNP
Have music already playing
Start swyh-rs
swyh-rs freezes time and time again, only recovering for a split second during which audio is actually streamed, silence between the short bursts
Will only close if task is killed

log_openhome-crazy-behaviour.zip

The problem only exists when Autoresume is checked on startup of swyh-rs. If it's disabled, swyh-rs doesn't freeze.

Edit: Same behaviour in v1.2.1!

dheijl commented 3 years ago

I'll do some testing with Bubble myself.

Autoresume can get in a "loop" depending on how the renderer responds, I think it's a timing issue, but I thought it only happened with AV transport. I have never seen it with Openhome.

I would check "disable chunked transfer" as this should always work even if it's against the http 1.1 standard.

Without autoresume Openhome should work without any problems unless Bubble or Chromecast have problems with the endless stream.

dheijl commented 3 years ago

For the first case (AVTransport that stops streaming after some hours):

Apparently the streaming connection gets closed without any error, which makes me think that my HTTP server has closed the connection because it thinks that it has sent the complete contents of the stream, although the CONTENT-LENGTH header is set to u64.MAX. Perhaps there is a math error (overflow?) somewhere in tiny-http, I'll check that.

For the second case, Openhome:

It's indeed a timing problem with Autoresume: Bubble sends a streaming GET request before it has received the Play command but immediately aborts it, this makes Autoresume kick in, but the Play command has already been sent now, which causes Bubble to make a new streaming GET request that now gets aborted by Autoresume etc...

I think that the first request from Bubble should be a HEAD request (to check on the stream parameters) and not a GET request. At least that is what Volumio renderers do...

I think I will remove the Autoresume option, as it only causes trouble. I will perhaps remove the Disable Chunked Transfer option too, and ditch chunked transfer altogether. It has been removed from the HTTP 2.0 standard also and replaced by a better scheme, probably because many clients do not support it properly.

Silun commented 3 years ago

Alright, thank you for checking! In the meantime, I have also come across something.

I am using OpenHome now, which is nice because the latency is considerably smaller, too. It is about 1 second now, I'd say. When I boot up my PC, I can hear the sound signaling the successful connection of swyh-rs (I am starting it on logon with a 1 minute delay to make sure BubbleUPNP is up). However if there is no audio playing - there usually isn't unless I'm actively testing - it also won't start to send the keepalive silence signal, resulting in a disconnect soon thereafter (and autoresume is set to off, naturally). I think currently the silence won't be sent before the event The wave_reader is now receiving samples has been logged. If autoresume is going to go away and continuous silence will replace it, then it should probably not wait for this kind of 'go!' signal.

Also, sometimes it'll play audio and just keep disconnecting time and time again. It's about the same rhythm that it had the bursts of silence back on DLNA in, but on OpenHome it just flat out disconnects.

Log attached here: log_openhome-many-disconnects.zip

Silun commented 3 years ago

Happy new year!

After swyh-rs has been running for some hours, I am getting random disconnects. This isn't the first time that has happened, but I figured it was a one time random occurrence before. It happens at 07:21:31 at the very end of the log. One song finishes, and right between the songs there's a disconnect. The timing might have been random though because I don't see how either swyh-rs or BUPNP would detect the end of a song. Maybe autoresume isn't obsolete after all?

log_sudden-disconnect.zip

dheijl commented 3 years ago

Happy new year to you too!

However if there is no audio playing - there usually isn't unless I'm actively testing - it also won't start to send the keepalive silence signal, resulting in a disconnect soon thereafter (and autoresume is set to off, naturally). I think currently the silence won't be sent before the event The wave_reader is now receiving samples has been logged. If autoresume is going to go away and continuous silence will replace it, then it should probably not wait for this kind of 'go!' signal.

I can't reproduce this here: with no music playing when swyh-rs starts with autoreconnect the silence kicks in after 30 seconds (checked with Wireshark).

Maybe autoresume isn't obsolete after all?

I'll have to devise a way to fix the autoresume behaviour with Bubble Openhome. It's not that simple because the player control and the streaming server run in seperate threads that are not aware of each other.

dheijl commented 3 years ago

Could you give the new 1.2.3 beta a try ?

I removed the SeekId OpenHome action, as it is not needed I think, and it causes the extra GET streaming request from Bubble. Volumio ignores it, but Bubble implements it.

Silun commented 3 years ago

Yes, I will test that!

I have created a bit of documentation about swyh not sending silence before logging the first received samples, see this imgur gallery. It's not wireshark, but GlassWire is probably reputable enough.

The corresponding log is this, all times are of course shifted by 1 hour as always:

log.zip

dheijl commented 3 years ago

This log is still from the 1.2.2 version that uses the SeekId command that causes problems with Bubble. Silence gets never sent because Bubble keeps refusing the Play command because the preceding SeekId received no data so the 30 second timeout never gets triggered, if I read the log correctly. And thanks for your patience....

Silun commented 3 years ago

Oh yes, those were 1.2.2 logs. Probably should have made that clear, sorry. It was meant as a reponse to wireshark not showing the same situation that I experienced. I figured it might help when it couldn't be reproduced. I see now that you already knew what was going on there, sorry if I caused unnecessary work.

This is on 1.2.3, autoresume will still cause the freezing problem on startup. log_123-freeze-on-startup.zip

dheijl commented 3 years ago

Apparently Bubble too uses a 30 second timeout waiting for music, because after 30 seconds it breaks the first streaming connection and starts a second streaming request but in the meantime autoresume has seen the first connection being lost and kicks in messing things up even more by aborting the second connection and so on....

dheijl commented 3 years ago

The new 1.3.0 release should fix the time-out clash, silence now starts sending after 15 seconds instead of after 30 seconds. So Autoresume should no longer kick in because Bubble would not wait long enough and break the connection before silence was being sent.

I tested this with Bubble in the following configuration:

Autoresume set
Autoreconnect set
Disable Chunked Transfer Encoding set
a Bubble Openhome renderer selected

I then started swyh-rs with no music playing, it selected the renderer, and started sending silence after 15 sceconds without any complaints from Bubble.

Silun commented 3 years ago

The silence is getting sent as it should for me, as well! I have been using v1.2.3b2 and wanted to share a log, but I see you have released something new. So those logs are probably not very interesting, I am not sure. It's a log of audio interruptions occuring every ~15 seconds. I'll upload it just in case and switch over to v1.3.0.

log_audio-interrupt.zip

dheijl commented 3 years ago

So it looks that it is actually sending the silence that causes Bubble or Nest to abort the connection, because this now happens after 15 seconds, the exact moment the silence now kicks in, while with the previous version it happened after 30 seconds, also exactly when the silence kicked in.
When I test here with Bubble this does not happen, and this makes me think that it is the Nest that refuses to accept the silence audio stream, and not Bubble. I don't have Nest Audio, but I'll try to unearth an old Chromecast Audio, perhaps they are similar enough to reproduce your problem with Nest.

Edit: I can reproduce the problem with a Chromecast Audio and Bubble UPNP. The Chromecast does not respond to the play command until it has actually received something or times out, causing the hang in the UI (a "play" button press callback waits for an answer from the renderer).

dheijl commented 3 years ago

Should finally be fixed in 1.3.1. Now swyh-rs always starts with an immediate initial 250 msec silence, then waits for music for 2 seconds before sending silence continuously. If music is captured, switch to the music immediately. If music stops, start sending continuous silence after 2 seconds of no music capture.

Silun commented 3 years ago

Thank you so much! I will check it out. I'm glad that it's reproducible and I am not seeing ghosts!

There is something happening in 1.3.0 that crashes swyh-rs, I believe. I started it, used it for a bit, then went to bed leaving my PC powered up with swyh-rs running. When I came back, I found swyh-rs not running any more. It has happened twice, so it's not a one-off thing. This is the crash-again log. There was no attempt to use google cast in that log IIRC.

Another crash happened when for testing purposes I had cast a tab in MS Edge, then switched to swyh-rs and it crashed within about a minute. This is the crash-google-cast log.

The logs look similar to me so I am grouping them.

log_crashes-130.zip

Edit: 1.3.1 on first run had sort of like an 'inverse' stuttering interruption issue, where every couple of seconds there would be a split second of sound, and silence in the much longer periods between those little episodes of sound. The second time I ran it, it just worked like it should. I have seen this issue where swyh needs 2 attempts to start up right (after not being used for some hours) many times but always figured it's probably just my chromecasts or bubble acting up.

log_131-first-run-sporadic-sound.zip

dheijl commented 3 years ago

I know about the crashes, they are unrelated and caused by changed behaviour in the ureq library. Should be fixed in the new 1.3.2 beta.

Wifi connections can cause stuttering in the sound.

The sporadic sound is a mystery: Bubble starts more than 1 stream for some reason, I have never seen that here. It then disconnects the first stream causing the second one to be dropped too by swyh-rs...

Silun commented 3 years ago

Total shot in the dark, but might it be related to my Chromecasts being a stereo pair, that is 2 identical devices linked together for real stereo sound? 2 Streams just sounds like Bubble is trying to reach them separately or something. Do you think that log is basis enough to open an issue over there?

dheijl commented 3 years ago

I have no idea, I didn't know that this was possible... Also, why does Bubble close the 1st stream almost immediately and starts a second stream only then followed by a response to the original Play request?

19:45:26 [INFO] tb_log: Received request /stream/swyh.wav from 192.168.1.99:52790 19:45:26 [DEBUG] (7) swyh_rs: Now have 1 streaming clients 19:45:28 [DEBUG] (7) swyh_rs: Now have 0 streaming clients left 19:45:28 [INFO] tb_log: Streaming to 192.168.1.99:52790 has ended 19:45:28 [INFO] tb_log: Received request /stream/swyh.wav from 192.168.1.99:52793 19:45:28 [DEBUG] (8) swyh_rs: Now have 1 streaming clients 19:45:32 [DEBUG] (1) ureq::unit: response 200 to POST http://192.168.1.99:49865/dev/a650210f-9d3e-1235-ffff-ffffe284001a/svc/av-openhome-org/Playlist/action

And further on those two streams continuously abort each other...

I'll look a bit more at those logs and do some more testing with a Chromecast and let you know if I find something...

What happens if you disable autoresume?

Silun commented 3 years ago

What happens if you disable autoresume?

That is quite hard to test as I am not able to reproduce this at will. What would you have me do, disable autoresume and wait until it happens again?

Edit: Okay, stroke of luck. I updated to v1.3.2 and the first time I started it, the same issue arose. During the episodes of silence, swyh is frozen. It started up with autoresume ticked, I managed to untick it, and it started working right pretty much instantly. When I ticked autoresume again about 30 seconds later, it still worked right as far as I can tell.

log_132-autoresume-fix.zip

dheijl commented 3 years ago

1.3.2 will hopefully fix it, I now support multiple streaming connections from the same renderer, and autoresume will not kick in if a connection has been closed but a new connection has already started by the time autoresume is checked in the" connection closed" logic.

Silun commented 3 years ago

It seems to work quite well now, at least I haven't found any major issues, except one thing. When a stream is started, it'll show up as a 6:45:48 long stream in the chromecast app. When that time has passed, it seems autoresume will not resume or start a new stream, it just ends silently. Starting audio at that point doesn't seem to do anything. In the interface, it'll still say it is connected, but no audio will play. When I click the renderer button twice to disconnect and then reconnect, it works again.

Log of this happening right here, audio was tested about a minute before the end of the log right before the manual reconnect.

log_7-hours.zip

dheijl commented 3 years ago

So it looks like it's usable now for you?

Would you be prepared to run the same test but with Chunked Transfer Encoding not disabled?

The reason I ask this:

Without chunked transfer encoding the length of the stream (in bytes) is given in the Http Content-Length header. I pass in the value u64::MAX - 1 (18.446.744.073.709.551.614 bytes), which corresponds to about 29 billion hours of music at 44 KHz 16 bit stereo, and that is certainly longer than 6:45:48. I copied this content length value from other SWYH-like programs like Local Audio Broadcast. It's possible that Bubble or the Chromecast somehow have to truncate this length for the Chromecast protocol. So I think that 6:45:48 stream length is generated somewhere between Bubble and the Chromecast.

With chunked transfer encoding there is no content length, but each "chunk" (8KB here) contains the chunk length, with a zero length chunk meaning the end of the stream.

Also, I don't think that after the 6:45:48 swyh-rs is sending silence, as it should still be sending music as long as the PC is playing music. I think that the stream between Bubble and Nest Audio is somehow "suspended", and that the connection with swyh-rs is still alive.

The only way to make sure is to fire up a network sniffer like Wireshark and capture the music stream packets on the loopback interface (127.0.0.1, not the real network interface) between swyh-rs and Bubble (on port 5901) once the "silence" started after 6:45:48.

Silun commented 3 years ago

Okay, weird. After your comment about Wireshark, I looked it up in Glasswire (which does a somewhat coarse bookkeeping about past transmitted data), and it seems that swyh-rs stopped streaming much, much earlier.

18:30 - start of swyh and starting to stream audio
20:10 - swyh stops to stream any data except for something that amounts to ~2 kB per hour
Around 21:15 swyh-rs stops sending even those 2 kB things and sends 0 kB from that point onward until I manually disconnect and reconnect at the end of the log

So perhaps it was something else indeed.

These are the events from the log that happen around that time where it stopped sending:

20:00:07 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP Discovery: OH renderer: http://192.168.1.99:49850/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml
20:00:08 [INFO] SSDP discovery: Skipping known Renderer at http://192.168.1.99:49850/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml
20:00:08 [DEBUG] (4) swyh_rs::openhome::avmedia: Getting new renderer descriptions
20:00:08 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery complete
20:10:08 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery started
20:10:09 [DEBUG] (4) swyh_rs::openhome::avmedia: UDP response at 601 from 192.168.1.99:51081: 
HTTP/1.1 200 OK
Ext: 
St: urn:av-openhome-org:service:Product:1
Server: Windows10/10.0 UPnP/1.0 BubbleUPnPServer/0.9-update38
Usn: uuid:a650210f-9d3e-1235-ffff-ffffe284001a::urn:av-openhome-org:service:Product:1
Cache-control: max-age=1800
Location: http://192.168.1.99:49850/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml

20:10:09 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP Discovery: OH renderer: http://192.168.1.99:49850/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml
20:10:11 [INFO] SSDP discovery: Skipping known Renderer at http://192.168.1.99:49850/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml
20:10:11 [DEBUG] (4) swyh_rs::openhome::avmedia: Getting new renderer descriptions
20:10:11 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery complete
20:20:11 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery started
20:20:14 [DEBUG] (4) swyh_rs::openhome::avmedia: UDP response at 2234 from 192.168.1.99:51081: 
HTTP/1.1 200 OK
Ext: 
St: urn:av-openhome-org:service:Product:1
Server: Windows10/10.0 UPnP/1.0 BubbleUPnPServer/0.9-update38
Usn: uuid:a650210f-9d3e-1235-ffff-ffffe284001a::urn:av-openhome-org:service:Product:1
Cache-control: max-age=1800
Location: http://192.168.1.99:49850/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml

20:20:14 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP Discovery: OH renderer: http://192.168.1.99:49850/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml
20:20:14 [INFO] SSDP discovery: Skipping known Renderer at http://192.168.1.99:49850/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml
20:20:14 [DEBUG] (4) swyh_rs::openhome::avmedia: Getting new renderer descriptions
20:20:14 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery complete
20:30:14 [DEBUG] (4) swyh_rs::openhome::avmedia: SSDP discovery started
20:30:17 [DEBUG] (4) swyh_rs::openhome::avmedia: UDP response at 2487 from 192.168.1.99:51081: 
HTTP/1.1 200 OK
Ext: 
St: urn:av-openhome-org:service:Product:1
Server: Windows10/10.0 UPnP/1.0 BubbleUPnPServer/0.9-update38
Usn: uuid:a650210f-9d3e-1235-ffff-ffffe284001a::urn:av-openhome-org:service:Product:1
Cache-control: max-age=1800
Location: http://192.168.1.99:49850/dev/a650210f-9d3e-1235-ffff-ffffe284001a/desc.xml

Which do look fairly normal, right? At least nothing special at 20:10 that would explain why it stopped streaming. So I guess this really wasn't about the 6:45:48. I will try to check what happens at this time limit both with and without chunked transfer over the next days.

dheijl commented 3 years ago

Nothing to see in the log as you say. Swyh-rs can not stop streaming, it will always send music or silence as long as the http conection is alive. What can happen is that the receiving side can no longer accept data, so that the tcp window reaches 0 at which point only ack/nak/rst messages (only a few bytes) can be exchanged, but no data until the tcp window on the receiving side is updated to a normal value. The http streaming layer is unaware of this. But the only way to detect it is with a network sniffer. I don't know if chunked transfer will make any difference....

dheijl commented 3 years ago

I will close this now. You can always reopen if needed.

dheijl / swyh-rs

Autoresume not working with BubbleUPNP and Nest Audio #27