xpra icon
Bug tracker and wiki

Opened 7 years ago

Closed 7 years ago

#409 closed defect (fixed)

OSX client resuming UI sometimes breaks sound

Reported by: Smo Owned by: Smo
Priority: major Milestone: 0.10
Component: sound Version: trunk
Keywords: Cc:

Description

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)

Attachments (4)

xpra_debug1.log (85.4 KB) - added by Smo 7 years ago.
OSX Sound Debug01
xpra_debug2.txt (76.8 KB) - added by Smo 7 years ago.
client-logs-process-packet.patch (934 bytes) - added by Antoine Martin 7 years ago.
adds logging to packet processing so we can see if those sound packets are arriving or not
xpra_debug3.txt (152.7 KB) - added by Smo 7 years ago.

Download all attachments as: .zip

Change History (23)

comment:1 Changed 7 years ago by Antoine Martin

Owner: changed from Antoine Martin to SmO

Untested fix in r4113 - does this work for you?

comment:2 Changed 7 years ago by 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)

comment:3 Changed 7 years ago by Antoine Martin

Owner: changed from SmO to osx

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?

comment:4 Changed 7 years ago by 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)

comment:5 Changed 7 years ago by 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)

comment:6 Changed 7 years ago by 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.

comment:7 Changed 7 years ago by Antoine Martin

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

Changed 7 years ago by Smo

Attachment: xpra_debug1.log added

OSX Sound Debug01

comment:8 Changed 7 years ago by Smo

I've attached the output with XPRA_SOUND_DEBUG

Let me know if you want the full debug output.

comment:9 Changed 7 years ago by Antoine Martin

Owner: changed from osx to Smo

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.

comment:10 Changed 7 years ago by 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

comment:11 Changed 7 years ago by 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" ?

Last edited 7 years ago by Antoine Martin (previous) (diff)

comment:12 Changed 7 years ago by Smo

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

comment:13 Changed 7 years ago by Smo

Attached debug log with XPRA_SOUND_DEBUG for comment:12

Changed 7 years ago by Smo

Attachment: xpra_debug2.txt added

comment:14 Changed 7 years ago by Antoine Martin

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

  • the sound starting:
    2013-08-09 21:03:29,295 using audio codec: MPEG 1 Audio, Layer 3 (MP3)
    (..)
    2013-08-09 21:03:29,335 new-state=PLAYING
    
  • Then it just plays sound and only stops briefly for 2 seconds:
    2013-08-09 21:03:33,496 UI thread is blocked, pausing server
    2013-08-09 21:03:33,498 sound sink queue underrun: level=0
    2013-08-09 21:03:35,483 UI thread is running again, resuming
    
  • Then it continues until the end (SIGINT):
    2013-08-09 21:03:37,229 add_data(..) queue_state=underrun
    

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.

Last edited 7 years ago by Antoine Martin (previous) (diff)

Changed 7 years ago by Antoine Martin

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

Changed 7 years ago by Smo

Attachment: xpra_debug3.txt added

comment:15 Changed 7 years ago by 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.

comment:16 Changed 7 years ago by 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

comment:17 Changed 7 years ago by Smo

To clarify a couple things

  • The sound plays fine before the suspend/resume it never returns afterwards and that is what I was trying to illustrate in the log files.
  • Server is usually up to date that morning I update via SVN and build a new rpm/dmg every time I test. In this instance the only patch applied was on the osx client. Both server and client are r4162.
  • What I meant by 'sometimes' breaks I meant that if you're very speedy with the menu < 2 seconds the sound continues.

comment:18 Changed 7 years ago by 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)

comment:19 Changed 7 years ago by Antoine Martin

Resolution: fixed
Status: newclosed

I assume this got tested ok

Note: See TracTickets for help on using tickets.