STR: 1. On OSX, insert Logitech C930e camera in USB port (possibly other Logitech?) 1. In debug nightly, open https://jsfiddle.net/ja800a6q/ 3. Pick and share Logitech C930e microphone. Expected result: audio feedback Actual result: crash in debug build: > ++DOMWINDOW == 31 (0x1883ae800) [pid = 96014] [serial = 36] [outer = 0x1905a8000] > [Parent 96014] WARNING: Cannot query channel count on a AudioSegment with no chunks.: '!mChunks.IsEmpty()', file /Users/Jan/moz/mozilla-central/dom/media/AudioSegment.h, line 369 > [Parent 96014] WARNING: No audio tracks, but full-duplex audio is enabled!!!!!: file /Users/Jan/moz/mozilla-central/dom/media/MediaStreamGraph.cpp, line 457 > --DOMWINDOW == 30 (0x121d9c800) [pid = 96014] [serial = 18] [outer = 0x0] [url = about:srcdoc] > --DOMWINDOW == 29 (0x122697800) [pid = 96014] [serial = 19] [outer = 0x0] [url = about:blank] > --DOMWINDOW == 28 (0x19294f400) [pid = 96014] [serial = 34] [outer = 0x0] [url = about:blank] > --DOMWINDOW == 27 (0x131056c00) [pid = 96014] [serial = 25] [outer = 0x0] [url = about:blank] > --DOMWINDOW == 26 (0x18431fc00) [pid = 96014] [serial = 29] [outer = 0x0] [url = about:home] > --DOMWINDOW == 25 (0x131385000) [pid = 96014] [serial = 28] [outer = 0x0] [url = about:blank] > --DOMWINDOW == 24 (0x190d0f000) [pid = 96014] [serial = 32] [outer = 0x0] [url = http://fiddle.jshell.net/jib1/202nqk5r/show/] > JavaScript error: resource://gre/modules/LoginManagerParent.jsm, line 78: TypeError: this._recipeManager is null > ++DOMWINDOW == 25 (0x1237c0400) [pid = 96014] [serial = 37] [outer = 0x1905a8000] > [Parent 96014] WARNING: Audio Buffer is not full by the end of the callback.: 'Available() == 0 || mSampleWriteOffset == 0', file /Users/Jan/moz/mozilla-central/dom/media/AudioBufferUtils.h, line 87 > [Parent 96014] WARNING: Cannot query channel count on a AudioSegment with no chunks.: '!mChunks.IsEmpty()', file /Users/Jan/moz/mozilla-central/dom/media/AudioSegment.h, line 369 > Assertion failed: (out_len == output_frame_count), function output, file /Users/Jan/moz/mozilla-central/media/libcubeb/src/cubeb_resampler_internal.h, line 236. > > com.apple.audio.IOThread.client (142)#0 0x00007fff96fa50ae in __pthread_kill () > #1 0x00000001000ee43d in pthread_kill () > #2 0x00007fff8aca537b in abort () > #3 0x00007fff8ac6c9c4 in __assert_rtn () > #4 0x0000000107c12c20 in cubeb_resampler_speex_one_way<float>::output(unsigned long) at /Users/Jan/moz/mozilla-central/media/libcubeb/src/cubeb_resampler_internal.h:236 > #5 0x0000000107c12151 in cubeb_resampler_speex<float, cubeb_resampler_speex_one_way<float>, delay_line<float> >::fill_internal_duplex(float*, long*, float*, long) at /Users/Jan/moz/mozilla-central/media/libcubeb/src/cubeb_resampler.cpp:200 > #6 0x0000000107c1259b in cubeb_resampler_speex<float, cubeb_resampler_speex_one_way<float>, delay_line<float> >::fill(void*, long*, void*, long) at /Users/Jan/moz/mozilla-central/media/libcubeb/src/cubeb_resampler.cpp:105 > #7 0x0000000107c0f3b4 in cubeb_resampler_fill at /Users/Jan/moz/mozilla-central/media/libcubeb/src/cubeb_resampler.cpp:267 > #8 0x0000000107c0d44c in audiounit_output_callback at /Users/Jan/moz/mozilla-central/media/libcubeb/src/cubeb_audiounit.c:314 > #9 0x000000019aa9beeb in AUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int) () > #10 0x000000019aa9a0b4 in AUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&) () > #11 0x000000019aa98a9e in AUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&) () > #12 0x000000019aa9f65e in AUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*) () > #13 0x00007fff93127ea3 in HALC_ProxyIOContext::IOWorkLoop() () > #14 0x00007fff931273ee in HALC_ProxyIOContext::IOThreadEntry(void*) () > #15 0x00007fff931272c3 in HALB_IOThread::Entry(void*) () > #16 0x00000001000eb815 in _pthread_body () > #17 0x00000001000eb792 in _pthread_start () > #18 0x00000001000e8fad in thread_start () (lldb) p output_frame_count (size_t) $0 = 512 (lldb) p out_len (uint32_t) $1 = 471 (lldb) p in_len (uint32_t) $2 = 512 (lldb) p *this (cubeb_resampler_speex_one_way<float>) $3 = { processor = (channels = 1) speex_resampler = 0x000000011eeab600 resampling_ratio = 1.08843541 resampling_in_buffer = { data_ = 0x0000000123976000 capacity_ = 512 length_ = 512 } resampling_out_buffer = { data_ = 0x0000000123977000 capacity_ = 512 length_ = 0 } additional_latency = 0 leftover_samples = 0 } (lldb) The out_len values is always 471 when this happens. Happens in both e10s and non-e10s. The crash seems to always happen now, though initially it seemed to happen only when I unplugged the device while it was running. At that time I got the same assert but with a different stack: > Assertion failed: (out_len == output_frame_count), function output, file /Users/Jan/moz/mozilla-central/media/libcubeb/src/cubeb_resampler_internal.h, line 236. > [Parent 95947] WARNING: short timeout didn't get an id (ipc/rcv) timed out 10004003 > : file /Users/Jan/moz/mozilla-central/ipc/glue/SharedMemoryBasic_mach.mm, line 622 > Assertion failure: false (Receiver message short time out), at /Users/Jan/moz/mozilla-central/ipc/glue/SharedMemoryBasic_mach.mm:623 > #01: mozilla::ipc::SharedMemoryBasic::ShareToProcess(int, unsigned int*)[/Users/Jan/moz/mozilla-central/obj-x86_64-apple-darwin12.2.1-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0xbf1998] > #02: mozilla::ipc::SharedMemoryCommon<unsigned int>::ShareHandle(int, IPC::Message*)[/Users/Jan/moz/mozilla-central/obj-x86_64-apple-darwin12.2.1-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0xbf2a95] > #03: mozilla::ipc::Shmem::ShareTo(mozilla::ipc::Shmem::IHadBetterBeIPDLCodeCallingThis_OtherwiseIAmADoodyhead, int, int)[/Users/Jan/moz/mozilla-central/obj-x86_64-apple-darwin12.2.1-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0xbce56f] > #04: mozilla::ipc::PBackgroundParent::CreateSharedMemory(unsigned long, mozilla::ipc::SharedMemory::SharedMemoryType, bool, int*)[/Users/Jan/moz/mozilla-central/obj-x86_64-apple-darwin12.2.1-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x10d4709] > #05: non-virtual thunk to mozilla::ipc::PBackgroundParent::CreateSharedMemory(unsigned long, mozilla::ipc::SharedMemory::SharedMemoryType, bool, int*)[/Users/Jan/moz/mozilla-central/obj-x86_64-apple-darwin12.2.1-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x10d484c] > #06: mozilla::camera::PCamerasParent::CreateSharedMemory(unsigned long, mozilla::ipc::SharedMemory::SharedMemoryType, bool, int*)[/Users/Jan/moz/mozilla-central/obj-x86_64-apple-darwin12.2.1-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x11f2bb4] > #07: mozilla::camera::PCamerasParent::AllocShmem(unsigned long, mozilla::ipc::SharedMemory::SharedMemoryType, mozilla::ipc::Shmem*)[/Users/Jan/moz/mozilla-central/obj-x86_64-apple-darwin12.2.1-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x11f4ca3] > #08: mozilla::ShmemBuffer mozilla::ShmemPool::Get<mozilla::camera::CamerasParent>(mozilla::camera::CamerasParent*, unsigned long)[/Users/Jan/moz/mozilla-central/obj-x86_64-apple-darwin12.2.1-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x3cde3e6] > #09: mozilla::camera::CamerasParent::DeliverFrameOverIPC(mozilla::camera::CaptureEngine, int, mozilla::ShmemBuffer, unsigned char*, unsigned long, unsigned int, long long, long long)[/Users/Jan/moz/mozilla-central/obj-x86_64-apple-darwin12.2.1-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x3cccbf6] > #10: mozilla::camera::DeliverFrameRunnable::Run()[/Users/Jan/moz/mozilla-central/obj-x86_64-apple-darwin12.2.1-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x3cf24ec] > #11: nsThread::ProcessNextEvent(bool, bool*)[/Users/Jan/moz/mozilla-central/obj-x86_64-apple-darwin12.2.1-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x1beb3f] > #12: NS_ProcessNextEvent(nsIThread*, bool)[/Users/Jan/moz/mozilla-central/obj-x86_64-apple-darwin12.2.1-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x24a2d7] > #13: mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*)[/Users/Jan/moz/mozilla-central/obj-x86_64-apple-darwin12.2.1-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0xbcae5b] > #14: MessageLoop::RunInternal()[/Users/Jan/moz/mozilla-central/obj-x86_64-apple-darwin12.2.1-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0xb01625] > #15: MessageLoop::RunHandler()[/Users/Jan/moz/mozilla-central/obj-x86_64-apple-darwin12.2.1-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0xb01585] > #16: MessageLoop::Run()[/Users/Jan/moz/mozilla-central/obj-x86_64-apple-darwin12.2.1-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0xb0152d] > #17: nsThread::ThreadFunc(void*)[/Users/Jan/moz/mozilla-central/obj-x86_64-apple-darwin12.2.1-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x1bc754] > #18: _pt_root[/Users/Jan/moz/mozilla-central/obj-x86_64-apple-darwin12.2.1-debug/dist/NightlyDebug.app/Contents/MacOS/libnss3.dylib +0x38759f] > #19: _pthread_body[/usr/lib/system/libsystem_pthread.dylib +0x39b1] > #20: _pthread_body[/usr/lib/system/libsystem_pthread.dylib +0x392e]

Jan-Ivar -- Can you check if this is still happening? If so, can you coordinate with achronop and retest with the latest OSX full duplex patches (which are in the process of landing)?

My Logitech C930e broke a bit ago, so I haven't been able to re-test this. I just re-ordered it so I'll be able to test this again tomorrow.

OK, I've verified that this still happens with the full duplex patches (on inbound today). It only happens with the Logitech C930e. OSX says it has a sample rate of 48000 (the other options being 16000, 24000 and 32000, no 44100): Assertion failed: (out_len == output_frame_count), function output, file /Users/Jan/moz/mozilla-inbound/media/libcubeb/src/cubeb_resampler_internal.h, line 236. Process 32997 stopped * thread #99: tid = 0x19025d, 0x00007fff9070a0ae libsystem_kernel.dylib`__pthread_kill + 10, name = 'com.apple.audio.IOThread.client', stop reason = signal SIGABRT frame #0: 0x00007fff9070a0ae libsystem_kernel.dylib`__pthread_kill + 10 libsystem_kernel.dylib`__pthread_kill + 10: -> 0x7fff9070a0ae: jae 0x7fff9070a0b8 ; __pthread_kill + 20 0x7fff9070a0b0: movq %rax, %rdi 0x7fff9070a0b3: jmp 0x7fff907053ef ; cerror_nocancel 0x7fff9070a0b8: retq (lldb) bt * thread #99: tid = 0x19025d, 0x00007fff9070a0ae libsystem_kernel.dylib`__pthread_kill + 10, name = 'com.apple.audio.IOThread.client', stop reason = signal SIGABRT > frame #0: 0x00007fff9070a0ae libsystem_kernel.dylib`__pthread_kill + 10 > frame #1: 0x00007fff97753500 libsystem_pthread.dylib`pthread_kill + 90 > frame #2: 0x00007fff8440a37b libsystem_c.dylib`abort + 129 > frame #3: 0x00007fff843d19c4 libsystem_c.dylib`__assert_rtn + 321 > * frame #4: 0x0000000108a13bd3 XUL`cubeb_resampler_speex_one_way<float>::output(this=0x00000001328d1460, output_frame_count=256) + 307 at cubeb_resampler_internal.h:236 > frame #5: 0x0000000108a142b5 XUL`cubeb_resampler_speex<float, cubeb_resampler_speex_one_way<float>, delay_line<float> >::fill_internal_duplex(this=0x00000001900a9e40, in_buffer=0x0000000132893000, input_frames_count=0x0000700003a42a58, out_buffer=0x000000018ddbf000, output_frames_needed=256) + 213 at cubeb_resampler.cpp:213 > frame #6: 0x0000000108a14722 XUL`cubeb_resampler_speex<float, cubeb_resampler_speex_one_way<float>, delay_line<float> >::fill(this=0x00000001900a9e40, input_buffer=0x0000000132893000, input_frames_count=0x0000700003a42a58, output_buffer=0x000000018ddbf000, output_frames_needed=256) + 146 at cubeb_resampler.cpp:109 > frame #7: 0x0000000108a0e9c4 XUL`cubeb_resampler_fill(resampler=0x00000001900a9e40, input_buffer=0x0000000132893000, input_frames_count=0x0000700003a42a58, output_buffer=0x000000018ddbf000, output_frames_needed=256) + 84 at cubeb_resampler.cpp:284 > frame #8: 0x0000000108a0c04c XUL`audiounit_output_callback(user_ptr=0x000000011f3ac160, flags=0x0000700003a42c78, tstamp=0x0000700003a42c80, bus=0, output_frames=256, outBufferList=0x000000018eff7220) + 828 at cubeb_audiounit.cpp:397 > frame #9: 0x0000000198107eeb CoreAudio`AUConverterBase::RenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int) + 709 > frame #10: 0x00000001981060b4 CoreAudio`AUBase::DoRenderBus(unsigned int&, AudioTimeStamp const&, unsigned int, AUOutputElement*, unsigned int, AudioBufferList&) + 154 > frame #11: 0x0000000198104a9e CoreAudio`AUBase::DoRender(unsigned int&, AudioTimeStamp const&, unsigned int, unsigned int, AudioBufferList&) + 504 > frame #12: 0x000000019810b65e CoreAudio`AUHAL::AUIOProc(unsigned int, AudioTimeStamp const*, AudioBufferList const*, AudioTimeStamp const*, AudioBufferList*, AudioTimeStamp const*, void*) + 1778 > frame #13: 0x00007fff8c88cea3 CoreAudio`HALC_ProxyIOContext::IOWorkLoop() + 2535 > frame #14: 0x00007fff8c88c3ee CoreAudio`HALC_ProxyIOContext::IOThreadEntry(void*) + 88 > frame #15: 0x00007fff8c88c2c3 CoreAudio`HALB_IOThread::Entry(void*) + 75 > frame #16: 0x00007fff977509b1 libsystem_pthread.dylib`_pthread_body + 131 > frame #17: 0x00007fff9775092e libsystem_pthread.dylib`_pthread_start + 168 > frame #18: 0x00007fff9774e385 libsystem_pthread.dylib`thread_start + 13 (lldb) p *this (cubeb_resampler_speex_one_way<float>) $2 = { processor = (channels = 1) speex_resampler = 0x0000000121fb7a00 resampling_ratio = 1.08843541 resampling_in_buffer = { data_ = 0x000000018ddca000 capacity_ = 512 length_ = 263 } resampling_out_buffer = { data_ = 0x0000000131513000 capacity_ = 256 length_ = 0 } additional_latency = 0 leftover_samples = 0 } (lldb) Note that to get this, I first had to comment out this line: https://dxr.mozilla.org/mozilla-central/rev/2ea3d51ba1bb9f5c3b6921c43ea63f70b4fdf5d2/dom/media/GraphDriver.cpp#1057 otherwise I hit a new assert: Assertion failed: (r == 0 && "Deadlock"), function enter, file /Users/Jan/moz/mozilla-inbound/media/libcubeb/src/cubeb_utils_unix.h, line 58.

Again with logging turned on: [Parent 42240] WARNING: NS_ENSURE_SUCCESS(rv, false) failed with result 0x80004002: file /Users/Jan/moz/mozilla-inbound/dom/base/nsDocument.cpp, line 5989 ]: [Parent 42240] WARNING: Cannot query channel count on a AudioSegment with no chunks.: '!mChunks.IsEmpty()', file /Users/Jan/moz/mozilla-inbound/dom/media/AudioSegment.h, line 369 Output buffer frame count 256.(line: 1285) Output audiounit init successfully.(line: 1312) Cubeb stream (0x102151940) init successful.(line: 1413) Cubeb stream (0x102151940) started successfully.(line: 1470) - output(0x102151940): buffers 1, size 2048, channels 2, frames 256.(line: 350) Cubeb stream (0x102151940) stopped successfully.(line: 1492) Output buffer frame count 256.(line: 1285) Output audiounit init successfully.(line: 1312) Cubeb stream (0x102151940) init successful.(line: 1413) Cubeb stream (0x102151940) started successfully.(line: 1470) - output(0x102151940): buffers 1, size 2048, channels 2, frames 256.(line: 350) - output(0x102151940): buffers 1, size 2048, channels 2, frames 256.(line: 350) - output(0x102151940): buffers 1, size 2048, channels 2, frames 256.(line: 350) Cubeb stream (0x102151940) stopped successfully.(line: 1492) Input buffer frame count 256.(line: 1174) Input audiounit init successfully.(line: 1243) Output buffer frame count 256.(line: 1285) Output audiounit init successfully.(line: 1312) Cubeb stream (0x102151940) init successful.(line: 1413) Cubeb stream (0x102151940) started successfully.(line: 1470) - output(0x102151940): buffers 1, size 2048, channels 2, frames 256.(line: 350) Output callback came first send silent.(line: 381) - output(0x102151940): buffers 1, size 2048, channels 2, frames 256.(line: 350) Output callback came first send silent.(line: 381) - output(0x102151940): buffers 1, size 2048, channels 2, frames 256.(line: 350) Output callback came first send silent.(line: 381) - output(0x102151940): buffers 1, size 2048, channels 2, frames 256.(line: 350) Output callback came first send silent.(line: 381) - output(0x102151940): buffers 1, size 2048, channels 2, frames 256.(line: 350) Output callback came first send silent.(line: 381) - output(0x102151940): buffers 1, size 2048, channels 2, frames 256.(line: 350) Output callback came first send silent.(line: 381) - output(0x102151940): buffers 1, size 2048, channels 2, frames 256.(line: 350) Output callback came first send silent.(line: 381) - output(0x102151940): buffers 1, size 2048, channels 2, frames 256.(line: 350) Output callback came first send silent.(line: 381) - output(0x102151940): buffers 1, size 2048, channels 2, frames 256.(line: 350) Output callback came first send silent.(line: 381) - output(0x102151940): buffers 1, size 2048, channels 2, frames 256.(line: 350) Output callback came first send silent.(line: 381) - output(0x102151940): buffers 1, size 2048, channels 2, frames 256.(line: 350) Output callback came first send silent.(line: 381) - output(0x102151940): buffers 1, size 2048, channels 2, frames 256.(line: 350) Output callback came first send silent.(line: 381) Assertion failed: (out_len == output_frame_count), function output, file /Users/Jan/moz/mozilla-inbound/media/libcubeb/src/cubeb_resampler_internal.h, line 236. Process 42240 stopped * thread #95: tid = 0x19459a, 0x00007fff9070a0ae libsystem_kernel.dylib`__pthread_kill + 10, name = 'com.apple.audio.IOThread.client', stop reason = signal SIGABRT frame #0: 0x00007fff9070a0ae libsystem_kernel.dylib`__pthread_kill + 10 libsystem_kernel.dylib`__pthread_kill + 10: -> 0x7fff9070a0ae: jae 0x7fff9070a0b8 ; __pthread_kill + 20 0x7fff9070a0b0: movq %rax, %rdi 0x7fff9070a0b3: jmp 0x7fff907053ef ; cerror_nocancel 0x7fff9070a0b8: retq (lldb)

(In reply to Jan-Ivar Bruaroey [:jib] from comment #3) > Note that to get this, I first had to comment out this line: > https://dxr.mozilla.org/mozilla-central/rev/ > 2ea3d51ba1bb9f5c3b6921c43ea63f70b4fdf5d2/dom/media/GraphDriver.cpp#1057 > > otherwise I hit a new assert: Assertion failed: (r == 0 && "Deadlock"), > function enter, file > /Users/Jan/moz/mozilla-inbound/media/libcubeb/src/cubeb_utils_unix.h, line > 58. I've filed bug 1290625 for this new assert, as it happens with all mics for me.

From IRC discussion (http://logs.glob.uno/?c=mozilla%23media&s=29+Jul+2016&e=31+Jul+2016#c276272) the scenario is: Input Logitech 930e sample rate 48000 Output default internal output sample rate 44100 User rate: 44100 (preferred rate if the output) Latency: 256 (the clamped min latency on OSX) Resampler apply on the input to downscale 48000 -> 44100

Input thread delay a lot to start, output has already 12 iteration by then and due to that the resampler consumes all the initial silence of the input buffer. I managed to repro the assert on my cubeb stand alone simulator by delay the start of the input the same amount of time (60 ms on my laptop). This is easily solved by adding more initial silence in the input buffer. I will upload a WIP patch to verify the theory using the actual device.

Add more initial silence in input buffer. WIP patch to verify my theory no ready for landing.

Jan-Ivar can you please try to repro with the WIP patch on? If you see more problems logs will help.

(In reply to Alex Chronopoulos [:achronop] from comment #9) > Jan-Ivar can you please try to repro with the WIP patch on? If you see more > problems logs will help. Thanks, Jan-Ivar

Thank Maire, yes please always ni? me so I don't drop the ball. I still see the assert even with this patch: Assertion failed: (out_len == output_frame_count), function output, file /Users/Jan/moz/mozilla-central/media/libcubeb/src/cubeb_resampler_internal.h, line 236. output_frame_count 256 in_len 270 out_len 248

Please let me know if you need more info.

I guess the problem is that the even increased silence is not enough. In previous patch I set twice more silent. In this patch I multiply it in a factor of 5 (arbitrary number) just to verify or reject my theory. In addition I activate the cubeb logs. If you can test again and include the logs would help. Please include the logs even in case of success, in order to estimate the time from the number of iteration. Thanks a sorry of the inconvenience.

Still happens. Logs attached.

This is the patch that will be submitted for review. Since it must go through cubeb repo I upload the gecko version here in case you want to use the camera in the mean time.

Another workaround is to set c930 as the default input device. For some reason when it is the default, input and output threads start simultaneously and the problem does not exist (at least on my system).

Landed as part of Bug 1315928