osx client with sound output never restarts

[totaam]

Issue migrated from trac ticket # 379

component: platforms | priority: major | resolution: fixed | keywords: osx

2013-07-13 02:04:13: afarr created the issue

---

Using osx 0.10 r 3830 client with vpx encoding, as soon as there is a speaker restart:

2013-07-12 15:32:21,323 using audio codec: MPEG 1 Audio, Layer 3 (MP3)
2013-07-12 15:32:22,747 re-starting speaker because of overrun
2013-07-12 15:32:22,748 re-starting speaker because of overrun
2013-07-12 15:32:22,856 using audio codec: MPEG 1 Audio, Layer 3 (MP3)

The sound pipeline never restarts.

To reproduce one simply needs to get sound playing on something before an overrun and then wait. One will come, and the sound won't come back.

There also seems to be some strange behavior when the session is started with multiple start-children. With 2 xterms only one will accept focus, and attempting to shift focus to the other will actually block either from accepting focus (from the keyboard at least) for between 1 and 3 minutes, after which the one that would accept focus previously will again. Trying again with the other repeats the process. (Three out of five times it was the "top" xterm, the other times it was the "bottom"). Trying to go to the focus-breaking child also blocks any ability to focus, for the keyboard, on any browser windows that have been initiated.

I don't know if this start-child issue is related or not... but it seemed worth mentioning.

[totaam]

2013-07-13 03:43:09: antoine changed owner from antoine to afarr

[totaam]

2013-07-13 03:43:09: antoine commented

---

Are you sure that the encoding makes any difference?
I don't see why it would.

The focus stuff is ongoing (see other tickets, and if needed put the info there, not here).
As for the sound, please post the log in debug mode.
It may be that osx won't let us connect to the sound output more than once, ouch.
(Harder to test for me with vbox than on a real machine)

[totaam]

2013-07-14 06:09:20: antoine commented

---

As per #249#comment:13, please provide server and client debug output.

[totaam]

2013-07-15 21:52:36: afarr changed status from new to assigned

[totaam]

2013-07-15 21:52:36: afarr commented

---

It looks like the encoding doesn't make any difference- it just happened to be with the vpx that I saw the sound stop after a re-starting speaker because of overrun.

I ran a number of tests with -d all with both x264 and vpx. In some cases, with each, the sound worked as expected, in other cases there was no sound at all.

In each case, after pausing by clicking on the global menu, the sound did not restart (I tried once with x264 and once with vpx, with a second global menu pause and unpause in each case also failing to re-initialize sound).

I'll attach complete logs, client and server, and label them according to behaviors (let me know if you want me to attach some more of the redundant cases of with or without sound, or whatever).

[totaam]

2013-07-15 21:59:14: afarr uploaded file xpraticket379_clientlogs3-x264-noSound.txt (3364.5 KiB)

osx r3830 x264 soundFailed client log

[totaam]

2013-07-15 22:04:46: afarr uploaded file xpraticket379_clientlogs2-x264-Sound.txt.zip (438.0 KiB)

osx r3830 x264-withSound client log

[totaam]

2013-07-15 22:07:11: afarr uploaded file xpraticket379_clientlogs7-vpx-noSound-BadPicture.txt (2446.1 KiB)

osx r3830 vpx noSound client log

[totaam]

2013-07-15 22:09:33: afarr uploaded file xpraticket379_clientlogs9-x264-Sound-globalPaused.txt (3736.1 KiB)

osx r3830 x264 with global menu pause client log

[totaam]

2013-07-15 22:12:06: afarr uploaded file xpraticket379_clientlogs8-vpx-Sound-globalPaused.txt (2994.8 KiB)

osx r3830 vpx with Global Pause client log

[totaam]

2013-07-16 16:13:41: antoine commented

---

• osx [r3830](../commit/1ce3579c24d83c9a11096857c984d4b2add15f63) x264 soundFailed client log
  Failed? Did the sound not start at all?
  I see many of those in the log:

2013-07-15 12:40:11,495 mp3 sound sink started
...
2013-07-15 12:40:13,514 re-starting speaker because of overrun
...

Looks like it played for ~2 seconds, got an overrun, restarted the pipeline.
Repeated many times, pretty much every 2 to 5 seconds. Looks like it cannot settle down.
What came out of the speakers? Anything at all? Not even the first 2 seconds before the first overrun?

[[BR]]

• osx [r3830](../commit/1ce3579c24d83c9a11096857c984d4b2add15f63) vpx noSound client log
  What is the difference between "noSound" here and "soundFailed" above?

2013-07-15 12:58:31,701 starting mp3 sound sink
...
2013-07-15 12:58:58,079 re-starting speaker because of overrun
...

Then more of the same: it overruns every few seconds. But at least in this test, the sound played for a whole ~27 seconds before the first overrun. Any idea why?

[[BR]]

• osx [r3830](../commit/1ce3579c24d83c9a11096857c984d4b2add15f63) x264 with global menu pause client log

2013-07-15 13:07:51,786 mp3 sound sink started
(...)
2013-07-15 13:09:02,759 sound sink queue overrun: level=470
2013-07-15 13:09:02,760 re-starting speaker because of overrun
2013-07-15 13:09:02,760 sound sink queue underrun: level=470
(...)

How can we have both underrun and overrun at the same queue level!? (TODO: antoine)
[[BR]]
Anyway, for the UI thread lock detection:

2013-07-15 13:08:24,328 poll_UI_loop() last_UI_thread_time was 0.9 seconds ago, UI_blocked_sent=False
2013-07-15 13:08:24,348 sound sink queue underrun: level=26
2013-07-15 13:08:25,329 poll_UI_loop() last_UI_thread_time was 1.9 seconds ago, UI_blocked_sent=False
2013-07-15 13:08:26,329 poll_UI_loop() last_UI_thread_time was 2.9 seconds ago, UI_blocked_sent=False
2013-07-15 13:08:26,330 UI thread is blocked, pausing server
2013-07-15 13:08:27,331 poll_UI_loop() last_UI_thread_time was 3.9 seconds ago, UI_blocked_sent=True
(...)
2013-07-15 13:09:02,351 poll_UI_loop() last_UI_thread_time was 39.0 seconds ago, UI_blocked_sent=True
2013-07-15 13:09:02,661 average server latency=23.4, using max wait 1.05s
2013-07-15 13:09:02,662 check_echo_timeout(1373918869296) last_ping_echoed_time=1373918899341
2013-07-15 13:09:02,662 UI_thread_wakeup()
2013-07-15 13:09:02,662 UI thread is running again, resuming

After that we can see the sound queue filling up again:

2013-07-15 13:09:02,680 sound sink: adding 417 bytes to \
    /GstPipeline:pipeline0/GstAppSrc:src (__main__.GstAppSrc), metadata: {'duration': 26122449, 'timestamp': 32888163265L}, level=287

And this is exactly when we get the only sound overrun (see timings above).
That's because when the osx UI thread is blocked, we will accumulate sound buffers that were sent before we told the server to "suspend", and so when we resume, all these pending buffers cause an overrun. Instead, we now "bump_sound_sequence()" to just drop those old sound buffers: done in r3869.
[[BR]]
At the server end ("fedora-18 [r3859](../commit/def0b2eab5db144d77b0dab987effa091343b1fc) with-client-x264-withGlobalPause Server Logs"), we see:

2013-07-15 13:07:38,319 using sound codec mp3
(..)
2013-07-15 13:08:15,374 will process ui packet suspend
2013-07-15 13:08:15,374 suspend([True, (1, 2, 4)])
2013-07-15 13:08:15,374 suspend(True, {\
    1: <WindowModel object at 0x1d8ca00 (xpra+x11+gtk_x11+window+WindowModel at 0x185ee80)>, \
    2: <WindowModel object at 0x1d96190 (xpra+x11+gtk_x11+window+WindowModel at 0x185f960)>, \
    4: <WindowModel object at 0x7fcb0ca99870 (xpra+x11+gtk_x11+window+WindowModel at 0x185ed20)>}) \
  suspended=False, resume_sound=False, sound_source=<xpra.sound.src.SoundSource object at 0x1d98090>
2013-07-15 13:08:15,374 SoundPipeline.stop()
2013-07-15 13:08:15,377 SoundPipeline.stop() done
2013-07-15 13:08:15,377 SoundPipeline.cleanup()
2013-07-15 13:08:15,377 SoundPipeline.stop()
2013-07-15 13:08:15,377 SoundPipeline.stop() done
2013-07-15 13:08:15,378 SoundPipeline.cleanup() done
(...)
2013-07-15 13:08:51,707 will process ui packet resume
2013-07-15 13:08:51,707 resume([True, (1, 2, 4)])
2013-07-15 13:08:51,707 resume(True, {\
    1: <WindowModel object at 0x1d8ca00 (xpra+x11+gtk_x11+window+WindowModel at 0x185ee80)>, \
    2: <WindowModel object at 0x1d96190 (xpra+x11+gtk_x11+window+WindowModel at 0x185f960)>, \
    4: <WindowModel object at 0x7fcb0ca99870 (xpra+x11+gtk_x11+window+WindowModel at 0x185ed20)>}) \
  suspended=True, resume_sound=True, sound_source=None
2013-07-15 13:08:51,708 not starting sound as we are suspended

Major blooper alert: r3868 ensures the server resumes the sound as expected.. (apart from that, it looks very good)

---

Please try again (at least the suspend/resume cycle should be fixed).

If we cannot figure out a pattern that is causing those overruns (that is even assuming that the overruns are the reason why the sound stops - TBC), then we may have to resort to using a subprocess instead of gstreamer built-in to ensure that the sound does start and stop exactly when we ask for it. (and if need be, we can use gstreamer 1.0.x when using a subprocess)

[totaam]

2013-07-16 18:26:46: afarr commented

---

In both cases labelled noSound I didn't hear any sound at all. However, it usually takes a second or two to launch a browser from the xterm start-child and then get the browser to a site with sound. As I said, in an earlier attempt I managed the timing just right and got sound for a second and then it stopped (which was dumb luck and a hint as to what was happening- it corresponded with a sound restart client log, but it wasn't running -d all, so there might have been something else happening).

I will repeat the tests for a while and hopefully will stumble across a sound drop as it happens, rather than the sound either working the whole way through (the logs listed as "Sound") vs. no apparent sound (noSound).

As a side note, the videos restarted at the pause point if the pause was short enough. The sound, however, never resumed.

[totaam]

2013-07-16 22:19:07: afarr commented

---

Did a lot more testing with x264, vpx and rgb encoding. However, my r3869 client seems to have some bad opengl libs, so all of my tests had to be run with --opengl=off.

Some tests I heard no sound at all (with each of the encodings, presumably it cut out before I managed to get sound started), some I heard sound... but I let a couple of tests run for 10 plus minutes (one x264 one vpx) and in each case the sound eventually stopped/didn't reset (after a speaker restart?).

The sound never restarted after a global menu click paused the client/server for a full second or more (pausing then resuming immediately, however, did not kill sound, presumably because it was quick enough that the speaker's didn't require an actual restarting?).

Interestingly, in cases where the sound was playing disconnecting my earbuds, or connecting them, also stopped the sound (and I couldn't get it to re-start).

I'm attaching a number of logs, client and corresponding server, which I'll try to identify as clearly as possible.

[totaam]

2013-07-16 22:21:21: afarr uploaded file xpraticket379_clientlogs14.txt (543.1 KiB)

osx r3869 x264 encoding no opengl sound stopped after 2+/- seconds client log

[totaam]

2013-07-16 22:23:07: afarr uploaded file xpraticket379_serverlogs14.txt (622.3 KiB)

fedora-18 r3869 with x264 no opengl client sound stopped after 2+/- seconds server log

[totaam]

2013-07-16 22:27:01: afarr uploaded file xpraticket379_clientlogs32.txt.zip (363.0 KiB)

osx r3869 x264 no opengl sound stopped after 10+ min client log

[totaam]

2013-07-16 22:29:21: afarr uploaded file xpraticket379_serverlogs32.zip (711.0 KiB)

fedora-18 r3869 with x264 no opengl client sound stopped after 10+ min server log

[totaam]

2013-07-16 22:30:34: afarr uploaded file xpraticket379_clientlogs31.txt.zip (244.3 KiB)

osx r3869 vpx no opengl sound stopped after 10+ min client log

[totaam]

2013-07-16 22:35:47: afarr uploaded file xpraticket379_clientlogs28.txt (621.1 KiB)

osx r3869 x264 no opengl sound resumed after global pause < 1sec client log

[totaam]

2013-07-16 22:37:09: afarr uploaded file xpraticket379_serverlogs28.txt (654.1 KiB)

fedora-18 r3869 with x264 no opengl client sound resumed after global pause < 1sec server log

[totaam]

2013-07-16 22:42:17: afarr uploaded file xpraticket379_clientlogs18.txt (994.4 KiB)

osx r3869 x264 no opengl sound stopped after earbuds plugged in client logs

[totaam]

2013-07-17 08:06:12: antoine commented

---

However, it usually takes a second or two to launch a browser from the xterm start-child and then get the browser to a site with sound.
[[BR]]
Then you can connect from another machine instead, do what is required to get some sound going and only then connect from the mac client.
Or you can also just start an app that does sound and nothing else, which could also be useful to see if there are any differences related to system/network latency or line contention with the video channel, something like: --start-child="mplayer somemusic.mp3"

... and in each case the sound eventually stopped/didn't reset
[[BR]]
Does this correspond to "re-start" events in the logs? Match the event time with:

re-starting speaker because of overrun

pausing then resuming immediately, however, did not kill sound, presumably because it was quick enough that the speaker's didn't require an actual restarting?
[[BR]]
Yes, that's likely the case. The suspend/resume cycle starts after around +2 seconds of UI lock.

Interestingly, in cases where the sound was playing disconnecting my earbuds, or connecting them, also stopped the sound
[[BR]]
Well, that's probably the biggest problem: looks like osx does something unexpected to our sound pipeline when that happens.
Can you capture logs of sound stopping because of this specifically? Just when this happens, not the megabytes of log before and after. Maybe the pipeline is paused and we need to give it a nudge (I hope).

---

What we may be able to do to workaround this crappy osx behaviour (but not the earplug thing) is to avoid restarting the pipeline altogether when we get an overrun:

• tell the server to start a new sound sequence (as we already do)
• drain the current pipeline: either by lowering the size of the queue (hard) or just by bumping the sound sequence number a few seconds before we tell the server (ugly but easier)

[totaam]

2013-07-17 09:11:40: antoine changed component from client to platforms

[totaam]

2013-07-17 09:11:40: antoine changed title from osx client with vpx encoding speakers never restart to osx client with sound output never restarts

[totaam]

2013-07-17 09:11:40: antoine commented

---

Updating title since this has nothing to do with a specific encoding.

[totaam]

2013-07-17 23:57:19: afarr commented

---

Does this correspond to "re-start" events in the logs? Match the event time with:
re-starting speaker because of overrun

Yes, it seems to. Looking through test14 logs I have:
2013-07-16 12:01:16,750 update_metadata({'title': 'Spikes Browser 1.999.08 - Splendid by Professor Elemental - YouTube'})
And about 9 seconds later:
2013-07-16 12:01:25,506 re-starting speaker because of overrun

Giving time for the video to start, that corresponds well enough to a perception of 2-4 seconds (especially as time was flying while I was enjoying the song?)... and that was the first instance I found in the logs of a re-starting of the speakers.

I'll attach an edited version of the log that shows various UI actions along the way with things running smoothly, as well as the portion where the re-start happens and all the actions that spurs.

Well, that's probably the biggest problem: looks like osx does something unexpected to our sound pipeline when that happens.
Can you capture logs of sound stopping because of this specifically? Just when this happens, not the megabytes of log before and after.

The logs for test17, one of the ones with the earbud speaker killing, doesn't show anything very different:

2013-07-16 12:11:43,519 sound sink: adding 417 bytes to /GstPipeline:pipeline0/GstAppSrc:src (__main__.GstAppSrc), metadata: {'duration': 26122449, 'timestamp': 62589387755L}, level=313
2013-07-16 12:11:43,519 on_enough_data((<__main__.GstAppSrc object (src) at 0x166e3940>,))
2013-07-16 12:11:43,519 sound sink: adding 522 bytes to /GstPipeline:pipeline0/GstAppSrc:src (__main__.GstAppSrc), metadata: {'duration': 26122449, 'timestamp': 62615510204L}, level=313
2013-07-16 12:11:43,528 sound sink queue overrun: level=470
2013-07-16 12:11:43,528 re-starting speaker because of overrun
2013-07-16 12:11:43,529 sound sink queue overrun: level=470
2013-07-16 12:11:43,529 re-starting speaker because of overrun

I've edited it down to some basics and will attach it as well. The big difference I can see is that there are a dozen re-starts in close succession, rather that just a single one like test14 where the sound cut out without a "client speaker mode change".

I'll also go through and edit down the megabytes of test32 (one of the ones that cut sound after 10+ minutes) to see if it is displaying the same problem (I suspect it is) and I'll attach something digestible from that too. Let me know if you think there's any point in going through the server logs too.

[totaam]

2013-07-17 23:59:10: afarr uploaded file xpraticket379_clientlogs14_edited.txt (48.3 KiB)

osx r3869 client logs edited, sound drop after 9 seconds of video

[totaam]

2013-07-18 00:00:07: afarr uploaded file xpraticket379_clientlogs17_edited.txt (21.6 KiB)

osx r3869 client logs edited, sound drop after earbuds pulled

[totaam]

2013-07-18 02:51:45: afarr uploaded file xpraticket379_clientlogs32_edited.txt (41.0 KiB)

osx r3869 ran for many minutes before speaker re-set

[totaam]

2013-07-18 11:25:56: antoine commented

---

The logs for test17, one of the ones with the earbud speaker killing, doesn't show anything very different:
[[BR]]
Well, that's good news I think, if the earplug changes only pause the sound output and cause an overrun, we can deal with that in the same way as any other overrun.

[[BR]]
r3871 may solve the osx problems by avoiding the teardown, we just re-use the same pipeline and never tear it down.

Please test to confirm that it does allow the sound to restart on osx when we get overruns (either as a result of earplug changes or just regular overruns).
It is worth testing on win32 again to make sure this does not have any undesirable side-effects there (I would much prefer not having to special case each platform).
[[BR]]
Pending: you will need the global menu to be able to test this:
Also, I think that the tray menu which allows one to stop/start the speaker may still suffer from the problem on osx (the sound won't restart), if so then I'll just disable the option to stop/start for osx in this release, and try to come up with an alternative implementation for the next release (like keep the same pipeline for the lifetime of the application, and manipulate its state directly: pause/play - which is not as simple as it 'sounds' ;)

[[BR]]
If this does not solve the problems, it may be worth trying the xpra/sound/sink.py tool from the mac command line to see if it suffers from the same problems. (interrupting it with ctrl-Z then resuming it, etc.)

[[BR]]
Note however that this solution is somewhat less direct than the previous code and we may therefore end up:

• playing old sound buffers for longer as we drain the current pipeline (~0.5s maximum)
• getting repeated overruns as we have to drain the buffers first (should recover quickly unless the network jitter is very very bad... in which case, we don't really need to worry anyway: bigger problems)

Hopefully, this isn't too much of an issue.

[totaam]

2013-07-19 01:06:35: afarr commented

---

Haven't gotten the osx built to test yet, but, in the meantime:

It is worth testing on win32 again to make sure this does not have any undesirable side-effects there (I would much prefer not having to special case each platform).

I'm afraid that with the win client (r3878, & freshly updated fedora-18 also with r3878) I'm getting: No sound; Choppy Sound; or good sound which eventually becomes choppy.

It looks like (sounds like) efforts to re-use the same sound pipeline with a win client causes the "leaky pipe choppiness" which manual adjustments to the leaky pipes settings used to cause.

I'll attach client logs for each case (the server logs didn't show anything interesting, though I can attach them too if you think there might be something in there), but it looks like the only real difference between them is the frequency of the re-starting speaker because of overrun. In the case where I heard no sound, it looked like the client was either re-starting speakers or ignoring sound data with old sequence number many multiple times per second, while the tests in which I heard choppy sound were doing it ... well, less. (Looking through the logs it looks like a break of 0.12 seconds or more between re-starts seems to be enough to hear an intelligible snippet of sound.)

In the first test in which I got the stuttering, it looked like there were a solid 3 seconds between the start of sound playing and a speaker re-start, which seemed to be enough for the pipeline to at least start... after which the choppiness was extreme, but sound continued to play. (In each case where there was sound, starting and stopping the speakers worked as expected... though it didn't fix choppy sound.)

At a glance:

2013-07-18 14:12:43,173 set_modal(False) swallowed
2013-07-18 14:12:43,174 set_fullscreen(False)
2013-07-18 14:12:43,174 sound sink: adding 104 bytes to /GstPipeline:pipeline0/GstAppSrc:src (__main__.GstAppSrc), metadata: {'duration': 26122449, 'timestamp': 14889795918L, 'sequence': 46}, level=365
2013-07-18 14:12:43,174 update_metadata({'title': "Spikes Browser 1.999.08 - Professor Elemental - I'm British (Dir: Moog Gravett) - YouTube"})
2013-07-18 14:12:43,176 set_modal(False) swallowed
2013-07-18 14:12:43,177 set_fullscreen(False)
2013-07-18 14:12:43,177 sound sink: adding 104 bytes to /GstPipeline:pipeline0/GstAppSrc:src (__main__.GstAppSrc), metadata: {'duration': 26122449, 'timestamp': 14915918367L, 'sequence': 46}, level=365
2013-07-18 14:12:43,180 need_data: 4096 bytes in /GstPipeline:pipeline0/GstAppSrc:src (__main__.GstAppSrc)
...
2013-07-18 14:12:46,875 re-starting speaker because of overrun
...
2013-07-18 14:12:47,266 re-starting speaker because of overrun
...
2013-07-18 14:12:47,365 re-starting speaker because of overrun
...

[totaam]

2013-07-19 03:22:35: antoine changed status from assigned to new

[totaam]

2013-07-19 03:22:35: antoine changed owner from afarr to antoine

[totaam]

2013-07-19 03:22:35: antoine commented

---

I was hoping it would not be the case (sorry, couldn't test properly yesterday), the proper solution to this is to wait for the pipeline to drain before requesting the re-start from the server.

(A better solution would be to force it to drain without waiting)

[totaam]

2013-07-19 07:11:57: antoine changed owner from antoine to afarr

[totaam]

2013-07-19 07:11:57: antoine commented

---

Please see r3882 commit message.

Needs more testing - I will try to do some more today.

[totaam]

2013-07-22 22:16:41: afarr changed status from new to assigned

[totaam]

2013-07-22 22:16:41: afarr commented

---

With Win client r3908 I'm still getting the sound drop. (Was testing OpenGL, hard to judge that though when the sound drops so quickly.)

Server side snippet:

2013-07-22 13:36:19,349 process non-ui packet damage-sequence
2013-07-22 13:36:19,349 record_latency: took 53.1 ms round trip (52.9 just for echo), 47.0 for decoding $
2013-07-22 13:36:19,390 will process ui packet sound-control
2013-07-22 13:36:19,390 will process ui packet sound-control
2013-07-22 13:36:19,390 will process ui packet sound-control
2013-07-22 13:36:19,390 SoundPipeline.stop()
2013-07-22 13:36:19,393 SoundPipeline.stop() done
2013-07-22 13:36:19,393 SoundPipeline.cleanup()
2013-07-22 13:36:19,393 SoundPipeline.stop()
2013-07-22 13:36:19,393 SoundPipeline.stop() done
2013-07-22 13:36:19,394 SoundPipeline.cleanup() done
2013-07-22 13:36:19,439 get_client_backlog missing acks: []
2013-07-22 13:36:19,440 update_quality() info={'backlog_factor': 100, 'latency_factor': 1325, 'min_quali$
2013-07-22 13:36:19,440 update_speed() info={'abs_factor': 39, 'target_damage_latency': 54, 'min_speed':$
2013-07-22 13:36:19,443 process non-ui packet damage-sequence
2013-07-22 13:36:19,443 record_latency: took 50.7 ms round trip (50.6 just for echo), 47.0 for decoding $

Client side snippet:

2013-07-22 13:36:17,065 present_fbo() drawable=<gtk.gdk.GLWindowImplWin32 object at 0x7511ee0 (GdkGLWindowImplWin32 at 0x2cd40e0)>
2013-07-22 13:36:17,065 src 8246 type 8251 id 20084 severity 9148 length 120 message Texture state usage warning: Waste of memory: Texture 0 has mipmaps, while it's min filter is inconsistent with mipmaps.
2013-07-22 13:36:17,065 SWAPPING BUFFERS NOW
2013-07-22 13:36:17,068 src 8246 type 8251 id 20084 severity 9148 length 120 message Texture state usage warning: Waste of memory: Texture 0 has mipmaps, while it's min filter is inconsistent with mipmaps.
2013-07-22 13:36:17,071 sound sink: adding 313 bytes to /GstPipeline:pipeline0/GstAppSrc:src (__main__.GstAppSrc), metadata: {'duration': 26122449, 'timestamp': 101799183673L}, level=444
2013-07-22 13:36:17,072 sound sink: adding 261 bytes to /GstPipeline:pipeline0/GstAppSrc:src (__main__.GstAppSrc), metadata: {'duration': 26122449, 'timestamp': 101825306122L}, level=444
2013-07-22 13:36:17,072 sound sink: adding 261 bytes to /GstPipeline:pipeline0/GstAppSrc:src (__main__.GstAppSrc), metadata: {'duration': 26122449, 'timestamp': 101851428571L}, level=444
2013-07-22 13:36:17,073 sound sink: adding 417 bytes to /GstPipeline:pipeline0/GstAppSrc:src (__main__.GstAppSrc), metadata: {'duration': 26122449, 'timestamp': 101877551020L}, level=444
2013-07-22 13:36:17,075 sound sink queue overrun: level=470
2013-07-22 13:36:17,075 re-starting speaker because of overrun
2013-07-22 13:36:17,078 sound sink queue overrun: level=470
2013-07-22 13:36:17,078 re-starting speaker because of overrun
2013-07-22 13:36:17,082 sound sink queue overrun: level=470
2013-07-22 13:36:17,082 re-starting speaker because of overrun
2013-07-22 13:36:17,082 need_data: 4096 bytes in /GstPipeline:pipeline0/GstAppSrc:src (__main__.GstAppSrc)
2013-07-22 13:36:17,144 GL Pixmap backing size: 1120 x 642, drawable=<gtk.gdk.GLWindowImplWin32 object at 0x75129e0 (GdkGLWindowImplWin32 at 0x2cd40e0)>
2013-07-22 13:36:17,145 update_texture_yuv((0, 0, 1120, 642, <xpra.codecs.image_wrapper.ImageWrapper object at 0x07306370>, 'YUV444P'))

I'll attach whole logs in case you have any desire to look through them.

[totaam]

2013-07-22 23:35:24: afarr commented

---

Meanwhile, the osx client (still with --opengl=off), r3961, the sound seems to often drop immediately. Without even running -d all I saw this prominently in the client logs:

2013-07-22 15:20:53,704 Attached to tcp:10.0.32.196:1200 (press Control-C to detach)

2013-07-22 15:20:55,783 UI thread is blocked, pausing server
2013-07-22 15:20:56,436 UI thread is running again, resuming
2013-07-22 15:20:58,303 using audio codec: MPEG 1 Audio, Layer 3 (MP3)

A second & third test showed this:

2013-07-22 15:26:48,103 Attached to tcp:10.0.32.196:1200 (press Control-C to detach)

2013-07-22 15:26:49,132 using audio codec: MPEG 1 Audio, Layer 3 (MP3)
2013-07-22 15:26:50,952 re-starting speaker because of overrun

And a fourth test showed none of the above, and sound worked... and when the sound eventually cut out- the re-starting speaker because of overrun message appeared at exactly that same time.

[totaam]

2013-07-23 14:37:06: antoine commented

---

Meanwhile, the osx client (still with --opengl=off)
Is this because of bad dylibs? If so, please follow up in #226 (OpenGL should be irrelevant to this ticket)

---

With r3968, I only seem to get a single overrun, usually on startup.
That seems to be because the pipelines take a while to initialize fully (we could do something about that too by initializing the pipeline when we request the sound, not when we start receiving it - or even request it when we are certain that initialization is complete)
Does this work for you? (I have tested this on Linux, win32 and osx - without sound output on the last two to verify..)
We no longer start/stop (which breaks OSX) or wait for the pipeline to drain (which does not seem to fire the "underrun" events we wait for)

[totaam]

2013-07-24 00:44:27: smo commented

---

Testing r3969 build on win32 with vpx encoding.

I seem to still have an issue that when the overrun occurs I can't get sound again.

Sometimes difficult to produce an overrun on a local network so I usually just wait until it occurs.

[totaam]

2013-07-24 02:29:30: antoine commented

---

I seem to still have an issue that when the overrun occurs I can't get sound again.
Is this on both platforms? Do you have logs?
[[BR]]

Sometimes difficult to produce an overrun on a local network so I usually just wait until it occurs.
Yes, not sure why the new code improves this..
You can make it fire more easily by reducing the queue size:

XPRA_SOUND_QUEUE_TIME=150 xpra attach

(default is 450)

[totaam]

2013-07-24 20:21:07: afarr commented

---

With osx r3971 I still get overrun and re-starting speakers logs which correspond to the sound cutting out.

2013-07-24 12:07:19,270 set_modal(False) swallowed
2013-07-24 12:07:19,270 need_data: 4096 bytes in /GstPipeline:pipeline0/GstAppSrc:src (__main__.GstAppSrc)
2013-07-24 12:07:19,270 update_metadata({'title': "Spikes Browser 1.999.08 - Professor Elemental - I'm British (Dir: Moog Gravett) - YouTube"})
2013-07-24 12:07:19,271 set_modal(False) swallowed
2013-07-24 12:07:19,289 sound sink: adding 104 bytes to /GstPipeline:pipeline0/GstAppSrc:src (__main__.GstAppSrc)
2013-07-24 12:07:19,290 sound sink: new level=365
2013-07-24 12:07:19,290 need_data: 4096 bytes in /GstPipeline:pipeline0/GstAppSrc:src (__main__.GstAppSrc)

Quickly followed by

2013-07-24 12:07:25,050 sound_sink_overrun(<xpra.sound.sink.SoundSink object at 0x166e28f0>, 470, ())
2013-07-24 12:07:25,050 sound sink: new level=470
2013-07-24 12:07:25,050 re-starting speaker because of overrun, delay=470ms
2013-07-24 12:07:25,050 min_sound_sequence=1
2013-07-24 12:07:25,055 ignoring sound data with old sequence number -1
2013-07-24 12:07:25,058 new hidden group leader window <gtk.gdk.Window object at 0x504ad0 (GdkWindow at 0xa9a428)> for ref=13494
2013-07-24 12:07:25,058 get_client_window_class({'fullscreen': False, 'has-alpha': True, 'xid': '0xc00c1c', 'pid': 13494, 'window-type': ('TOOLTIP',), 'maximized': False, 'override-redirect': True}, True) GLClientWindowClass=None, opengl_enabled=False, mmap_enabled=False, window_types=('TOOLTIP',), encoding=x264

I'll attach the log in it's entirety (a lucky case where the overrun happened within 6 seconds of the sound starting). Let me know if you want corresponding server logs.

[totaam]

2013-07-24 20:22:41: afarr uploaded file testxpraticket379_clientlog42.txt (530.3 KiB)

osx r3971 client log sound drop at 12:07:25

[totaam]

2013-07-24 22:45:39: afarr commented

---

With win client r3971 the sound doesn't initialize properly (4 tests, no sound initially with any of them). However, if I use the xpra tray to turn speakers off/on then the sound runs fine. Well even.

Letting it run for an hour never encountered sound cutting off. After about half an hour though, I began to notice some of the choppiness characteristic of leaky sound pipes. After an hour it sounded like nearly as much was leaking out of the sound pipes as was making its way all the way to my speakers.

A look through the logs (time +/- 14:12 when I first noticed sound leakiness) I find a lot like this:

2013-07-24 14:12:04,124 sound sink queue overrun: level=470
2013-07-24 14:12:04,124 sound_sink_overrun(<xpra.sound.sink.SoundSink object at 0x02380190>, 470, ())
2013-07-24 14:12:04,124 overrun: already waiting for restart
2013-07-24 14:12:04,127 sound sink queue overrun: level=470
2013-07-24 14:12:04,128 sound_sink_overrun(<xpra.sound.sink.SoundSink object at 0x02380190>, 470, ())
2013-07-24 14:12:04,128 overrun: already waiting for restart
2013-07-24 14:12:04,130 need_data: 4096 bytes in /GstPipeline:pipeline1/GstAppSrc:src (__main__.GstAppSrc)
2013-07-24 14:12:04,180 sound sink: adding 626 bytes to /GstPipeline:pipeline1/GstAppSrc:src (__main__.GstAppSrc)
2013-07-24 14:12:04,181 sound sink: new level=417
2013-07-24 14:12:04,183 sound sink: adding 365 bytes to /GstPipeline:pipeline1/GstAppSrc:src (__main__.GstAppSrc)
2013-07-24 14:12:04,183 sound sink: new level=417
2013-07-24 14:12:04,187 need_data: 4096 bytes in /GstPipeline:pipeline1/GstAppSrc:src (__main__.GstAppSrc)
2013-07-24 14:12:04,246 sound sink: adding 522 bytes to /GstPipeline:pipeline1/GstAppSrc:src (__main__.GstAppSrc)
2013-07-24 14:12:04,246 sound sink: new level=470
2013-07-24 14:12:04,247 sound sink: adding 313 bytes to /GstPipeline:pipeline1/GstAppSrc:src (__main__.GstAppSrc)
2013-07-24 14:12:04,247 sound sink: new level=391
2013-07-24 14:12:04,250 need_data: 4096 bytes in /GstPipeline:pipeline1/GstAppSrc:src (__main__.GstAppSrc)

Closer to the end of the session:

2013-07-24 14:30:14,680 sound sink: adding 313 bytes to /GstPipeline:pipeline1/GstAppSrc:src (__main__.GstAppSrc)
2013-07-24 14:30:14,680 sound sink: new level=470
2013-07-24 14:30:14,681 sound sink: adding 313 bytes to /GstPipeline:pipeline1/GstAppSrc:src (__main__.GstAppSrc)
2013-07-24 14:30:14,681 sound sink: new level=470
2013-07-24 14:30:14,683 sound sink queue overrun: level=470
2013-07-24 14:30:14,684 sound_sink_overrun(<xpra.sound.sink.SoundSink object at 0x02380190>, 470, ())
2013-07-24 14:30:14,684 overrun: already waiting for restart
2013-07-24 14:30:14,687 sound sink queue overrun: level=470
2013-07-24 14:30:14,687 sound_sink_overrun(<xpra.sound.sink.SoundSink object at 0x02380190>, 470, ())
2013-07-24 14:30:14,688 overrun: already waiting for restart
2013-07-24 14:30:14,688 need_data: 4096 bytes in /GstPipeline:pipeline1/GstAppSrc:src (__main__.GstAppSrc)
2013-07-24 14:30:14,736 sound sink: adding 261 bytes to /GstPipeline:pipeline1/GstAppSrc:src (__main__.GstAppSrc)
2013-07-24 14:30:14,736 sound sink: new level=470
2013-07-24 14:30:14,736 sound sink: adding 313 bytes to /GstPipeline:pipeline1/GstAppSrc:src (__main__.GstAppSrc)
2013-07-24 14:30:14,737 sound sink: new level=470
2013-07-24 14:30:14,739 sound sink queue overrun: level=470
2013-07-24 14:30:14,740 sound_sink_overrun(<xpra.sound.sink.SoundSink object at 0x02380190>, 470, ())
2013-07-24 14:30:14,740 overrun: already waiting for restart
2013-07-24 14:30:14,743 sound sink queue overrun: level=470
2013-07-24 14:30:14,743 sound_sink_overrun(<xpra.sound.sink.SoundSink object at 0x02380190>, 470, ())
2013-07-24 14:30:14,744 overrun: already waiting for restart
2013-07-24 14:30:14,746 need_data: 4096 bytes in /GstPipeline:pipeline1/GstAppSrc:src (__main__.GstAppSrc)

It looks like, not surprisingly, as time goes on and the speakers don't restart the leakiness becomes more and more pronounced (as the overrun: already waiting for restart messages happen more and more frequently) and eventually unbearable. The fact that there was no re-starting speakers and there was also no sound cut out does seem to isolate the problem to that process though (if it was ever in question).

I'll attach a complete log. Let me know if you want corresponding server log.

[totaam]

2013-07-25 01:49:41: afarr commented

---

I'm not sure if it is significant, but with that sound patch provided for Smo the sound is still cutting-out, but using the tray menu icon to toggle the speakers off/on restarts it.

Comparing the logs for the SoundPipeline.start() of a failed restart vs a successful, the only difference that I can spot is that, with the failed start I see this:

2013-07-24 16:19:19,151 SoundPipeline.start()
2013-07-24 16:19:19,211 sound sink queue underrun: level=0
2013-07-24 16:19:19,213 SoundPipeline.start() done

and with a successful start I see this:

2013-07-24 16:19:23,653 SoundPipeline.start()
2013-07-24 16:19:23,707 SoundPipeline.start() done
2013-07-24 16:19:23,707 sound sink queue underrun: level=0

I have a hard time imagining that the little difference is causing so much headache, but if there's a process firing out of order for some reason, it might be significant(?).

I'll zip and attach the full log. 16:19 had a manual speaker reset and 16:28 and 16:54 ... which should at least narrow down the places to look in this monstrosity of a log file, if it seems likely to be productive.

[totaam]

2013-07-31 12:50:48: antoine uploaded file sound-restart-from-underrun.patch (2.5 KiB)

another attempt at getting sound to restart on OSX via an underrun signal without stop/start

[totaam]

2013-07-31 12:55:24: antoine commented

---

As per #362#comment:4, there were enough changes to warrant more testing.

Please try the latest trunk to see if OSX behaves any better with these changes. If not, then please also try with the patch: sound-restart-from-underrun.patch

Please provide logs with XPRA_SOUND_DEBUG=1 rather than -d all.

[totaam]

2013-08-01 17:03:40: antoine changed status from assigned to new

[totaam]

2013-08-01 17:03:40: antoine changed owner from afarr to SmO

[totaam]

2013-08-01 17:03:40: antoine commented

---

Please try r4040

[totaam]

2013-08-02 06:59:29: totaam commented

---

As per #362#comment:13, please stress test on osx and close this ticket.

[totaam]

2013-08-05 23:35:14: smo changed status from new to closed

[totaam]

2013-08-05 23:35:14: smo changed resolution from ** to fixed

[totaam]

2013-08-05 23:35:14: smo commented

---

After testing on several occasions over the last few days I will close this ticket.

Appears to be working correctly now on OSX