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

OSX client resuming UI sometimes breaks sound #409

Closed
totaam opened this issue Aug 9, 2013 · 28 comments
Closed

OSX client resuming UI sometimes breaks sound #409

totaam opened this issue Aug 9, 2013 · 28 comments
Labels
audio

Comments

@totaam
Copy link
Collaborator

totaam commented Aug 9, 2013

Issue migrated from trac ticket # 409

component: sound | priority: major | resolution: fixed

2013-08-09 02:25:30: smo created the issue

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)
@totaam
Copy link
Collaborator Author

totaam commented Aug 9, 2013

2013-08-09 03:26:04: antoine changed owner from antoine to SmO

@totaam
Copy link
Collaborator Author

totaam commented Aug 9, 2013

2013-08-09 03:26:04: antoine commented

Untested fix in r4113 - does this work for you?

@totaam
Copy link
Collaborator Author

totaam commented Aug 9, 2013

2013-08-09 08:22:49: smo commented

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)

@totaam
Copy link
Collaborator Author

totaam commented Aug 9, 2013

2013-08-09 08:46:19: totaam changed owner from SmO to osx

@totaam
Copy link
Collaborator Author

totaam commented Aug 9, 2013

2013-08-09 08:46:19: totaam commented

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

[[BR]]

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?

@totaam
Copy link
Collaborator Author

totaam commented Aug 9, 2013

2013-08-09 09:04:11: smo commented

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)

@totaam
Copy link
Collaborator Author

totaam commented Aug 9, 2013

2013-08-09 09:08:04: totaam commented

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)

@totaam
Copy link
Collaborator Author

totaam commented Aug 9, 2013

2013-08-09 09:09:57: smo commented

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.

@totaam
Copy link
Collaborator Author

totaam commented Aug 9, 2013

2013-08-09 09:10:37: totaam commented

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

@totaam
Copy link
Collaborator Author

totaam commented Aug 9, 2013

2013-08-09 09:21:05: smo uploaded file xpra_debug1.log (85.4 KiB)

OSX Sound Debug01

@totaam
Copy link
Collaborator Author

totaam commented Aug 9, 2013

2013-08-09 09:21:51: smo commented

I've attached the output with XPRA_SOUND_DEBUG

Let me know if you want the full debug output.

@totaam
Copy link
Collaborator Author

totaam commented Aug 9, 2013

2013-08-09 14:41:13: totaam changed owner from osx to smo

@totaam
Copy link
Collaborator Author

totaam commented Aug 9, 2013

2013-08-09 14:41:13: totaam commented

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.

@totaam
Copy link
Collaborator Author

totaam commented Aug 10, 2013

2013-08-10 03:12:59: smo commented

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

@totaam
Copy link
Collaborator Author

totaam commented Aug 10, 2013

2013-08-10 03:44:59: totaam commented

When using the UI if I spend more than 2 seconds in it the sound stops
[[BR]]
That's odd.
[[BR]]

However if I stop the media and start it again I can often get sound once again.
[[BR]]
Does this cause an overrun before it restarts?
[[BR]]

I seem to be missing all logging to the console as well with r4142
[[BR]]
"all logging" ?

@totaam
Copy link
Collaborator Author

totaam commented Aug 10, 2013

2013-08-10 05:02:57: smo commented

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

@totaam
Copy link
Collaborator Author

totaam commented Aug 10, 2013

2013-08-10 05:05:13: smo commented

Attached debug log with XPRA_SOUND_DEBUG for comment:12

@totaam
Copy link
Collaborator Author

totaam commented Aug 10, 2013

2013-08-10 05:05:25: smo uploaded file xpra_debug2.txt (76.8 KiB)

@totaam
Copy link
Collaborator Author

totaam commented Aug 10, 2013

2013-08-10 06:12:37: totaam commented

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?
[[BR]]

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.

@totaam
Copy link
Collaborator Author

totaam commented Aug 10, 2013

2013-08-10 06:13:14: totaam uploaded file client-logs-process-packet.patch (0.9 KiB)

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

@totaam
Copy link
Collaborator Author

totaam commented Aug 12, 2013

2013-08-12 19:25:05: smo uploaded file xpra_debug3.txt (152.7 KiB)

@totaam
Copy link
Collaborator Author

totaam commented Aug 12, 2013

2013-08-12 19:28:04: smo commented

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.

@totaam
Copy link
Collaborator Author

totaam commented Aug 13, 2013

2013-08-13 02:10:22: antoine commented

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

@totaam
Copy link
Collaborator Author

totaam commented Aug 13, 2013

2013-08-13 02:24:08: smo commented

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.

@totaam
Copy link
Collaborator Author

totaam commented Aug 13, 2013

2013-08-13 05:22:17: totaam commented

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)

@totaam
Copy link
Collaborator Author

totaam commented Aug 22, 2013

2013-08-22 08:03:22: antoine changed status from new to closed

@totaam
Copy link
Collaborator Author

totaam commented Aug 22, 2013

2013-08-22 08:03:22: antoine changed resolution from ** to fixed

@totaam
Copy link
Collaborator Author

totaam commented Aug 22, 2013

2013-08-22 08:03:22: antoine commented

I assume this got tested ok

@totaam totaam closed this as completed Aug 22, 2013
@totaam totaam added the audio label Jan 22, 2021
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