0.15 client sound sporadically breaks

[totaam]

Issue migrated from trac ticket # 986

component: client | priority: major | resolution: fixed

2015-09-24 02:35:19: afarr created the issue

---

Testing with 0.15.0 and 0.15.6 client and server (osx and win32 clients, fedora 21 server, r-approximately at your releases of 0.15.0 & 0.15.6) I have been seeing (hearing?) sound sporadically breaking.

I haven't been able to find a reliable reproduction in terms of activity that induces it, but with a number of client machines I have seen it happening repeatedly for a while, then apparently stop doing so (haven't successfully narrowed down specific client circumstances inducing it though, it happens on a variety of client machines, while not happening to others on the same network, often repeatedly, despite those others running the same versions on similar or same OS).

In all cases, the client side has shown output similar to this:

2015-09-23 18:08:03,279 ignoring sound data with old sequence number 2 (now on 3)
2015-09-23 18:08:03,528 sound_sink_state_changed(sink_subprocess_wrapper(<subprocess.Popen object at 0x0800AAB0>), ready) on_sink_ready=<function sink_ready at 0x083274B0>
2015-09-23 18:08:03,529 sink_ready(()) codec=mp3
2015-09-23 18:08:03,700 sound_sink_exit() not the current sink, ignoring it
2015-09-23 18:08:03,701 sound_process_stopped(sink_subprocess_wrapper(None), ()) not the current sink, ignoring it

In one case the connection was over a vpn, in other cases the clients were on same local network as servers.

In the case over the vpn, which was recurring regularly, the client output also suggested a latency issue (failed to get xpra info):

2015-08-29 16:27:20,826 sound_sink_state_changed(sink_subprocess_wrapper(<subprocess.Popen object at 0x157f3070>), paused) on_sink_ready=None
2015-08-29 16:27:20,827 sound_sink_state_changed(sink_subprocess_wrapper(<subprocess.Popen object at 0x157f3070>), active) on_sink_ready=None
2015-08-29 16:27:26,583 unknown packet type: airgap-msg
Recv -  load_finished
2015-08-29 16:27:46,287 unknown packet type: airgap-msg
Recv -  load_finished
2015-08-29 16:32:46,916 re-starting speaker because of overrun
2015-08-29 16:32:46,917 stop_receiving_sound(True) sound sink=sink_subprocess_wrapper(<subprocess.Popen object at 0x157f3070>)
2015-08-29 16:32:46,918 stop_receiving_sound(True) calling <bound method sink_subprocess_wrapper.cleanup of sink_subprocess_wrapper(<subprocess.Popen object at 0x157f3070>)>
2015-08-29 16:32:46,919 stop_receiving_sound(True) done
2015-08-29 16:32:46,919 sound_sink_overrun() will restart in 0ms (server supports eos sequence: True)
2015-08-29 16:32:46,943 restarting sound sound_sink=None, codec=mp3, server_sound_sequence=True
2015-08-29 16:32:46,943 send_new_sound_sequence() sequence=1
2015-08-29 16:32:47,023 start_receiving_sound() sound sink=None
2015-08-29 16:32:47,025 start_sound_sink(mp3)
2015-08-29 16:32:47,025 starting mp3 sound sink
2015-08-29 16:32:47,096 mp3 sound sink started
2015-08-29 16:32:47,422 sound-sink internal error: write connection TwoFileConnection() reset: [Errno 32] Broken pipe
2015-08-29 16:32:47,423 sound_sink_exit() not the current sink, ignoring it
2015-08-29 16:32:47,425 sound_process_stopped(sink_subprocess_wrapper(None), ()) not the current sink, ignoring it
2015-08-29 16:32:47,546 sound_sink_exit() not the current sink, ignoring it
2015-08-29 16:32:47,612 server is not responding, drawing spinners over the windows
2015-08-29 16:32:47,694 ignoring sound data with old sequence number 0 (now on 1)
2015-08-29 16:32:47,695 ignoring sound data with old sequence number 0 (now on 1)
2015-08-29 16:32:47,695 ignoring sound data with old sequence number 0 (now on 1)
2015-08-29 16:32:47,740 ignoring sound data with old sequence number 0 (now on 1)


....

2015-08-29 16:32:47,846 ignoring sound data with old sequence number 0 (now on 1)
2015-08-29 16:32:47,863 server is OK again
2015-08-29 16:32:48,042 ignoring sound data with old sequence number 0 (now on 1)
2015-08-29 16:32:48,043 ignoring sound data with old sequence number 0 (now on 1)
2015-08-29 16:32:48,043 ignoring sound data with old sequence number 0 (now on 1)
2015-08-29 16:32:48,044 ignoring sound data with old sequence number 0 (now on 1)
2015-08-29 16:32:48,048 ignoring sound data with old sequence number 0 (now on 1)
2015-08-29 16:32:48,049 ignoring sound data with old sequence number 0 (now on 1)
** Message: pygobject_register_sinkfunc is deprecated (GstObject)
2015-08-29 16:32:49,596 the sound-sink process has failed to start, stopping it
2015-08-29 16:32:49,987 sound_sink_state_changed(sink_subprocess_wrapper(<subprocess.Popen object at 0x19f43a10>), ready) on_sink_ready=<function sink_ready at 0x157f8830>
2015-08-29 16:32:49,987 sink_ready(()) codec=mp3
2015-08-29 16:32:50,130 the mp3 sound sink has stopped
2015-08-29 16:32:50,131 stop_receiving_sound(True) sound sink=sink_subprocess_wrapper(None)
2015-08-29 16:32:50,131 stop_receiving_sound(True) calling <bound method sink_subprocess_wrapper.cleanup of sink_subprocess_wrapper(None)>
2015-08-29 16:32:50,132 stop_receiving_sound(True) done
2015-08-29 16:32:50,135 sound_process_stopped(sink_subprocess_wrapper(None), ()) not the current sink, ignoring it
2015-08-29 16:32:50,213 speaker is now disabled - dropping packet
2015-08-29 16:32:50,279 sound_sink_exit() not the current sink, ignoring it

In one case rebooting the client caused the problem to stop (failed to get an xpra info in time for that case too). The logs were essentially the same as above, but without the server is OK again message... probably because there weren't the same latency issues, since it was on the same network as the server.

In another case the same error messages seemed to be appearing, accompanied by a stuttering of the sound... but the sound seemed to restart successfully after a second or two (I'll attach an xpra info from this case). In this case, the client output was:

2015-09-23 18:21:48,025 re-starting speaker because of overrun
2015-09-23 18:21:48,058 stop_receiving_sound(True) sound sink=sink_subprocess_wrapper(<subprocess.Popen object at 0x0800AAB0>)
2015-09-23 18:21:48,059 ignoring sound data with old sequence number 3 (now on 4)
2015-09-23 18:21:48,125 stop_receiving_sound(True) calling <bound method sink_subprocess_wrapper.cleanup of sink_subprocess_wrapper(<subprocess.Popen object at 0x0800AAB0>)>
2015-09-23 18:21:48,233 ignoring sound data with old sequence number 3 (now on 4)
2015-09-23 18:21:48,233 stop_receiving_sound(True) done
2015-09-23 18:21:48,233 sound_sink_overrun() will restart in 0ms (server supports eos sequence: True)
2015-09-23 18:21:48,233 ignoring sound data with old sequence number 3 (now on 4)
2015-09-23 18:21:48,234 ignoring sound data with old sequence number 3 (now on 4)
2015-09-23 18:21:48,242 restarting sound sound_sink=None, codec=mp3, server_sound_sequence=True
2015-09-23 18:21:48,243 send_new_sound_sequence() sequence=4
2015-09-23 18:21:48,243 start_receiving_sound() sound sink=None
2015-09-23 18:21:48,243 start_sound_sink(mp3)
2015-09-23 18:21:48,243 starting mp3 sound sink
2015-09-23 18:21:48,252 mp3 sound sink started
2015-09-23 18:21:48,575 sound_sink_state_changed(sink_subprocess_wrapper(<subprocess.Popen object at 0x0832A0D0>), ready) on_sink_ready=<function sink_ready at 0x08327AB0>
2015-09-23 18:21:48,575 sink_ready(()) codec=mp3
2015-09-23 18:21:48,736 sound_sink_exit() not the current sink, ignoring it
2015-09-23 18:21:48,737 sound_process_stopped(sink_subprocess_wrapper(None), ()) not the current sink, ignoring it
2015-09-23 18:21:49,249 sound-sink using audio codec: MPEG 1 Audio, Layer 3 (MP3)
2015-09-23 18:21:49,263 sound_sink_state_changed(sink_subprocess_wrapper(<subprocess.Popen object at 0x0832A0D0>), paused) on_sink_ready=None
2015-09-23 18:21:49,265 sound_sink_state_changed(sink_subprocess_wrapper(<subprocess.Popen object at 0x0832A0D0>), active) on_sink_ready=None
2015-09-23 18:21:49,369 sound_sink_exit() not the current sink, ignoring it

In a number of other cases, there was no -d sound set and there was no sign of any other errors than the sound-sink internal error: write connection TwoFileConnection() reset: [Errno 32] Broken pipe which I have been seeing periodically but generally with no ill effect.

[totaam]

2015-09-24 02:37:52: afarr uploaded file ticket986_sound-buffer-break-info.txt (129.2 KiB)

xpra info for win client 0.15.6 v. fedora 21 0.15.6, with sound sink breaks and ignores by client

[totaam]

2015-09-24 08:30:14: antoine changed owner from antoine to afarr

[totaam]

2015-09-24 08:30:14: antoine commented

---

Sounds to me like the issues that #849 is meant to solve.
I don't think there's much we can do for 0.15 at this point.

See also #1003#comment:5, #855, #987

[totaam]

2015-12-05 11:33:38: antoine commented

---

See #855#comment:8

[totaam]

2015-12-09 01:23:43: afarr commented

---

As commented in #855, I'll try with latest - but previous tests have shown that sound was still breaking, and UI thread blocking was still occurring, even with -d sound logs running... and grepping through logs afterward to see if there were any smoking guns immediately on the heels of the UI thread blocking messages didn't elucidate any (though, oddly, I did occasionally see instances of a message that the UI thread was blocked, with no attendant message that it was re-starting).

I'll test with 0.16, and see if the sound survives a night alone, though I've seen it failing with 0.16 as well (never as quickly as was sometimes the case with 0.15). In either case, I suspect this one will have to be just closed as obsolete, and 0.16 issues dealt with separately.

[totaam]

2015-12-11 22:01:28: afarr commented

---

Testing some with 0.16.0 r11304 osx client against a 0.16.0 r11342 fedora 21 server, I am still finding that the sound drops, but it usually takes a number of hours.

Looking through the logs for one such test (which didn't involve letting the client go to sleep and all those issues) - I noticed that the 0.16.0 r11304 osx client doesn't have mp3 enabled, and is instead using wav.

skipping flac with GStreamer 1.x to avoid obscure 'not-neogtiated' errors I do not have time for
missing ['lamemp3enc', 'mad', 'mp3parse'] from ('lamemp3enc', None, 'mad', 'mp3parse')
missing ['lamemp3enc', 'mad'] from ('lamemp3enc', None, 'mad', 'mpegaudioparse')
missing ['opusenc', 'opusdec'] from ('opusenc', 'oggmux', 'opusdec', 'oggdemux')
initialized sound codecs:
* vorbis     : vorbisenc   , gdppay      , vorbisdec   , gdpdepay    
* wav        : wavenc      , None        , None        , wavparse    
* wavpack    : wavpackenc  , None        , wavpackdec  , wavpackparse
* speex      : speexenc    , oggmux      , speexdec    , oggdemux    
2015-12-09 16:34:46,342 query_sound() process returned 0
2015-12-09 16:34:46,342 query_sound() out=sources=osxaudiosrc,oss4src,osxaudiosrc,audiotestsrc
gst.version=1,4,5,0
encoders=vorbis,wav,wavpack,speex
demuxers=gdp,ogg
muxers=gdp,ogg
decoders=vorbis,wav,wavpack,speex
plugins=aacparse,ac3parse,amrparse,appsink,appsrc,audioamplify,audiochannelmix,audiochebband,audiocheblimit,audioconvert,audiodynamic,audioecho,audiofirfilter,audioiirfilter,audioinvert,audiokaraoke,audiomixer,audiopanorama,audiorate,audioresample,audiotestsrc,audiowsincband,audiowsinclimit,bin,capsfilter,dcaparse,downloadbuffer,faac,faad,fakesink,fakesrc,fdsink,fdsrc,filesink,filesrc,flacdec,flacenc,flacparse,flactag,funnel,gdpdepay,gdppay,identity,input-selector,mpegaudioparse,multiqueue,oggaviparse,oggdemux,oggmux,oggparse,ogmaudioparse,ogmtextparse,ogmvideoparse,oss4sink,oss4src,osxaudiosink,osxaudiosrc,output-selector,pipeline,queue,queue2,sbcparse,scaletempo,spacescope,spectrascope,speexdec,speexenc,synaescope,tee,typefind,valve,volume,vorbisdec,vorbisenc,vorbisparse,vorbistag,wavenc,wavescope,wavpackdec,wavpackenc,wavpackparse,wavparse
pygst.version=3,14,0

Not sure if that was contributing to the eventual sound loss... but I suspect it was not an intentional choice.

A quick check through the beta osx clients in your repo, and I find that r11206 is the latest that still has mp3. Since I assume it's a packaging issue (new gstreamer 1.0?) - I'll just mention it here... and will repeat a test on the sound with the client that has mp3, just in case.

[totaam]

2015-12-12 06:26:37: antoine commented

---

You should be using vorbis and not wav.
Ensuring that all the codecs are built and bundled correctly is blocker ticket #970.

[totaam]

2015-12-15 00:58:06: afarr commented

---

Added comment in #970 to indicate that osx builds in xpra/beta repo (and our repos) after r11206 do not support mp3.

Created #1052 to note that fedora 21 xpra/beta builds (as well as our builds) are not supporting vorbis.

Unfortunately, these two issues combine to leave me with no way to test osx issues on post r11206 builds except with wav...

[totaam]

2015-12-15 21:42:25: afarr commented

---

Ok... I think I finally found logs, both server and client side, with -d sound from 0.16 sound stop. I'll clip some bits here, since it took 7 hours of playing before it happened (over 1GB of text in each of the client and server logs... you don't want that).

Hmm... checking the connection of the logs though, in this case it was a 0.16.0 r11304 osx client against a 0.16.0 r11342 fedora 21 server - which, as mentioned above, means that the session was running with wav. (I'll clip in some log bits all the same... but I'll try to at least repro with mp3, if not vorbis).

Server side (I'll include from a little before the sound stopped all the way to when I disconnected, which was about 10 minutes later):

2015-12-10 16:07:35,994 info_update: {'pipeline': 'pulsesrc device=auto_null.monitor ! volume name=volume volume=1.0 ! wavenc ! appsink name=sink emit-signals=true max-buffers=10 drop=true sync=false async=false qos=false', 'codec_description': '', 'bytes': 2147428888, 'volume': 100, 'state': 'active', 'codec': 'wav', 'buffers': 2440262}
2015-12-10 16:07:35,994 sound_source_info: {'pipeline': 'pulsesrc device=auto_null.monitor ! volume name=volume volume=1.0 ! wavenc ! appsink name=sink emit-signals=true max-buffers=10 drop=true sync=false async=false qos=false', 'codec_description': '', 'pid': 25768, 'bytes': 2147428888, 'volume': 100, 'state': 'active', 'codec': 'wav', 'time': 1449792455, 'buffers': 2440262}
�[36m2015-12-10 16:07:35,998 sound source emit_buffer data=<type 'str'>, len=880, metadata={'duration': 9977324L, 'timestamp': 25394604988662L}�[0m
2015-12-10 16:07:35,999 new_sound_buffer(source_subprocess_wrapper(25768), 880, {'duration': 9977324, 'timestamp': 25394604988662, 'time': 1449792455998}) suspended=False
�[36m2015-12-10 16:07:36,011 sound source emit_buffer data=<type 'str'>, len=880, metadata={'duration': 9977324L, 'timestamp': 25394614965986L}�[0m
2015-12-10 16:07:36,012 new_sound_buffer(source_subprocess_wrapper(25768), 880, {'duration': 9977324, 'timestamp': 25394614965986, 'time': 1449792456011}) suspended=False
�[36m2015-12-10 16:07:36,016 sound source emit_buffer data=<type 'str'>, len=880, metadata={'duration': 9977324L, 'timestamp': 25394624943310L}�[0m
2015-12-10 16:07:36,017 new_sound_buffer(source_subprocess_wrapper(25768), 880, {'duration': 9977324, 'timestamp': 25394624943310, 'time': 1449792456016}) suspended=False
�[36m2015-12-10 16:07:36,027 sound source emit_buffer data=<type 'str'>, len=880, metadata={'duration': 9977325L, 'timestamp': 25394634920634L}�[0m
2015-12-10 16:07:36,028 new_sound_buffer(source_subprocess_wrapper(25768), 880, {'duration': 9977325, 'timestamp': 25394634920634, 'time': 1449792456027}) suspended=False
�[36m2015-12-10 16:07:36,035 sound source emit_buffer data=<type 'str'>, len=880, metadata={'duration': 9977324L, 'timestamp': 25394644897959L}�[0m
2015-12-10 16:07:36,037 new_sound_buffer(source_subprocess_wrapper(25768), 880, {'duration': 9977324, 'timestamp': 25394644897959, 'time': 1449792456035}) suspended=False
�[36m2015-12-10 16:07:36,045 sound source emit_buffer data=<type 'str'>, len=880, metadata={'duration': 9977324L, 'timestamp': 25394654875283L}�[0m
2015-12-10 16:07:36,046 new_sound_buffer(source_subprocess_wrapper(25768), 880, {'duration': 9977324, 'timestamp': 25394654875283, 'time': 1449792456045}) suspended=False
2015-12-10 16:07:36,046 sound_control(stop, ())
2015-12-10 16:07:36,047 stop_sending_sound() sound_source=source_subprocess_wrapper(25768)
2015-12-10 16:07:36,047 cleanup() sending cleanup request to sound source
2015-12-10 16:07:36,048 sound_control(new-sequence, (1,))
�[36m2015-12-10 16:07:36,050 sound source SoundPipeline.cleanup()�[0m
�[36m2015-12-10 16:07:36,050 sound source SoundPipeline.stop() state=active�[0m
2015-12-10 16:07:36,050 sound source stopping�[0m
2015-12-10 16:07:36,051 info_update: {'pipeline': 'pulsesrc device=auto_null.monitor ! volume name=volume volume=1.0 ! wavenc ! appsink name=sink emit-signals=true max-buffers=10 drop=true sync=false async=false qos=false', 'codec_description': '', 'bytes': 2147434168, 'volume': 100, 'state': 'active', 'codec': 'wav', 'buffers': 2440268}
2015-12-10 16:07:36,051 sound_source_info: {'pipeline': 'pulsesrc device=auto_null.monitor ! volume name=volume volume=1.0 ! wavenc ! appsink name=sink emit-signals=true max-buffers=10 drop=true sync=false async=false qos=false', 'codec_description': '', 'pid': 25768, 'bytes': 2147434168, 'volume': 100, 'state': 'active', 'codec': 'wav', 'time': 1449792456, 'buffers': 2440268}
�[36m2015-12-10 16:07:36,057 sound source emit_buffer data=<type 'str'>, len=880, metadata={'duration': 9977324L, 'timestamp': 25394664852607L}�[0m
�[36m2015-12-10 16:07:36,070 sound source new preroll1: <GstSample at 0x7f0c1801c0f0>�[0m
�[36m2015-12-10 16:07:36,075 sound source emit_buffer data=<type 'str'>, len=880, metadata={'duration': 9977325L, 'timestamp': 25394674829931L}�[0m
�[36m2015-12-10 16:07:36,094 sound source SoundPipeline.stop() done�[0m
�[36m2015-12-10 16:07:36,098 sound source SoundPipeline.cleanup() bus=<Bus object at 0x7f0c285405a0 (GstBus at 0x1e7aca0)>�[0m
�[36m2015-12-10 16:07:36,098 sound source SoundPipeline.cleanup() bus_message_handler_id=1�[0m
�[36m2015-12-10 16:07:36,100 sound source SoundPipeline.cleanup() done�[0m
2015-12-10 16:07:36,102 new_sound_buffer(source_subprocess_wrapper(25768), 880, {'duration': 9977324, 'timestamp': 25394664852607, 'time': 1449792456058}) suspended=False
2015-12-10 16:07:36,102 sound buffer dropped: from old source or closed
2015-12-10 16:07:36,102 new_sound_buffer(source_subprocess_wrapper(25768), 880, {'duration': 9977325, 'timestamp': 25394674829931, 'time': 1449792456076}) suspended=False
2015-12-10 16:07:36,103 sound buffer dropped: from old source or closed
2015-12-10 16:07:36,109 info_update: {'pipeline': 'pulsesrc device=auto_null.monitor ! volume name=volume volume=1.0 ! wavenc ! appsink name=sink emit-signals=true max-buffers=10 drop=true sync=false async=false qos=false', 'codec_description': *, 'bytes': 2147435928, 'volume': 0, 'state': 'unknown', 'codec': *, 'buffers': 2440270}
2015-12-10 16:07:36,110 sound_source_info: {'pipeline': 'pulsesrc device=auto_null.monitor ! volume name=volume volume=1.0 ! wavenc ! appsink name=sink emit-signals=true max-buffers=10 drop=true sync=false async=false qos=false', 'codec_description': *, 'pid': 25768, 'bytes': 2147435928, 'volume': 0, 'state': 'unknown', 'codec': *, 'time': 1449792456, 'buffers': 2440270}
�[36m2015-12-10 16:07:36,550 sound source stop() wrapped object=SoundSource('pulsesrc device=auto_null.monitor ! volume name=volume volume=1.0 ! wavenc ! appsink name=sink emit-signals=true max-buffers=10 drop=true sync=false async=false qos=false' - None)�[0m
�[36m2015-12-10 16:07:36,550 sound source SoundPipeline.cleanup()�[0m
�[36m2015-12-10 16:07:36,550 sound source SoundPipeline.cleanup() bus=None�[0m
�[36m2015-12-10 16:07:36,551 sound source stop() wrapped object=None�[0m
�[36m2015-12-10 16:07:36,551 sound source stop() wrapped object=None�[0m
2015-12-10 16:07:36,555 sound_source_exit(source_subprocess_wrapper(25768), ())
�[36m2015-12-10 16:07:36,563 sound source stop() wrapped object=None�[0m
2015-12-10 16:07:36,803 sound_source_exit(source_subprocess_wrapper(None), ())
2015-12-10 16:18:50,000 stop_sending_sound() sound_source=None
2015-12-10 16:18:50,070 xpra client disconnected.

Client side:

2015-12-10 16:07:35,147 info_update: {'queue.max': 130, 'pipeline': 'appsrc do-timestamp=1 name=src emit-signals=0 block=0 is-live=0 stream-type=stream format=4 ! wavparse ! audioconvert ! audioresample ! volume name=volume volume=1.0 ! queue name=queue min-threshold-time=0 max-size-buffers=0 max-size-bytes=0 max-size-time=450000000 leaky=2 ! osxaudiosink async=True qos=True sync=False', 'queue.pct': 1, 'queue.state': 'pushing', 'codec_description': 'uncompressed 16-bit pcm audio', 'bytes': 2147428888, 'queue.underruns': 0, 'volume': 100, 'state': 'active', 'queue.overruns': 7786, 'queue.cur': 1, 'buffers': 2440262, 'codec': 'wav', 'queue.min': 0}
�[36m2015-12-10 16:07:35,152 sound output add_data(880 bytes, {'duration': 9977324, 'timestamp': 25394604988662L, 'sequence': 0, 'time': 1449792455998L}) queue_state=pushing�[0m
�[36m2015-12-10 16:07:35,153 sound output pushed   880 bytes, new buffer level:   1ms, queue state=pushing�[0m
�[36m2015-12-10 16:07:35,153 sound output set_max_level lrange= 93, last_max_update=4168s�[0m
�[36m2015-12-10 16:07:35,153 sound output set_max_level overrun count=0 , margin= 50, pct= 0, cmst=130, mst=134�[0m
2015-12-10 16:07:35,192 sound output EOS�[0m
�[36m2015-12-10 16:07:35,192 sound output add_data(880 bytes, {'duration': 9977324, 'timestamp': 25394614965986L, 'sequence': 0, 'time': 1449792456011L}) queue_state=pushing�[0m
�[31m2015-12-10 16:07:35,193 sound output push-buffer error: <enum GST_FLOW_FLUSHING of type GstFlowReturn>�[0m
�[36m2015-12-10 16:07:35,193 sound output add_data(880 bytes, {'duration': 9977324, 'timestamp': 25394624943310L, 'sequence': 0, 'time': 1449792456016L}) queue_state=pushing�[0m
�[31m2015-12-10 16:07:35,193 sound output push-buffer error: <enum GST_FLOW_FLUSHING of type GstFlowReturn>�[0m
�[36m2015-12-10 16:07:35,194 sound output add_data(880 bytes, {'duration': 9977325, 'timestamp': 25394634920634L, 'sequence': 0, 'time': 1449792456027L}) queue_state=pushing�[0m
�[31m2015-12-10 16:07:35,194 sound output push-buffer error: <enum GST_FLOW_FLUSHING of type GstFlowReturn>�[0m
�[36m2015-12-10 16:07:35,195 sound output add_data(880 bytes, {'duration': 9977324, 'timestamp': 25394644897959L, 'sequence': 0, 'time': 1449792456035L}) queue_state=pushing�[0m
2015-12-10 16:07:35,195 stopping speaker because of error: push-buffer error: <enum GST_FLOW_FLUSHING of type GstFlowReturn>
����������������������������������������������������������������������������������������������������������������2015-12-10 16:07:35,195 stop_receiving_sound(True) sound sink=sink_subprocess_wrapper(13932)
2015-12-10 16:07:35,195 stop_receiving_sound(True) calling <bound method sink_subprocess_wrapper.cleanup of sink_subprocess_wrapper(13932)>
2015-12-10 16:07:35,195 cleanup() sending cleanup request to sound output
2015-12-10 16:07:35,196 stop_receiving_sound(True) done
2015-12-10 16:07:35,197 sound_sink_error(sink_subprocess_wrapper(13932), push-buffer error: <enum GST_FLOW_FLUSHING of type GstFlowReturn>) not the current sink, ignoring it
�[36m2015-12-10 16:07:35,197 sound output SoundPipeline.cleanup()�[0m
2015-12-10 16:07:35,197 sound_sink_error(sink_subprocess_wrapper(13932), push-buffer error: <enum GST_FLOW_FLUSHING of type GstFlowReturn>) not the current sink, ignoring it
�[36m2015-12-10 16:07:35,197 sound output SoundPipeline.stop() state=stopped�[0m
2015-12-10 16:07:35,197 sound_sink_error(sink_subprocess_wrapper(13932), push-buffer error: <enum GST_FLOW_FLUSHING of type GstFlowReturn>) not the current sink, ignoring it
2015-12-10 16:07:35,197 sound_sink_state_changed(sink_subprocess_wrapper(13932), stopped) not the current sink, ignoring it
�[36m2015-12-10 16:07:35,197 sound output SoundPipeline.stop() done�[0m
�[36m2015-12-10 16:07:35,197 sound output SoundPipeline.cleanup() bus=<Bus object at 0x5628530 (GstBus at 0x91fd80)>�[0m
�[36m2015-12-10 16:07:35,198 sound output SoundPipeline.cleanup() bus_message_handler_id=1�[0m
�[36m2015-12-10 16:07:35,198 sound output SoundPipeline.cleanup() done�[0m
2015-12-10 16:07:35,200 ignoring sound data with old sequence number 0 (now on 1)
2015-12-10 16:07:35,200 ignoring sound data with old sequence number 0 (now on 1)
2015-12-10 16:07:35,207 info_update: {'queue.max': 130, 'pipeline': 'appsrc do-timestamp=1 name=src emit-signals=0 block=0 is-live=0 stream-type=stream format=4 ! wavparse ! audioconvert ! audioresample ! volume name=volume volume=1.0 ! queue name=queue min-threshold-time=0 max-size-buffers=0 max-size-bytes=0 max-size-time=450000000 leaky=2 ! osxaudiosink async=True qos=True sync=False', 'queue.pct': 0, 'queue.state': 'pushing', 'codec_description': 'uncompressed 16-bit pcm audio', 'bytes': 2147429768, 'queue.underruns': 0, 'volume': 0, 'state': 'unknown', 'queue.overruns': 7786, 'queue.cur': 0, 'buffers': 2440263, 'codec': '', 'queue.min': 22}
�[36m2015-12-10 16:07:35,698 sound output stop() wrapped object=SoundSink('appsrc do-timestamp=1 name=src emit-signals=0 block=0 is-live=0 stream-type=stream format=4 ! wavparse ! audioconvert ! audioresample ! volume name=volume volume=1.0 ! queue name=queue min-threshold-time=0 max-size-buffers=0 max-size-bytes=0 max-size-time=450000000 leaky=2 ! osxaudiosink async=True qos=True sync=False' - None)�[0m
�[36m2015-12-10 16:07:35,698 sound output SoundPipeline.cleanup()�[0m
�[36m2015-12-10 16:07:35,698 sound output SoundPipeline.cleanup() bus=None�[0m
2015-12-10 16:07:35,699 sound_sink_exit() not the current sink, ignoring it
2015-12-10 16:07:35,699 sound_process_stopped(sink_subprocess_wrapper(None), ()) not the current sink, ignoring it
�[36m2015-12-10 16:07:35,699 sound output stop() wrapped object=None�[0m
�[36m2015-12-10 16:07:35,699 sound output stop() wrapped object=None�[0m
�[36m2015-12-10 16:07:35,700 sound output stop() wrapped object=None�[0m
2015-12-10 16:07:35,719 sound_sink_exit() not the current sink, ignoring it
2015-12-10 16:12:25,768 server is not responding, drawing spinners over the windows
2015-12-10 16:12:32,325 server is OK again

got signal SIGINT, exiting

Let me know if there's anything else I should search the logs for (or anything that might be worth watching for once I manage to repro with mp3 or vorbis).

[totaam]

2015-12-16 01:22:11: antoine changed status from new to assigned

[totaam]

2015-12-16 01:22:11: antoine changed owner from afarr to antoine

[totaam]

2015-12-16 01:22:11: antoine commented

---

The server stops because we tell it to (following the client stopping):

sound_control(stop, ())
stop_sending_sound() sound_source=source_subprocess_wrapper(25768)

Why the client stops is less clear:

sound output EOS

Followed by:

stopping speaker because of error: push-buffer error: <enum GST_FLOW_FLUSHING of type GstFlowReturn>

I'm not sure how it is possible to get an End-Of-Stream client side unless the server sends one. Maybe that's how we get told that the OSX client no longer wishes to output sound? (for power saving or whatever)

I'll try to write code to catch this EOS and attempt to restart the sound in that case.

[totaam]

2015-12-21 14:49:38: antoine changed status from assigned to new

[totaam]

2015-12-21 14:49:38: antoine changed owner from antoine to afarr

[totaam]

2015-12-21 14:49:38: antoine commented

---

r11452 should prevent the push-buffer error following an EOS: we will just drop new buffers instead of trying to push them. (will probably backport)

But I am still unclear on what is causing this EOS as there is not enough context in the log sample from comment:7. Did this EOS originate from the server? (the server logs start too late to tell - are both ends synced with NTP?)
If that is the case I would expect to see this message in the client log: server sent end-of-stream for sequence NNN, closing sound pipeline, and we would then need to know why the server decided to send it. This message would originate from the stop_sending_sound server source method, which can be called from:

• server shutdown (not the case here)
• an error during sound startup (unlikely since we aren't supposed to be re-starting the sound - should be obvious if that was the case)
• the xpra control channel request - which usually comes from the client itself (unless you use the control interface manually)

This last one comes from the client's stop_receiving_sound method, which is triggered by:

• a client shutdown (not the case here)
• an error during sound startup (again, unlikely here)
• the sound subprocess terminating (shouldn't happen unless we request it)
• an error in the sound subprocess

Each one of those would include a log message with the exact cause.

---

Summary of what I think is happening (assuming that the client and server clocks are out of sync):

• client: something we don't know happens
• client sends sound_control(stop, ()) and new-sequence to the server
• server stops the sound and sends an EOS to the client
• client stops sound

---

PS: we should use the sound sequence number to ensure we stop the correct sound source if we handle restarts (which we don't in 0.16, so no rush) - will try to tackle this one in 0.17

[totaam]

2015-12-23 14:08:25: antoine commented

---

r11474 should help: it ensures we never stop the wrong sound source, by checking the sequence number (if we ever send more than one stop request for the same sound source - which should not happen) - it will help more with 0.15.x than 0.16.x

[totaam]

2015-12-28 23:38:42: afarr commented

---

I did a search through the full 1.5 GB client side log file for the server sent end-of-stream for sequence NNN, closing sound pipeline message, and found no sign of it. Hopefully a bigger edit of client and server logs will help spot what's going on.

Looks like server and client clocks are within 1 second of each other (which, admittedly, can be a long set of logs), but not NTP sync'd. The client seems to be 1 second ahead of the server (or so the clock/date functions read... neither is giving me time in ms).

I'll attach a little over a minute of logs for both client and server from this last test, which should be more than enough to get better context (still several MB each)- and I'll include all the initial connection info at the beginning of the logs as well, in case there's something there of use.

[totaam]

2015-12-28 23:43:56: afarr uploaded file ticket986_client-log-d-sound_clipped.txt (4676.4 KiB)

just over a minute of -d sound client logs

[totaam]

2015-12-28 23:47:57: afarr uploaded file ticket986_server-log-d-sound_clipped.txt (3549.7 KiB)

just over a minute of -d sound server logs

[totaam]

2015-12-29 00:52:39: antoine changed status from new to assigned

[totaam]

2015-12-29 00:52:39: antoine changed owner from afarr to antoine

[totaam]

2015-12-29 00:52:39: antoine commented

---

I see nothing unusual in those logs before the EOS:

sound output add_data(880 bytes, {'duration': 9977324, 'timestamp': 25394604988662L, 'sequence': 0, 'time': 1449792455998L}) queue_state=pushing�
sound output pushed   880 bytes, new buffer level:   1ms, queue state=pushing�
sound output set_max_level lrange= 93, last_max_update=4168s�
sound output set_max_level overrun count=0 , margin= 50, pct= 0, cmst=130, mst=134�
sound output EOS�

Matching this sound packet using its timestamp (25394604988662), I see that this is just one of many sound packets sent by the server around that time:

new_sound_buffer(source_subprocess_wrapper(25768), 880, {'duration': 9977325, 'timestamp': 25394595011337, 'time': 1449792455989}) suspended=False
info_update: {'pipeline': 'pulsesrc device=auto_null.monitor ! volume name=volume volume=1.0 ! wavenc ! appsink name=sink emit-signals=true max-buffers=10 drop=true sync=false async=false qos=false', \
    'codec_description': '', 'bytes': 2147428888, 'volume': 100, 'state': 'active', 'codec': 'wav', 'buffers': 2440262}
sound_source_info: {'pipeline': 'pulsesrc device=auto_null.monitor ! volume name=volume volume=1.0 ! wavenc ! appsink name=sink emit-signals=true max-buffers=10 drop=true sync=false async=false qos=false', \
    'codec_description': '', 'pid': 25768, 'bytes': 2147428888, 'volume': 100, 'state': 'active', 'codec': 'wav', 'time': 1449792455, 'buffers': 2440262}
sound source emit_buffer data=<type 'str'>, len=880, metadata={'duration': 9977324L, 'timestamp': 25394604988662L}�
new_sound_buffer(source_subprocess_wrapper(25768), 880, {'duration': 9977324, 'timestamp': 25394604988662, 'time': 1449792455998}) suspended=False
sound source emit_buffer data=<type 'str'>, len=880, metadata={'duration': 9977324L, 'timestamp': 25394614965986L}�

(with many more following these until we stop sending)

So it looks like we will have to catch this unexpected EOS (and make sure that it is unexpected..) and somehow restart the sound in this case.

[totaam]

2016-01-12 19:23:35: afarr commented

---

For what it's worth, testing again with 0.17.0 r11640 osx client against 0.17.0 r11649 fedora 23 server running vorbis... sound remained intact and happy after 13 hour overnight run.

Will test a couple more times, but it may be that vorbis is better about overruns, and as a result better about sound resets/crashes(?).

[totaam]

2016-01-13 05:41:01: antoine commented

---

That would be good, I would much prefer switching to a better codec (done already in newer releases) than write lots of ugly and difficult-to-test code, potentially causing more harm than good.

[totaam]

2016-03-16 07:08:49: antoine changed status from assigned to closed

[totaam]

2016-03-16 07:08:49: antoine set resolution to fixed

[totaam]

2016-03-16 07:08:49: antoine commented

---

Closing: this is no longer an issue with newer versions, we can re-open if needed.