Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

speaker forwarding after re-attach sometimes unsuccessful #663

Closed
totaam opened this issue Aug 24, 2014 · 24 comments
Closed

speaker forwarding after re-attach sometimes unsuccessful #663

totaam opened this issue Aug 24, 2014 · 24 comments
Labels
audio

Comments

@totaam
Copy link
Collaborator

totaam commented Aug 24, 2014

Issue migrated from trac ticket # 663

component: sound | priority: minor | resolution: worksforme

2014-08-24 21:13:53: onlyjob created the issue

0.14.3: Often (roughly at least with 50% probability) speaker forwarding do not work after re-attach (after disconnect) until I switch Speaker "off" and then "on" again from the menu. The following is printed to client's console on re-attach:

Cannot connect to server socket err = No such file or directory
Cannot connect to server request channel
jack server is not running or cannot be started

The following is printed during speaker off/on manipulation:

Cannot connect to server socket err = No such file or directory
Cannot connect to server request channel
jack server is not running or cannot be started
2014-08-25 06:05:45,812 unknown sound pipeline tag message <gst.Message taglist, container-format=(string)Ogg; from oggdemux1 at 0x7f5c7c002140>: <GstStructure (taglist) at 4a05f50>
2014-08-25 06:05:46,233 using audio codec: FLAC

I do not have "pulseaudio" or "jackd" on client and this issue is not sensitive to particular audio codec.

When attach successfully forwarding speaker without off/on manipulation the following is logged:

Cannot connect to server socket err = No such file or directory
Cannot connect to server request channel
jack server is not running or cannot be started
2014-08-25 06:08:19,152 unknown sound pipeline tag message <gst.Message taglist, container-format=(string)Ogg; from oggdemux0 at 0x7fa818001990>: <GstStructure (taglist) at 33fa410>
2014-08-25 06:08:19,560 using audio codec: FLAC
@totaam
Copy link
Collaborator Author

totaam commented Aug 25, 2014

2014-08-25 05:43:10: totaam changed owner from antoine to onlyjob

@totaam
Copy link
Collaborator Author

totaam commented Aug 25, 2014

2014-08-25 05:43:10: totaam commented

I have to admit that the non-pulseaudio on Linux setups haven't been tested much.
On Linux, we try the autoaudiosink element first.
You can override this behaviour with:

XPRA_SOUND_SINK=value xpra attach ...

The options that may be available apart from "auto" are: pulsesink, alsasink, osssink, oss4sink, jackaudiosink - this is documented here: Sound
Maybe one of those will work better on your non-pulseaudio setup.
I would have expected autoaudiosink to make the right decision for us, but we already have platform specific quircks for OSX and win32, maybe another one is needed.

Failing that, please try:

  • posting the client debug output with -d sound
  • try the ./xpra/sound/sink.py tool to play an mp3 file

@totaam
Copy link
Collaborator Author

totaam commented Aug 25, 2014

2014-08-25 12:41:46: onlyjob commented

Apparently my sink is alsasink since it is the only one working on my system.
However forcing alsasink do not change probability of successful audio forwarding.
I think autoaudiosink selects proper backend and then sometimes something wrong is happening...

Also when audio successfully forwarded it skips quite badly in the beginning slowly improving
until approximately around 2:30...3:00 since session attach skipping completely disappears.
Playing with XPRA_SOUND_QUEUE_TIME yield nothing as it have no influence on skipping pattern.
This is on dual gigabit low-latency local network...

-d sound output from silent session (capabilities stripped):

2014-08-25 18:45:40,108 initalized CODECS:
2014-08-25 18:45:40,108 * wavpack : ('wavpackenc', None, 'wavpackdec', 'wavpackparse')
2014-08-25 18:45:40,109 * flac : ('flacenc', 'oggmux', 'flacdec', 'oggdemux')
2014-08-25 18:45:40,109 * wav : ('wavenc', None, None, 'wavparse')
2014-08-25 18:45:40,109 * speex : ('speexenc', 'oggmux', 'speexdec', 'oggdemux')
2014-08-25 18:45:40,109 speaker_allowed=True, speaker_codecs=['wavpack', 'flac', 'wav', 'speex']
2014-08-25 18:45:40,109 microphone_allowed=True, microphone_codecs=['wavpack', 'flac', 'wav', 'speex']
2014-08-25 18:45:40,402 PyOpenGL warning: missing accelerate module
2014-08-25 18:45:40,402 PyOpenGL warning: missing array format handlers: numeric, vbo, vbooffset
2014-08-25 18:45:40,402 OpenGL Version: 4.4.12967 Compatibility Profile Context 14.10.1006
2014-08-25 18:45:40,422 keyboard layouts: us,ru
2014-08-25 18:45:40,448 detected keyboard: rules=evdev, model=pc101, layout=us
2014-08-25 18:45:40,449 desktop size is 4400x2560 with 1 screen(s):
2014-08-25 18:45:40,449   ':0.0' (1163x677 mm) workarea: 4400x2519 at 0x41
2014-08-25 18:45:40,449     DFP5 1280x1024 at 0x1536 (360x270 mm)
2014-08-25 18:45:40,449     DFP10 1440x2560 at 1280x0 (597x336 mm)
2014-08-25 18:45:40,449     DFP1 1680x1050 at 2720x990 (474x296 mm)
2014-08-25 18:45:40,458 pactl_output('list',) returned 1
2014-08-25 18:45:40,465 pactl_output('list',) returned 1
2014-08-25 18:45:40,472 pactl_output('list',) returned 1
2014-08-25 18:45:40,478 pactl_output('list',) returned 1
2014-08-25 18:45:40,883 server: Linux debian 7.6 , Xpra version 0.14.3 (7423)
2014-08-25 18:45:40,886 pulseaudio id=, server=, sound decoders=['mp3', 'wavpack', 'wav', 'flac', 'speex'], sound encoders=['mp3', 'wavpack', 'wav', 'flac', 'speex'], receive=True, send=True
2014-08-25 18:45:40,886 start_receiving_sound() sound sink=None
2014-08-25 18:45:40,886 start_sound_sink(wavpack)
2014-08-25 18:45:40,887 starting wavpack sound sink
2014-08-25 18:45:40,888 is_pa_installed() pactl_bin=/usr/bin/pactl
2014-08-25 18:45:40,888 pipeline elements=['appsrc name=src max-bytes=32768 emit-signals=0 block=0 is-live=0 stream-type=stream format=4', 'wavpackparse', 'wavpackdec', 'audioconvert', 'audioresample', 'queue name=queue max-size-buffers=0 max-size-bytes=0 max-size-time=450000000 leaky=2', 'autoaudiosink']
2014-08-25 18:45:40,888 pipeline=appsrc name=src max-bytes=32768 emit-signals=0 block=0 is-live=0 stream-type=stream format=4 ! wavpackparse ! wavpackdec ! audioconvert ! audioresample ! queue name=queue max-size-buffers=0 max-size-bytes=0 max-size-time=450000000 leaky=2 ! autoaudiosink
2014-08-25 18:45:40,902 SoundPipeline.start()
Cannot connect to server socket err = No such file or directory
Cannot connect to server request channel
jack server is not running or cannot be started
2014-08-25 18:45:40,915 sound sink queue underrun: level=0
2014-08-25 18:45:40,916 SoundPipeline.start() done
2014-08-25 18:45:40,916 wavpack sound sink started
2014-08-25 18:45:40,916 Attached to ssh:debstor:22 (press Control-C to detach)

2014-08-25 18:45:40,933 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from autoaudiosink0 at 0x2022bd0>
2014-08-25 18:45:40,933 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from queue at 0x2022c50>
2014-08-25 18:45:40,934 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioresample0 at 0x2022b50>
2014-08-25 18:45:40,934 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioconvert0 at 0x2022ad0>
2014-08-25 18:45:40,934 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackdec0 at 0x2022a50>
2014-08-25 18:45:40,934 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackparse0 at 0x2022950>
2014-08-25 18:45:40,967 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from src at 0x2022cd0>
2014-08-25 18:45:40,969 new-state=READY
2014-08-25 18:45:40,969 sound_sink_state_changed(<SoundSink object at 0x7f5b9cead690 (xpra+sound+sink+SoundSink at 0x207e020)>, ready) on_sink_ready=<function sink_ready at 0x7f5b9ceab230>
2014-08-25 18:45:40,970 sink_ready(()) codec=wavpack
2014-08-25 18:45:40,970 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_CREATE, owner=(GstElement)"\(GstQueue\)\ queue", object=(GstTask)"\(GstTask\)\ queue:src"; from src at 0x2022f50>
2014-08-25 18:45:40,970 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from queue at 0x206e810>
2014-08-25 18:45:40,971 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioresample0 at 0x206e890>
2014-08-25 18:45:40,971 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioconvert0 at 0x206e910>
2014-08-25 18:45:40,971 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackdec0 at 0x206e990>
2014-08-25 18:45:40,972 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackparse0 at 0x206ea10>
2014-08-25 18:45:40,972 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_ENTER, owner=(GstElement)"\(GstQueue\)\ queue", object=(GstTask)"\(GstTask\)\ queue:src"; from src at 0x206eb10>
2014-08-25 18:45:40,972 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_CREATE, owner=(GstElement)"\(GstAppSrc\)\ src", object=(GstTask)"\(GstTask\)\ src:src"; from src at 0x206ea90>
2014-08-25 18:45:40,972 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from src at 0x2022dd0>
2014-08-25 18:45:40,972 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_ENTER, owner=(GstElement)"\(GstAppSrc\)\ src", object=(GstTask)"\(GstTask\)\ src:src"; from src at 0x7f5b640019a0>

At the moment I don't have package gstreamer0.10-plugins-ugly to play MP3 installed so ./xpra/sound/sink.py didn't work for me:
without explicitly given codec python sink.py audio.mp3 prints

  File "/usr/lib/python2.7/dist-packages/xpra/sound/gstreamer_util.py", line 238, in get_decoder_parser
    assert name in CODECS, "invalid codec: %s (should be one of: %s)" % (name, CODECS.keys())
AssertionError: invalid codec: mp3 (should be one of: ['speex', 'wav', 'wavpack', 'flac', 'opus'])

When invoked as ./xpra/sound/sink.py audio.mp3 flac it prints

loaded 10791788 bytes from audio.mp3
2014-08-25 21:26:40,761 add_data(..) queue_state=starting
2014-08-25 21:26:40,761 sound sink: pushed 10791788 bytes, new buffer level: 0ms
Cannot connect to server socket err = No such file or directory
Cannot connect to server request channel
jack server is not running or cannot be started
2014-08-25 21:26:41,778 underrun (end of stream)

But speaker forwarding works in the xpra session fairly well
(except for two issues mentioned i.e. skipping in first 3 minutes
and not always successfully starting forwarding).
Interestingly I can't remember when audio could not be started
by off/on sequence when it did not work from very beginning.
I wonder why is second attempt to forward audio is always successful?

@totaam
Copy link
Collaborator Author

totaam commented Aug 25, 2014

2014-08-25 12:55:13: onlyjob commented

GST_DEBUG=2 printed some interesting warnings:

0:00:04.353010043 23328      0x2737230 WARN                oggdemux gstoggdemux.c:2095:gst_ogg_demux_sink_event:<oggdemux0> unexpected segment format: buffers
0:00:04.353300443 23328      0x2737230 WARN                 flacdec gstflacdec.c:1297:gst_flac_dec_sink_event:<flacdec0> couldn't convert time => samples
2014-08-25 21:52:42,612 unknown sound pipeline tag message <gst.Message taglist, container-format=(string)Ogg; from oggdemux0 at 0x7f4b04001b20>: <GstStructure (taglist) at 2308660>
2014-08-25 21:52:43,028 using audio codec: FLAC
0:00:04.771873504 23328      0x2737230 WARN                    alsa gstalsa.c:124:gst_alsa_detect_formats:<alsasink0> skipping non-int format
0:00:04.776467802 23328 0x7f4b0402a050 WARN                     bin gstbin.c:2395:gst_bin_do_latency_func:<pipeline0> did not really configure latency of 0:00:00.000000000

@totaam
Copy link
Collaborator Author

totaam commented Aug 25, 2014

2014-08-25 15:02:45: onlyjob commented

For first 3 minutes xpra-client logs sound sink queue underrun: level=0 with -d sound.
Then underruns slowly die out and audio plays smoothly without skipping.
Is there anything to tweak in order to avoid skipping in the beginning or accelerate auto tune?

@totaam
Copy link
Collaborator Author

totaam commented Aug 25, 2014

2014-08-25 15:17:34: totaam commented

Also when audio successfully forwarded it skips quite badly in the beginning slowly improving until approximately around 2:30...3:00 since session attach skipping completely disappears.
(..)
For first 3 minutes xpra-client logs sound sink queue underrun: level=0
[[BR]]
That means that your sink (alsasink) is draining the data from the queue too quickly. It's odd that it doesn't happen with osx, win32 or pulseaudio.
Does r7431 make any difference? (don't see why, but worth a shot)
[[BR]]
What about this:

--- src/xpra/sound/sink.py	(revision 7431)
+++ src/xpra/sound/sink.py	(working copy)
@@ -80,6 +80,7 @@
         pipeline_els.append("audioresample")
         queue_el =  ["queue",
                     "name=queue",
+                    "min-threshold-time=%s" % int(QUEUE_TIME/4),
                     "max-size-buffers=0",
                     "max-size-bytes=0",
                     "max-size-time=%s" % QUEUE_TIME,

It should force more data to accumulate before allowing the sink to read from the buffer. Does it make any difference at all? (maybe even try QUEUE_TIME/2? and with wavpack)
[[BR]]

.. and not always successfully starting forwarding
[[BR]]
I see nothing suspicious in the log samples.
Maybe fixing the underruns will fix this too.
[[BR]]

When invoked as ./xpra/sound/sink.py audio.mp3 flac it prints
[[BR]]
Best not to do that. If you want to test with the flac codec, just feed it a file in flac format.

@totaam
Copy link
Collaborator Author

totaam commented Aug 29, 2014

2014-08-29 07:26:13: totaam commented

@onlyjob: does that fix things for you? I don't have a Debian + non-pulseaudio setup to test it.

If so, please re-assign to afarr for testing, so we can ensure that does not make osx or win32 worse: as those tend to get overruns and not underruns...

@totaam
Copy link
Collaborator Author

totaam commented Aug 30, 2014

2014-08-30 05:19:08: onlyjob commented

It looks like r7431 did not make any difference.

"min-threshold-time=%s" % int(QUEUE_TIME/4) also did not help and QUEUE_TIME/2 possibly made it worse: once or twice speaker forwarding suddenly stopped (on client) shortly after it started.

-d sound show that underruns occur (even on silence) every time when audio is started (using menu or on attach) for up to 2.5...5 minutes. Then audio goes smoothly with no skipping whatsoever.

@totaam
Copy link
Collaborator Author

totaam commented Aug 30, 2014

2014-08-30 05:24:00: onlyjob commented

Replying to [comment:6 totaam]:

@onlyjob: does that fix things for you? I don't have a Debian + non-pulseaudio setup to test it.

apt-get remove pulseaudio converts setup to non-PA; reinstalling pulseaudio restores previous settings. Reboot may be needed to stop PA (and other) daemon(s) and restart apps with new settings...

@totaam
Copy link
Collaborator Author

totaam commented Aug 30, 2014

2014-08-30 10:16:44: totaam commented

@onlyjob: I really wished it was that simple:

  • [https://wiki.debian.org/SoundFAQ] is currently 403 Forbidden
  • [https://wiki.debian.org/SoundCard] - same
  • sound doesn't work with pulseaudio + Debian Wheezy, many google hits, but no help

I've tried to improve underrun handling in r7485: the changes above were making the queue min threshold permanent, which was not helpful (just making things worse as you noted), so instead we raise the threshold only temporarily when hitting an underrun, and clear it again after an arbitrary 2 seconds.

I'm testing blind, well 'deaf' to be precise, so the change above could actually make things worse - I have no idea.

And I'm not sure which module ends up being used with autoaudiosink, maybe installing this sink helped?

apt-get install gstreamer0.10-alsa

I was getting clock drift, causing the client to repeatedly hit the overrun and restarting the pipeline, and then it stopped doing that.. I removed the gstreamer alsa module, and it still worked OK then!
It was doing the same thing with underrun, sometimes, then stopped.

@totaam
Copy link
Collaborator Author

totaam commented Aug 30, 2014

2014-08-30 16:40:35: onlyjob commented

Thank you for your efforts with improving audio support.

I'm definitely on XPRA_SOUND_SINK=alsasink and I have gstreamer0.10-alsa installed. "autoaudiosink" selects Alsa on my system, as it appears with -d sound log: owner=(GstElement)"\(GstAlsaSink\)\ autoaudiosink0-actual-sink-alsa"

Removing gstreamer0.10-alsa selects OpenAL: "\(GstOpenALSink\)\ autoaudiosink0-actual-sink-openal".

r7485 applied to 0.14.4 hangs server real hard -- it stops responding after disconnect and I have to kill it using kill -9 and restart with --use-display as even xpra upgrade do not help. Unfortunately there were no noticeable improvement with underruns. I have clocks on client and server in sync as much as possible with regular NTP time corrections. Lately I was trying all this with Wavpack. Surprisingly underruns are persistent in the beginning of session and completely disappear some minutes later...

@totaam
Copy link
Collaborator Author

totaam commented Aug 30, 2014

2014-08-30 17:03:39: totaam commented

OK, I've reverted r7485 in r7488. Strange how I never hit that problem.

I'm out of ideas. Please attach the full -d sound output log for the first 3 or 4 minutes (just enough to get the "bad" initial behaviour and at least one minute of "good" behaviour).

I have clocks on client and server in sync as much as possible with regular NTP time corrections
[[BR]]
I meant the sound signal clock, which can sometimes drift a bit between the sound data and the rate at which the sound card is consuming it. r7431 added the timestamp to the buffers we hand over to gstreamer, which could have helped, but did not.

@totaam
Copy link
Collaborator Author

totaam commented Aug 31, 2014

2014-08-31 01:54:35: onlyjob uploaded file xpra-sound.log.xz (17.3 KiB)

@totaam
Copy link
Collaborator Author

totaam commented Aug 31, 2014

2014-08-31 01:58:57: onlyjob commented

Full -d sound log attached. On this instance it took around 5 min. to stabilise audio. Sometimes it is a bit faster and roughly one minute till complete disappearance of underruns audio crackling almost gone and can be barely heard.

@totaam
Copy link
Collaborator Author

totaam commented Sep 4, 2014

2014-09-04 11:44:13: onlyjob commented

Here is a fragment of server log (-d sound) when client switches speaker forwarding to "On" from menu but sound forwarding did not work:

2014-09-04 20:15:23,662 sound_control(start, ('wav',))
2014-09-04 20:15:23,662 start_sending_sound(wav)
2014-09-04 20:15:23,662 using sound codec wav
2014-09-04 20:15:23,678 pactl_output('stat',) returned 0
2014-09-04 20:15:23,678 get_pactl_stat_line(Server String:)=/tmp/pulse-8XiBnTK3trYQ/native
2014-09-04 20:15:23,678 start sound, remote pulseaudio server=, local pulseaudio server=/tmp/pulse-8XiBnTK3trYQ/native
2014-09-04 20:15:23,679 start sound, client id=, server id=
2014-09-04 20:15:23,692 pactl_output('list',) returned 0
2014-09-04 20:15:23,693 found pulseaudio monitor devices: {'auto_null.monitor': 'Monitor of Dummy Output'}
2014-09-04 20:15:23,703 pactl_output('set-source-mute', 'auto_null.monitor', '0') returned 0
2014-09-04 20:15:23,703 set_source_mute: output=
2014-09-04 20:15:23,703 pipeline elements=['pulsesrc device=auto_null.monitor', 'audioconvert', 'volume name=volume volume=1.0', 'wavenc', None, 'appsink name=sink']
2014-09-04 20:15:23,703 pipeline=pulsesrc device=auto_null.monitor ! audioconvert ! volume name=volume volume=1.0 ! wavenc ! appsink name=sink
2014-09-04 20:15:23,707 starting sound capture using pulseaudio device: Monitor of Dummy Output
2014-09-04 20:15:23,707 start_sending_sound() sound source=<SoundSource object at 0x7f5f87093320 (xpra+sound+src+SoundSource at 0x31cdb40)>
2014-09-04 20:15:23,707 SoundPipeline.start()
2014-09-04 20:15:23,714 SoundPipeline.start() done
2014-09-04 20:15:23,714 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from sink at 0x3438190>
2014-09-04 20:15:23,715 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavenc7 at 0x2ed05c0>
2014-09-04 20:15:23,715 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from volume at 0x7f5f40002110>
2014-09-04 20:15:23,715 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioconvert7 at 0x3453250>
2014-09-04 20:15:23,715 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from pulsesrc7 at 0x7f5f40002690>
2014-09-04 20:15:23,715 new-state=READY
2014-09-04 20:15:23,716 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavenc7 at 0x7f5f40002590>
2014-09-04 20:15:23,716 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from volume at 0x3438390>
2014-09-04 20:15:23,716 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioconvert7 at 0x7f5f40002090>
2014-09-04 20:15:23,716 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_ENTER, owner=(GstElement)"\(GstPulseSrc\)\ pulsesrc7", object=(gpointer)NULL; from audiosrcringbuffer7 at 0x3453650>
2014-09-04 20:15:23,717 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_CREATE, owner=(GstElement)"\(GstPulseSrc\)\ pulsesrc7", object=(GstTask)"\(GstTask\)\ pulsesrc7:src"; from src at 0x3453350>
2014-09-04 20:15:23,717 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from pulsesrc7 at 0x7f5f540078c0>
2014-09-04 20:15:23,717 new-state=PAUSED
2014-09-04 20:15:23,717 <gst.Message GstMessageNewClock, clock=(GstClock)"\(GstAudioClock\)\ GstAudioSrcClock"; from pipeline7 at 0x3453150>
2014-09-04 20:15:23,717 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_ENTER, owner=(GstElement)"\(GstPulseSrc\)\ pulsesrc7", object=(GstTask)"\(GstTask\)\ pulsesrc7:src"; from src at 0x7f5f40002190>
2014-09-04 20:15:23,717 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavenc7 at 0x34535d0>
2014-09-04 20:15:23,718 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from volume at 0x3453450>
2014-09-04 20:15:23,718 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioconvert7 at 0x7f5f54007d40>
2014-09-04 20:15:23,718 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from pulsesrc7 at 0x7f5f54007dc0>

Sometimes it works but sometimes it fails as above...

@totaam
Copy link
Collaborator Author

totaam commented Sep 4, 2014

2014-09-04 17:07:23: totaam commented

In the log above, weren't there more log messages after the ones you posted?
Like maybe a new-state=PLAYING ?

It looks fine, do you have the same log of when it does work? Can you post it here? Are there any differences?

Does it also happen with the mp3 codec? That's the one that got tested the most. wavpack works flawlessly here too.

The gstreamer states are documented here: Element States

Please also try posting this same log with:

export GST_DEBUG=5

Finally, r7514 adds the ability to tune the sink (alsasink in your case) and you may be able to find something there that fixes it.
For the full list of attributes, see:

gst-inspect alsasink

I've set sync to false for alsasink, because it was the most obvious change, but beyond that.. your guess is as good as mine.

The only other alternative would be to blacklist alsa sound output (since no-one has reported problems with pulsesink), but I don't see how that is possible since we use autoaudiosink...

The only alternative explanation that I can find is something to do with EOS or pads, links:

@totaam
Copy link
Collaborator Author

totaam commented Sep 23, 2014

2014-09-23 07:08:14: totaam commented

Looks like I may have to close this as 'needinfo', as per comment:14.

See also: #663, #400#comment:8.

@totaam
Copy link
Collaborator Author

totaam commented Oct 4, 2014

2014-10-04 09:57:54: onlyjob commented

I attach to session where music is playing with --no-clipboard -d sound.
Sometime I can hear the audio from the other end as soon as session is attached, but sometimes it is silent. Here is log taken from client on unsuccessful audio forwarding:

2014-10-04 18:40:01,647 Attached to ssh:debstor:22 (press Control-C to detach)

2014-10-04 18:40:01,654 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from alsasink0 at 0x206aea0>
2014-10-04 18:40:01,654 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from queue at 0x206ae20>
2014-10-04 18:40:01,655 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioresample0 at 0x206ada0>
2014-10-04 18:40:01,655 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioconvert0 at 0x206af20>
2014-10-04 18:40:01,656 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackdec0 at 0x2072010>
2014-10-04 18:40:01,656 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackparse0 at 0x2072090>
2014-10-04 18:40:01,656 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from src at 0x2072110>
2014-10-04 18:40:01,656 new-state=READY
2014-10-04 18:40:01,656 sound_sink_state_changed(<SoundSink object at 0x7f1e65ee26e0 (xpra+sound+sink+SoundSink at 0x1e6b8a0)>, ready) on_sink_ready=<function sink_ready at 0x7f1e6700c938>
2014-10-04 18:40:01,657 sink_ready(()) codec=wavpack
2014-10-04 18:40:01,657 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_CREATE, owner=(GstElement)"\(GstQueue\)\ queue", object=(GstTask)"\(GstTask\)\ queue:src"; from src at 0x2072310>
2014-10-04 18:40:01,657 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from queue at 0x2072390>
2014-10-04 18:40:01,657 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioresample0 at 0x2072410>
2014-10-04 18:40:01,657 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioconvert0 at 0x2072490>
2014-10-04 18:40:01,658 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackdec0 at 0x2072510>
2014-10-04 18:40:01,658 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackparse0 at 0x2072590>
2014-10-04 18:40:01,658 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_CREATE, owner=(GstElement)"\(GstAppSrc\)\ src", object=(GstTask)"\(GstTask\)\ src:src"; from src at 0x2072610>
2014-10-04 18:40:01,658 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_ENTER, owner=(GstElement)"\(GstQueue\)\ queue", object=(GstTask)"\(GstTask\)\ queue:src"; from src at 0x7f1e30001830>
2014-10-04 18:40:01,659 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from src at 0x2072690>
2014-10-04 18:40:01,659 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_ENTER, owner=(GstElement)"\(GstAppSrc\)\ src", object=(GstTask)"\(GstTask\)\ src:src"; from src at 0x7f1e30001e30>

Now I click Speaker-->Off:

2014-10-04 18:43:24,512 stop_receiving_sound() sound sink=<SoundSink object at 0x7f1e65ee26e0 (xpra+sound+sink+SoundSink at 0x1e6b8a0)>
2014-10-04 18:43:24,512 UIXpraClient.stop_receiving_sound_thread()
2014-10-04 18:43:24,513 SoundPipeline.cleanup()
2014-10-04 18:43:24,513 SoundPipeline.stop()
2014-10-04 18:43:24,513 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PLAYING, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_READY; from alsasink0 at 0x2072290>
2014-10-04 18:43:24,513 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from alsasink0 at 0x20ed230>
2014-10-04 18:43:24,513 SoundPipeline.stop() done
2014-10-04 18:43:24,514 speaker is now disabled - dropping packet
2014-10-04 18:43:24,514 SoundPipeline.cleanup() done
2014-10-04 18:43:24,515 UIXpraClient.stop_receiving_sound_thread() done

And Speaker-->On:

2014-10-04 18:43:33,362 start_receiving_sound() sound sink=None
2014-10-04 18:43:33,363 start_sound_sink(wavpack)
2014-10-04 18:43:33,363 starting wavpack sound sink
2014-10-04 18:43:33,364 pipeline elements=['appsrc name=src max-bytes=32768 emit-signals=0 block=0 is-live=0 stream-type=stream format=4', 'wavpackparse', 'wavpackdec', 'audioconvert', 'audioresample', 'queue name=queue max-size-buffers=0 max-size-bytes=0 max-size-time=450000000 leaky=2', 'alsasink']
2014-10-04 18:43:33,364 pipeline=appsrc name=src max-bytes=32768 emit-signals=0 block=0 is-live=0 stream-type=stream format=4 ! wavpackparse ! wavpackdec ! audioconvert ! audioresample ! queue name=queue max-size-buffers=0 max-size-bytes=0 max-size-time=450000000 leaky=2 ! alsasink
2014-10-04 18:43:33,368 SoundPipeline.start()
2014-10-04 18:43:33,371 sound sink queue underrun: level=0
2014-10-04 18:43:33,371 SoundPipeline.start() done
2014-10-04 18:43:33,371 wavpack sound sink started
2014-10-04 18:43:33,371 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from alsasink1 at 0x20ed230>
2014-10-04 18:43:33,372 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from queue at 0x2072290>
2014-10-04 18:43:33,372 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioresample1 at 0x7f1e30001f30>
2014-10-04 18:43:33,372 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioconvert1 at 0x7f1e28001840>
2014-10-04 18:43:33,372 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackdec1 at 0x7f1e280018c0>
2014-10-04 18:43:33,373 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackparse1 at 0x7f1e28001940>
2014-10-04 18:43:33,373 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from src at 0x7f1e280019c0>
2014-10-04 18:43:33,373 new-state=READY
2014-10-04 18:43:33,374 sound_sink_state_changed(<SoundSink object at 0x7f1e65ee2780 (xpra+sound+sink+SoundSink at 0x22606a0)>, ready) on_sink_ready=<function sink_ready at 0x7f1e4f45e500>
2014-10-04 18:43:33,374 sink_ready(()) codec=wavpack
2014-10-04 18:43:33,374 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_CREATE, owner=(GstElement)"\(GstQueue\)\ queue", object=(GstTask)"\(GstTask\)\ queue:src"; from src at 0x7f1e28001bc0>
2014-10-04 18:43:33,375 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from queue at 0x7f1e28001c40>
2014-10-04 18:43:33,375 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioresample1 at 0x7f1e28001ac0>
2014-10-04 18:43:33,376 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioconvert1 at 0x7f1e2c003d40>
2014-10-04 18:43:33,378 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackdec1 at 0x7f1e2c003cc0>
2014-10-04 18:43:33,378 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_ENTER, owner=(GstElement)"\(GstQueue\)\ queue", object=(GstTask)"\(GstTask\)\ queue:src"; from src at 0x7f1e30001930>
2014-10-04 18:43:33,378 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackparse1 at 0x7f1e2c003c40>
2014-10-04 18:43:33,378 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_CREATE, owner=(GstElement)"\(GstAppSrc\)\ src", object=(GstTask)"\(GstTask\)\ src:src"; from src at 0x7f1e2c003bc0>
2014-10-04 18:43:33,379 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from src at 0x7f1e2c003b40>
2014-10-04 18:43:33,379 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_ENTER, owner=(GstElement)"\(GstAppSrc\)\ src", object=(GstTask)"\(GstTask\)\ src:src"; from src at 0x20ed730>
2014-10-04 18:43:34,174 add_data(..) queue_state=underrun
2014-10-04 18:43:34,174 sound sink: pushed 112 bytes, new buffer level: 0ms
2014-10-04 18:43:34,175 add_data(..) queue_state=underrun
2014-10-04 18:43:34,175 sound sink: pushed 112 bytes, new buffer level: 0ms
2014-10-04 18:43:34,175 using audio codec: Wavpack
2014-10-04 18:43:34,178 sound sink queue running: level=500
2014-10-04 18:43:34,179 sound sink queue pushing: level=500
2014-10-04 18:43:34,179 sound sink queue overrun ignored: level=500, elapsed time=0.8
2014-10-04 18:43:34,179 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_ENTER, owner=(GstElement)"\(GstAlsaSink\)\ alsasink1", object=(gpointer)NULL; from audiosinkringbuffer1 at 0x7f1e2c003d40>
2014-10-04 18:43:34,179 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from alsasink1 at 0x7f1e300019b0>
2014-10-04 18:43:34,179 new-state=PAUSED
2014-10-04 18:43:34,180 sound_sink_state_changed(<SoundSink object at 0x7f1e65ee2780 (xpra+sound+sink+SoundSink at 0x22606a0)>, paused) on_sink_ready=None
2014-10-04 18:43:34,180 <gst.Message (none) from pipeline1 at 0x7f1e30001ab0>
2014-10-04 18:43:34,180 <gst.Message GstMessageNewClock, clock=(GstClock)"\(GstAudioClock\)\ GstAudioSinkClock"; from pipeline1 at 0x7f1e2c003dc0>
2014-10-04 18:43:34,180 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from alsasink1 at 0x7f1e2c003e40>
2014-10-04 18:43:34,180 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from queue at 0x7f1e2c003ec0>
2014-10-04 18:43:34,180 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioresample1 at 0x7f1e2c003f40>
2014-10-04 18:43:34,180 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioconvert1 at 0x7f1e10001810>
2014-10-04 18:43:34,180 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackdec1 at 0x7f1e10001890>
2014-10-04 18:43:34,180 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackparse1 at 0x7f1e10001910>
2014-10-04 18:43:34,180 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from src at 0x7f1e10001990>
2014-10-04 18:43:34,180 new-state=PLAYING
2014-10-04 18:43:34,180 sound_sink_state_changed(<SoundSink object at 0x7f1e65ee2780 (xpra+sound+sink+SoundSink at 0x22606a0)>, active) on_sink_ready=None
2014-10-04 18:43:34,370 sound sink queue underrun: level=0
2014-10-04 18:43:34,672 add_data(..) queue_state=underrun
2014-10-04 18:43:34,673 sound sink: pushed 60 bytes, new buffer level: 0ms
2014-10-04 18:43:34,673 sound sink queue running: level=500
2014-10-04 18:43:34,673 sound sink queue pushing: level=500
2014-10-04 18:43:34,861 sound sink queue underrun: level=0
2014-10-04 18:43:35,171 add_data(..) queue_state=underrun
2014-10-04 18:43:35,172 sound sink: pushed 60 bytes, new buffer level: 0ms
2014-10-04 18:43:35,172 sound sink queue running: level=500
2014-10-04 18:43:35,172 sound sink queue pushing: level=500
2014-10-04 18:43:35,373 sound sink queue underrun: level=0
2014-10-04 18:43:35,670 add_data(..) queue_state=underrun

This happens with any codec (XPRA_SOUND_SINK=alsasink).

For comparison here is the log from session successfully playing audio:

2014-10-04 18:47:39,116 Attached to ssh:debstor:22 (press Control-C to detach)                                                              

2014-10-04 18:47:39,123 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from alsasink0 at 0x1b65ea0>                                                              
2014-10-04 18:47:39,124 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from queue at 0x1b65e20>                                                                  
2014-10-04 18:47:39,124 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioresample0 at 0x1b65da0>                                                         
2014-10-04 18:47:39,124 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioconvert0 at 0x1b65f20>                                                          
2014-10-04 18:47:39,124 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackdec0 at 0x1b6d010>                                                            
2014-10-04 18:47:39,125 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackparse0 at 0x1b6d090>                                                          
2014-10-04 18:47:39,125 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING; from src at 0x1b6d110>                                                                    
2014-10-04 18:47:39,125 new-state=READY                                                                                                     
2014-10-04 18:47:39,125 sound_sink_state_changed(<SoundSink object at 0x7f58f35325f0 (xpra+sound+sink+SoundSink at 0x19668a0)>, ready) on_sink_ready=<function sink_ready at 0x7f58f465c938>                                                                                            
2014-10-04 18:47:39,125 sink_ready(()) codec=wavpack                                                                                        
2014-10-04 18:47:39,126 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_CREATE, owner=(GstElement)"\(GstQueue\)\ queue", object=(GstTask)"\(GstTask\)\ queue:src"; from src at 0x1b6d310>                                          
2014-10-04 18:47:39,126 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from queue at 0x1b6d390>                                                                
2014-10-04 18:47:39,126 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioresample0 at 0x1b6d410>                                                       
2014-10-04 18:47:39,126 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioconvert0 at 0x1b6d490>                                                        
2014-10-04 18:47:39,127 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackdec0 at 0x1b6d510>                                                          
2014-10-04 18:47:39,127 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackparse0 at 0x1b6d590>                                                        
2014-10-04 18:47:39,127 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_CREATE, owner=(GstElement)"\(GstAppSrc\)\ src", object=(GstTask)"\(GstTask\)\ src:src"; from src at 0x1b6d610>                                             
2014-10-04 18:47:39,127 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_ENTER, owner=(GstElement)"\(GstQueue\)\ queue", object=(GstTask)"\(GstTask\)\ queue:src"; from src at 0x7f58bc001830>                                      
2014-10-04 18:47:39,128 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from src at 0x1b6d690>                                                                  
2014-10-04 18:47:39,128 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_ENTER, owner=(GstElement)"\(GstAppSrc\)\ src", object=(GstTask)"\(GstTask\)\ src:src"; from src at 0x7f58bc001e30>                                         
2014-10-04 18:47:39,932 add_data(..) queue_state=underrun                                                                                   
2014-10-04 18:47:39,933 sound sink: pushed 32378 bytes, new buffer level: 0ms                                                               
2014-10-04 18:47:39,933 add_data(..) queue_state=underrun                                                                                   
2014-10-04 18:47:39,933 using audio codec: Wavpack                                                                                          
2014-10-04 18:47:39,933 sound sink: pushed 32378 bytes, new buffer level: 0ms                                                               
2014-10-04 18:47:39,939 sound sink queue running: level=500                                                                                 
2014-10-04 18:47:39,939 sound sink queue pushing: level=500                                                                                 
2014-10-04 18:47:39,940 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING; from alsasink0 at 0x7f58bc0018b0>                                                       
2014-10-04 18:47:39,940 new-state=PAUSED                                                                                                    
2014-10-04 18:47:39,940 sound_sink_state_changed(<SoundSink object at 0x7f58f35325f0 (xpra+sound+sink+SoundSink at 0x19668a0)>, paused) on_sink_ready=None                                                                                                                              
2014-10-04 18:47:39,940 <gst.Message (none) from pipeline0 at 0x7f58bc0019b0>                                                               
2014-10-04 18:47:39,940 stream status: <gst.Message GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_ENTER, owner=(GstElement)"\(GstAlsaSink\)\ alsasink0", object=(gpointer)NULL; from audiosinkringbuffer0 at 0x1c1bb50>                                      
2014-10-04 18:47:39,940 <gst.Message GstMessageNewClock, clock=(GstClock)"\(GstAudioClock\)\ GstAudioSinkClock"; from pipeline0 at 0x7f58a00019a0>                                                                                                                                      
2014-10-04 18:47:39,940 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from alsasink0 at 0x7f58a0001a20>                                                     
2014-10-04 18:47:39,941 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from queue at 0x7f58a0001aa0>                                                         
2014-10-04 18:47:39,941 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioresample0 at 0x7f58a0001b20>                                                
2014-10-04 18:47:39,941 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from audioconvert0 at 0x7f58a0001ba0>                                                 
2014-10-04 18:47:39,941 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackdec0 at 0x7f58a0001c20>                                                   
2014-10-04 18:47:39,941 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from wavpackparse0 at 0x7f58a0001ca0>                                                 
2014-10-04 18:47:39,941 state changed: <gst.Message GstMessageState, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING; from src at 0x7f58a0001d20>                                                           
2014-10-04 18:47:39,941 new-state=PLAYING                                                                                                   
2014-10-04 18:47:39,941 sound_sink_state_changed(<SoundSink object at 0x7f58f35325f0 (xpra+sound+sink+SoundSink at 0x19668a0)>, active) on_sink_ready=None                                                                                                                              
2014-10-04 18:47:40,120 sound sink queue underrun: level=0                                                                                  
2014-10-04 18:47:40,425 add_data(..) queue_state=underrun                                                                                   
2014-10-04 18:47:40,425 sound sink: pushed 30668 bytes, new buffer level: 0ms                                                               
2014-10-04 18:47:40,427 sound sink queue running: level=500                                                                                 
2014-10-04 18:47:40,427 sound sink queue pushing: level=500                                                                                 
2014-10-04 18:47:40,610 sound sink queue underrun: level=0                                                                                  
2014-10-04 18:47:40,931 add_data(..) queue_state=underrun

I'm beginning to think that it could be a server-side leak of some sort. When trying to reproduce I noticed that the more I attach to session the more likely it becomes for sound forwarding to fail. Eventually after many attaches (when audio playing on server side) xpra stopped responding to client and I had to terminate it on server... I'll try to get a log with "GST_DEBUG=5"...

@totaam
Copy link
Collaborator Author

totaam commented Oct 4, 2014

2014-10-04 10:05:26: onlyjob uploaded file attach_no_sound.log.xz (30.9 KiB)

@totaam
Copy link
Collaborator Author

totaam commented Oct 4, 2014

2014-10-04 10:06:31: onlyjob uploaded file gst-inspect_alsasink.txt (7.3 KiB)

@totaam
Copy link
Collaborator Author

totaam commented Oct 4, 2014

2014-10-04 10:09:11: onlyjob commented

Newly attached file attach_no_sound.log.xz is a log taken with "GST_DEBUG=5" when audio was unseccessfully forwarded on attach with "--no-clipboard -d sound".

File gst-inspect_alsasink.txt is the output of gst-inspect alsasink.

@totaam
Copy link
Collaborator Author

totaam commented Mar 21, 2015

2015-03-21 17:39:31: antoine changed status from new to closed

@totaam
Copy link
Collaborator Author

totaam commented Mar 21, 2015

2015-03-21 17:39:31: antoine set resolution to worksforme

@totaam
Copy link
Collaborator Author

totaam commented Mar 21, 2015

2015-03-21 17:39:31: antoine commented

This should be totally reliable now that we handle this out of process - see #669. Please re-open if you can reproduce with 0.15

@totaam totaam closed this as completed Mar 21, 2015
@totaam totaam mentioned this issue Jan 22, 2021
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
audio
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@totaam