Xpra: Ticket #409: OSX client resuming UI sometimes breaks sound

Sometimes when using the menu in OSX the sound fails to restart after UI resume.

Here are the errors from the server end.

Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/xpra/server/server_base.py", line 1108, in _process_resume
    ss.resume(ui, wd)
  File "/usr/lib/python2.7/site-packages/xpra/server/source.py", line 400, in resume
    self.start_sending_sound()
TypeError: start_sending_sound() takes exactly 2 arguments (1 given)
2013-08-08 18:09:34,438 using sound codec mp3
2013-08-08 18:09:34,585 starting sound using pulseaudio device null.monitor
2013-08-08 18:09:34,710 codec: MPEG-1 Layer 3 (MP3)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/xpra/server/server_base.py", line 1108, in _process_resume
    ss.resume(ui, wd)
  File "/usr/lib/python2.7/site-packages/xpra/server/source.py", line 400, in resume
    self.start_sending_sound()
TypeError: start_sending_sound() takes exactly 2 arguments (1 given)
2013-08-08 18:09:49,994 using sound codec mp3
2013-08-08 18:09:50,062 starting sound using pulseaudio device null.monitor
2013-08-08 18:09:50,187 codec: MPEG-1 Layer 3 (MP3)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/xpra/server/server_base.py", line 1108, in _process_resume
    ss.resume(ui, wd)
  File "/usr/lib/python2.7/site-packages/xpra/server/source.py", line 400, in resume
    self.start_sending_sound()
TypeError: start_sending_sound() takes exactly 2 arguments (1 given)
2013-08-08 18:10:35,196 using sound codec mp3
2013-08-08 18:10:35,266 starting sound using pulseaudio device null.monitor
2013-08-08 18:10:35,334 codec: MPEG-1 Layer 3 (MP3)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/xpra/server/server_base.py", line 1108, in _process_resume
    ss.resume(ui, wd)
  File "/usr/lib/python2.7/site-packages/xpra/server/source.py", line 400, in resume
    self.start_sending_sound()
TypeError: start_sending_sound() takes exactly 2 arguments (1 given)


Fri, 09 Aug 2013 02:26:04 GMT - Antoine Martin: owner changed

Untested fix in r4113 - does this work for you?


Fri, 09 Aug 2013 07:22:48 GMT - Smo:

Looks like sound is restarting on the server end now but it doesn't restart on the client and no errors.

As you can see from the server output.

2013-08-09 00:19:18,441 starting sound using pulseaudio device null.monitor
2013-08-09 00:19:20,609 codec: MPEG-1 Layer 3 (MP3)
2013-08-09 00:19:21,276 using sound codec mp3
2013-08-09 00:19:21,308 starting sound using pulseaudio device null.monitor
2013-08-09 00:19:23,400 codec: MPEG-1 Layer 3 (MP3)
2013-08-09 00:19:45,191 using sound codec mp3
2013-08-09 00:19:45,234 starting sound using pulseaudio device null.monitor
2013-08-09 00:19:45,389 codec: MPEG-1 Layer 3 (MP3)
2013-08-09 00:20:09,887 using sound codec mp3
2013-08-09 00:20:09,923 starting sound using pulseaudio device null.monitor
2013-08-09 00:20:10,022 codec: MPEG-1 Layer 3 (MP3)
2013-08-09 00:20:14,670 using sound codec mp3
2013-08-09 00:20:14,706 starting sound using pulseaudio device null.monitor
2013-08-09 00:20:14,803 codec: MPEG-1 Layer 3 (MP3)
2013-08-09 00:20:18,486 using sound codec mp3
2013-08-09 00:20:18,526 starting sound using pulseaudio device null.monitor
2013-08-09 00:20:18,621 codec: MPEG-1 Layer 3 (MP3)
2013-08-09 00:20:21,702 using sound codec mp3
2013-08-09 00:20:21,741 starting sound using pulseaudio device null.monitor
2013-08-09 00:20:23,700 using sound codec mp3
2013-08-09 00:20:23,735 starting sound using pulseaudio device null.monitor
2013-08-09 00:20:23,811 codec: MPEG-1 Layer 3 (MP3)
2013-08-09 00:20:31,330 using sound codec mp3
2013-08-09 00:20:31,372 starting sound using pulseaudio device null.monitor
2013-08-09 00:20:31,480 codec: MPEG-1 Layer 3 (MP3)
2013-08-09 00:21:01,699 using sound codec mp3
2013-08-09 00:21:01,743 starting sound using pulseaudio device null.monitor
2013-08-09 00:21:01,859 codec: MPEG-1 Layer 3 (MP3)
2013-08-09 00:21:06,985 using sound codec mp3
2013-08-09 00:21:07,021 starting sound using pulseaudio device null.monitor
2013-08-09 00:21:09,112 using sound codec mp3
2013-08-09 00:21:09,147 starting sound using pulseaudio device null.monitor
2013-08-09 00:21:09,256 codec: MPEG-1 Layer 3 (MP3)
2013-08-09 00:21:14,558 using sound codec mp3
2013-08-09 00:21:14,595 starting sound using pulseaudio device null.monitor
2013-08-09 00:21:14,665 codec: MPEG-1 Layer 3 (MP3)

Fri, 09 Aug 2013 07:46:18 GMT - Antoine Martin: owner changed

So, the resume code is working and we can close this particular ticket I think.


The remaining problem is to do with the sound on OSX, and the fact that we cannot re-start pipelines. This will affect the UI (we need to remove the option), and the way we deal with overruns: as per #379 - I believe this ticket may have been closed prematurely: overruns will cause the same stop/start sequence - are you certain that the sound does continue after overruns on osx?


Fri, 09 Aug 2013 08:04:11 GMT - Smo:

Just checked again to make sure got 3 overruns right away here is the output. Client is r4124

Each time it restarted sound no problem.

2013-08-09 00:59:10,874 using audio codec: MPEG 1 Audio, Layer 3 (MP3)
2013-08-09 00:59:17,024 re-starting speaker because of overrun
objc[22248]: Object 0x3c7af20 of class NSImage autoreleased with no pool in place - just leaking - break on objc_autoreleaseNoPool() to debug
objc[22248]: Object 0x4b68fa0 of class __NSCFNumber autoreleased with no pool in place - just leaking - break on objc_autoreleaseNoPool() to debug
objc[22248]: Object 0x3bd25b0 of class __NSCFDictionary autoreleased with no pool in place - just leaking - break on objc_autoreleaseNoPool() to debug
objc[22248]: Object 0x3c7af20 of class NSImage autoreleased with no pool in place - just leaking - break on objc_autoreleaseNoPool() to debug
objc[22248]: Object 0x4b69a00 of class __NSCFNumber autoreleased with no pool in place - just leaking - break on objc_autoreleaseNoPool() to debug
objc[22248]: Object 0x3bcc680 of class __NSCFDictionary autoreleased with no pool in place - just leaking - break on objc_autoreleaseNoPool() to debug
2013-08-09 00:59:17,438 using audio codec: MPEG 1 Audio, Layer 3 (MP3)
2013-08-09 01:00:21,811 re-starting speaker because of overrun
objc[22248]: Object 0x3c7af20 of class NSImage autoreleased with no pool in place - just leaking - break on objc_autoreleaseNoPool() to debug
objc[22248]: Object 0x4b68fa0 of class __NSCFNumber autoreleased with no pool in place - just leaking - break on objc_autoreleaseNoPool() to debug
objc[22248]: Object 0x4b40550 of class __NSCFDictionary autoreleased with no pool in place - just leaking - break on objc_autoreleaseNoPool() to debug
objc[22248]: Object 0x3c7af20 of class NSImage autoreleased with no pool in place - just leaking - break on objc_autoreleaseNoPool() to debug
objc[22248]: Object 0x4b69a00 of class __NSCFNumber autoreleased with no pool in place - just leaking - break on objc_autoreleaseNoPool() to debug
objc[22248]: Object 0x4b40750 of class __NSCFDictionary autoreleased with no pool in place - just leaking - break on objc_autoreleaseNoPool() to debug
2013-08-09 01:00:22,320 using audio codec: MPEG 1 Audio, Layer 3 (MP3)
2013-08-09 01:02:06,051 re-starting speaker because of overrun
objc[22248]: Object 0x3c7af20 of class NSImage autoreleased with no pool in place - just leaking - break on objc_autoreleaseNoPool() to debug
objc[22248]: Object 0x4b68fa0 of class __NSCFNumber autoreleased with no pool in place - just leaking - break on objc_autoreleaseNoPool() to debug
objc[22248]: Object 0xef53c40 of class __NSCFDictionary autoreleased with no pool in place - just leaking - break on objc_autoreleaseNoPool() to debug
objc[22248]: Object 0x3c7af20 of class NSImage autoreleased with no pool in place - just leaking - break on objc_autoreleaseNoPool() to debug
objc[22248]: Object 0x4b69a00 of class __NSCFNumber autoreleased with no pool in place - just leaking - break on objc_autoreleaseNoPool() to debug
objc[22248]: Object 0xef54530 of class __NSCFDictionary autoreleased with no pool in place - just leaking - break on objc_autoreleaseNoPool() to debug
2013-08-09 01:02:06,447 using audio codec: MPEG 1 Audio, Layer 3 (MP3)

Fri, 09 Aug 2013 08:08:03 GMT - Antoine Martin:

Interesting.

Where do you get those NSImage / objc_autoreleaseNoPool warnings from?

Do you have the client log for the failing resume restarts? (as per comment:2)


Fri, 09 Aug 2013 08:09:56 GMT - Smo:

Those messages seem to happen everytime the sound is restarting. There was no error output on the client in comment:2. I can turn on some debugging output and provide you with that if you like.


Fri, 09 Aug 2013 08:10:36 GMT - Antoine Martin:

Yes please: XPRA_SOUND_DEBUG and/or "-d all"


Fri, 09 Aug 2013 08:21:04 GMT - Smo: attachment set

OSX Sound Debug01


Fri, 09 Aug 2013 08:21:50 GMT - Smo:

I've attached the output with XPRA_SOUND_DEBUG

Let me know if you want the full debug output.


Fri, 09 Aug 2013 13:41:12 GMT - Antoine Martin: owner changed

r4131 solves this by not using the UI thread for sound data, which means that sound should continue even when the mouse enters the OSX global menu, and if we get an overrun, it should be dealt with like a regular overrun, and this apparently works fine as it is (see comment:4)

r4132 removes the sound menu for osx (which had state synchronization problems and probably did not work - did it?)

Does this work for you?

BTW, I just started seeing those objc_autoreleaseNoPool sound warnings myself - no idea what they are about.. slightly worrying.


Sat, 10 Aug 2013 02:12:59 GMT - Smo:

When using the UI if I spend more than 2 seconds in it the sound stops. However if I stop the media and start it again I can often get sound once again.

I seem to be missing all logging to the console as well with r4142


Sat, 10 Aug 2013 02:44:59 GMT - Antoine Martin:

When using the UI if I spend more than 2 seconds in it the sound stops


That's odd.

However if I stop the media and start it again I can often get sound once again.


Does this cause an overrun before it restarts?

I seem to be missing all logging to the console as well with r4142


"all logging" ?


Sat, 10 Aug 2013 04:02:56 GMT - Smo:

Nevermind the logging comment I forgot I was redirecting it to a file oops.


Sat, 10 Aug 2013 04:05:12 GMT - Smo:

Attached debug log with XPRA_SOUND_DEBUG for comment:12


Sat, 10 Aug 2013 04:05:25 GMT - Smo: attachment set


Sat, 10 Aug 2013 05:12:37 GMT - Antoine Martin:

Please confirm what I am looking at (timing - events), what I see from the log is:

The queue state is always in "underrun", but it was also in "underrun" state before the ui suspend/resume and it was playing ok then, wasn't it?

Was the server also fully up to date? I don't see how we can end up not processing sound-data packets with the latest code (unless the server stops sending them). Please post the client output with the new debug patch attached.

Also, please clarify "sometimes breaks sound": what makes it break or not break, any difference in the logs? Any difference in terms of how long you spend in suspended mode?


Note: there was also a systray error in there:

Traceback (most recent call last):
 File "xpra/client/ui_client_base.pyc", line 1210, in _process_new_tray
 File "xpra/client/ui_client_base.pyc", line 438, in setup_system_tray
 File "xpra/client/client_tray.pyc", line 32, in __init__
 File "xpra/client/client_tray.pyc", line 89, in new_backing
 File "xpra/client/client_tray.pyc", line 140, in __init__
 TypeError: __init__() takes exactly 2 arguments (5 given)

which is fixed in r4146.


Sat, 10 Aug 2013 05:13:13 GMT - Antoine Martin: attachment set

adds logging to packet processing so we can see if those sound packets are arriving or not


Mon, 12 Aug 2013 18:25:04 GMT - Smo: attachment set


Mon, 12 Aug 2013 18:28:03 GMT - Smo:

Added a log with the patch provided.

I simply started some sound click on a menu item for >2 seconds till sound stopped then quit the session.

Not sure if that helps.


Tue, 13 Aug 2013 01:10:22 GMT - Antoine Martin:

TILs:

2013-08-12 11:21:26,567 processing non-ui packet 'sound-data' using '<bound method XpraClient._process_sound_data of \
    <XpraClient object at 0x520c490 (xpra+client+gtk2+client+XpraClient at 0x8a7420)>>'
2013-08-12 11:21:26,573 UI thread is blocked, pausing server
2013-08-12 11:21:28,717 UI thread is running again, resuming
2013-08-12 11:21:28,722 processing ui packet 'cursor' using '<bound method XpraClient._process_cursor of \
    <XpraClient object at 0x520c490 (xpra+client+gtk2+client+XpraClient at 0x8a7420)>>'
2013-08-12 11:21:28,768 processing non-ui packet 'sound-data' using '<bound method XpraClient._process_sound_data of \
    <XpraClient object at 0x520c490 (xpra+client+gtk2+client+XpraClient at 0x8a7420)>>'

So we are not receiving any packets at all for 2 seconds - which looks very suspicious. Why would the server not send any?

I will try again in a VM, in the meantime please answer the remaining questions from comment:14


Tue, 13 Aug 2013 01:24:08 GMT - Smo:

To clarify a couple things


Tue, 13 Aug 2013 04:22:16 GMT - Antoine Martin:

Silly me, I can reproduce this even with a VM, fixed in r4146.

The suspend code was causing an 'underrun'. What I don't understand is why it makes so much of a difference on OSX. Getting an 'underrun' should not be fatal, every other platform recovers gracefully. To make matters worse, we do get the occasional 'underrun' on OSX, and those aren't fatal, only this one is!?

And this makes me think that OSX may still have problems if we get network jitter. Please try with:

XPRA_FAKE_JITTER=5000 xpra ...

(client side - which should give you 5s off for 10s on)


Thu, 22 Aug 2013 07:03:21 GMT - Antoine Martin: status changed; resolution set

I assume this got tested ok


Sat, 23 Jan 2021 04:54:35 GMT - migration script:

this ticket has been moved to: https://github.com/Xpra-org/xpra/issues/409