After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 764905 - rtspsrc stops playback after a while
rtspsrc stops playback after a while
Status: RESOLVED INCOMPLETE
Product: GStreamer
Classification: Platform
Component: gstreamer (core)
1.8.0
Other Mac OS
: Normal normal
: git master
Assigned To: GStreamer Maintainers
GStreamer Maintainers
Depends on:
Blocks:
 
 
Reported: 2016-04-11 16:12 UTC by Marcin Lewandowski
Modified: 2016-10-31 16:00 UTC
See Also:
GNOME target: ---
GNOME version: ---


Attachments
Network dump (780.57 KB, application/x-gzip)
2016-04-12 16:24 UTC, Marcin Lewandowski
Details
Network dump (1.38 MB, application/x-gzip)
2016-04-12 16:33 UTC, Marcin Lewandowski
Details

Description Marcin Lewandowski 2016-04-11 16:12:47 UTC
I encounter odd behaviour with rtspsrc.

I have Gst-backed RTSP server that encodes opus audio stream and rtspsrc on the other side that tries to play it back.

Generally speaking it works fine but it just stops playback after some time (5-10 min) with no error, warning, message etc. (I am logging everything that appears on the pipeline's bus).

When I restart the receiver pipeline it just starts to work again so I assume that problem is on the receiver side.

If sometimes happen that two identical receivers are connected to the same mount of the same RTSP server and while one is silent, another plays back, so I assume that RTSP server is sending data correctky.


The receiver's pipeline is

rtspsrc location=rtsp://.... user-agent=... drop-on-latency=true latency=500 tls-database=... protocols=... username=... password=... ! decodebin ! audioconvert ! audioresample ! queue2 ! openslessink

(protocols are  0x00000001 | 0x00000002 | 0x00000004 | 0x00000010 | 0x00000020)

I am using 1.8.0 on both sides.

I am not sure if this is related but during playback on Android I ocassionally get

04-11 16:38:41.989 21543 21629 W GStreamer+audiobasesink: 0:04:35.920673280 0xb8e045b0 gstaudiobasesink.c:1484:gst_audio_base_sink_skew_slaving:<audio_interface_playback> correct clock skew +0:00:00.020063566 > +0:00:00.020000000
04-11 16:38:42.006 21543 21629 W GStreamer+audiobasesink: 0:04:35.938068176 0xb8e045b0 gstaudiobasesink.c:1512:gst_audio_base_sink_skew_slaving:<audio_interface_playback> correct clock skew -0:00:00.020290466 < -+0:00:00.020000000


I have managed to reproduce the issue on Mac OS X. 

I've used gst-launch -m -vv to run identical pipeline and the only output was

/GstPipeline:pipeline0/GstRTSPSrc:rtspsrc0/GstRtpBin:manager/GstRtpSession:rtpsession0: stats = "application/x-rtp-session-stats\,\ rtx-drop-count\=\(uint\)0\,\ sent-nack-count\=\(uint\)0\,\ recv-nack-count\=\(uint\)0\,\ source-stats\=\(GValueArray\)NULL\,\ rtx-count\=\(uint\)0\;"

(repeated many times)

and it kept appearing even when audio was not playing.

I have run it with GST_DEBUG=*:4,rtspsrc:5,opus:5 and there were no messages prior to hanging.

I've added level element to the pipeline to see whether it emits anything when audio stops playing. As I anticipated, level stops emitting messages when audio stops playing.
Comment 1 Sebastian Dröge (slomo) 2016-04-12 07:08:39 UTC
Can you get a full debug log with level 6? Also check with gdb what all threads are doing while nothing is happening anymore.
Comment 2 Marcin Lewandowski 2016-04-12 10:25:22 UTC
(lldb) attach -p 54598
Process 54598 stopped
* thread #1: tid = 0x24bd3c, 0x00007fff91cf7386 libsystem_kernel.dylib`mach_msg_trap + 10, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
    frame #0: 0x00007fff91cf7386 libsystem_kernel.dylib`mach_msg_trap + 10
libsystem_kernel.dylib`mach_msg_trap:
->  0x7fff91cf7386 <+10>: retq
    0x7fff91cf7387 <+11>: nop

libsystem_kernel.dylib`mach_msg_overwrite_trap:
    0x7fff91cf7388 <+0>:  movq   %rcx, %r10
    0x7fff91cf738b <+3>:  movl   $0x1000020, %eax

Executable module set to "/Library/Frameworks/GStreamer.framework/Versions/1.0/Commands/gst-launch-1.0".
Architecture set to: x86_64-apple-macosx.
(lldb) bt all
* thread #1: tid = 0x24bd3c, 0x00007fff91cf7386 libsystem_kernel.dylib`mach_msg_trap + 10, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0: 0x00007fff91cf7386 libsystem_kernel.dylib`mach_msg_trap + 10
    frame #1: 0x00007fff91cf67c7 libsystem_kernel.dylib`mach_msg + 55
    frame #2: 0x00007fff9bab4624 CoreFoundation`__CFRunLoopServiceMachPort + 212
    frame #3: 0x00007fff9bab3aec CoreFoundation`__CFRunLoopRun + 1356
    frame #4: 0x00007fff9bab3338 CoreFoundation`CFRunLoopRunSpecific + 296
    frame #5: 0x00007fff9e3c0935 HIToolbox`RunCurrentEventLoopInMode + 235
    frame #6: 0x00007fff9e3c076f HIToolbox`ReceiveNextEventCommon + 432
    frame #7: 0x00007fff9e3c05af HIToolbox`_BlockUntilNextEventMatchingListInModeWithFilter + 71
    frame #8: 0x00007fff8fd500ee AppKit`_DPSNextEvent + 1067
    frame #9: 0x00007fff9011c943 AppKit`-[NSApplication _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 454
    frame #10: 0x000000010e00ac23 libglib-2.0.0.dylib`cocoa_poll_func + 179
    frame #11: 0x000000010e00bc9d libglib-2.0.0.dylib`g_main_context_iterate + 333
    frame #12: 0x000000010e00c01f libglib-2.0.0.dylib`g_main_loop_run + 223
    frame #13: 0x000000010ddfc95e libgstreamer-1.0.0.dylib`gst_bus_poll + 286
    frame #14: 0x000000010ddd6004 gst-launch-1.0`event_loop + 3412
    frame #15: 0x000000010ddd4cfa gst-launch-1.0`main + 2010
    frame #16: 0x00007fff987d25ad libdyld.dylib`start + 1
    frame #17: 0x00007fff987d25ad libdyld.dylib`start + 1

  thread #2: tid = 0x24bd4a, 0x00007fff91cfdff6 libsystem_kernel.dylib`kevent_qos + 10, queue = 'com.apple.libdispatch-manager'
    frame #0: 0x00007fff91cfdff6 libsystem_kernel.dylib`kevent_qos + 10
    frame #1: 0x00007fff9a4b7099 libdispatch.dylib`_dispatch_mgr_invoke + 216
    frame #2: 0x00007fff9a4b6d01 libdispatch.dylib`_dispatch_mgr_thread + 52

  thread #3: tid = 0x24bd64, 0x00007fff91cfceb2 libsystem_kernel.dylib`__psynch_cvwait + 10, name = 'queue2-0:src'
    frame #0: 0x00007fff91cfceb2 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff91935150 libsystem_pthread.dylib`_pthread_cond_wait + 767
    frame #2: 0x000000010e05308f libglib-2.0.0.dylib`g_cond_wait + 47
    frame #3: 0x000000010eb87742 libgstcoreelements.so`gst_queue2_loop + 866
    frame #4: 0x000000010de5e5a3 libgstreamer-1.0.0.dylib`gst_task_func + 339
    frame #5: 0x000000010e0343c2 libglib-2.0.0.dylib`g_thread_pool_thread_proxy + 50
    frame #6: 0x000000010e03344a libglib-2.0.0.dylib`g_thread_proxy + 90
    frame #7: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #8: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #9: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13

  thread #4: tid = 0x24bd65, 0x00007fff91cfd176 libsystem_kernel.dylib`__select + 10, name = 'task0'
    frame #0: 0x00007fff91cfd176 libsystem_kernel.dylib`__select + 10
    frame #1: 0x000000010e01a0fa libglib-2.0.0.dylib`g_poll + 410
    frame #2: 0x000000010e5285ea libgio-2.0.0.dylib`g_socket_condition_timed_wait + 362
    frame #3: 0x000000010e5270a7 libgio-2.0.0.dylib`g_socket_receive_with_blocking + 359
    frame #4: 0x000000010e50bfef libgio-2.0.0.dylib`g_input_stream_read + 207
    frame #5: 0x000000010e3f3469 libgstrtsp-1.0.0.dylib`fill_raw_bytes + 89
    frame #6: 0x000000010e3eff84 libgstrtsp-1.0.0.dylib`read_bytes + 292
    frame #7: 0x000000010e3f0728 libgstrtsp-1.0.0.dylib`build_next + 1144
    frame #8: 0x000000010e3f015d libgstrtsp-1.0.0.dylib`gst_rtsp_connection_receive + 173
    frame #9: 0x000000010e3c5503 libgstrtsp.so`gst_rtspsrc_thread + 435
    frame #10: 0x000000010de5e5a3 libgstreamer-1.0.0.dylib`gst_task_func + 339
    frame #11: 0x000000010e0343c2 libglib-2.0.0.dylib`g_thread_pool_thread_proxy + 50
    frame #12: 0x000000010e03344a libglib-2.0.0.dylib`g_thread_proxy + 90
    frame #13: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #14: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #15: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13

  thread #5: tid = 0x24bd66, 0x00007fff91cfd176 libsystem_kernel.dylib`__select + 10, name = 'gmain'
    frame #0: 0x00007fff91cfd176 libsystem_kernel.dylib`__select + 10
    frame #1: 0x000000010e01a0fa libglib-2.0.0.dylib`g_poll + 410
    frame #2: 0x000000010e00bc9d libglib-2.0.0.dylib`g_main_context_iterate + 333
    frame #3: 0x000000010e00bd84 libglib-2.0.0.dylib`g_main_context_iteration + 100
    frame #4: 0x000000010e00d5c6 libglib-2.0.0.dylib`glib_worker_main + 54
    frame #5: 0x000000010e03344a libglib-2.0.0.dylib`g_thread_proxy + 90
    frame #6: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #7: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #8: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13

  thread #6: tid = 0x24bd6c, 0x00007fff91cfd176 libsystem_kernel.dylib`__select + 10, name = 'CocoaSelectThread'
    frame #0: 0x00007fff91cfd176 libsystem_kernel.dylib`__select + 10
    frame #1: 0x000000010e01a0fa libglib-2.0.0.dylib`g_poll + 410
    frame #2: 0x000000010e00dbea libglib-2.0.0.dylib`cocoa_select_thread_func + 122
    frame #3: 0x000000010e03344a libglib-2.0.0.dylib`g_thread_proxy + 90
    frame #4: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #5: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #6: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13

  thread #7: tid = 0x24bd7f, 0x00007fff91cfceb2 libsystem_kernel.dylib`__psynch_cvwait + 10, name = 'rtpjitterbuffer0:src'
    frame #0: 0x00007fff91cfceb2 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff91935150 libsystem_pthread.dylib`_pthread_cond_wait + 767
    frame #2: 0x000000010e05308f libglib-2.0.0.dylib`g_cond_wait + 47
    frame #3: 0x000000011141188a libgstrtpmanager.so`gst_rtp_jitter_buffer_loop + 330
    frame #4: 0x000000010de5e5a3 libgstreamer-1.0.0.dylib`gst_task_func + 339
    frame #5: 0x000000010e0343c2 libglib-2.0.0.dylib`g_thread_pool_thread_proxy + 50
    frame #6: 0x000000010e03344a libglib-2.0.0.dylib`g_thread_proxy + 90
    frame #7: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #8: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #9: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13

  thread #8: tid = 0x24bda8, 0x00007fff91cfce3a libsystem_kernel.dylib`__pselect + 10, name = 'rtpsession-rtcp-thread'
    frame #0: 0x00007fff91cfce3a libsystem_kernel.dylib`__pselect + 10
    frame #1: 0x00007fff91cfa51f libsystem_kernel.dylib`pselect$1050 + 82
    frame #2: 0x000000010de3fe6f libgstreamer-1.0.0.dylib`gst_poll_wait + 1231
    frame #3: 0x000000010de57da6 libgstreamer-1.0.0.dylib`gst_system_clock_id_wait_jitter_unlocked + 774
    frame #4: 0x000000010de04f81 libgstreamer-1.0.0.dylib`gst_clock_id_wait + 97
    frame #5: 0x0000000111434579 libgstrtpmanager.so`rtcp_thread + 409
    frame #6: 0x000000010e03344a libglib-2.0.0.dylib`g_thread_proxy + 90
    frame #7: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #8: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #9: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13

  thread #9: tid = 0x24bda9, 0x00007fff91cfceb2 libsystem_kernel.dylib`__psynch_cvwait + 10, name = 'timer'
    frame #0: 0x00007fff91cfceb2 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff91935150 libsystem_pthread.dylib`_pthread_cond_wait + 767
    frame #2: 0x000000010e05308f libglib-2.0.0.dylib`g_cond_wait + 47
    frame #3: 0x0000000111415ab1 libgstrtpmanager.so`wait_next_timeout + 6385
    frame #4: 0x000000010e03344a libglib-2.0.0.dylib`g_thread_proxy + 90
    frame #5: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #6: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #7: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13

  thread #10: tid = 0x24bdac, 0x00007fff91cf7386 libsystem_kernel.dylib`mach_msg_trap + 10, name = 'com.apple.audio.IOThread.client'
    frame #0: 0x00007fff91cf7386 libsystem_kernel.dylib`mach_msg_trap + 10
    frame #1: 0x00007fff91cf67c7 libsystem_kernel.dylib`mach_msg + 55
    frame #2: 0x00007fff8a6405ee CoreAudio`HALB_MachPort::SendMessageWithReply(unsigned int, unsigned int, unsigned int, unsigned int, mach_msg_header_t*, bool, unsigned int) + 98
    frame #3: 0x00007fff8a64057c CoreAudio`HALB_MachPort::SendSimpleMessageWithSimpleReply(unsigned int, unsigned int, int, int&, bool, unsigned int) + 42
    frame #4: 0x00007fff8a63e939 CoreAudio`HALC_ProxyIOContext::IOWorkLoop() + 1149
    frame #5: 0x00007fff8a63e3ee CoreAudio`HALC_ProxyIOContext::IOThreadEntry(void*) + 88
    frame #6: 0x00007fff8a63e2c3 CoreAudio`HALB_IOThread::Entry(void*) + 75
    frame #7: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #8: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #9: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13

Log is coming soon.
Comment 3 Marcin Lewandowski 2016-04-12 10:58:02 UTC
Here is the link to the full log with GST_DEBUG=*:6:

https://pub.radiokit.org/gstbug764905/log6.txt.gz

I have also noticed that just before stopping the audio becomes distorted for a few seconds, and then it disappears but regular glitches (such as chk chk chk for a few seconds) are heard, and then silence.

I will try to record this.

More info about test case:

I am using Opus for transmitting audio with PLC and FEC. On Android I use GStreamer 1.8.0 built via cerber, except bumping Opus to the most recent version. On Mac OS X I use plain GStreamer 1.8.0 from official builds so Opus is slightly older and the same happens.

On the server side I use GStreamer 1.8.0 (built manually) but underlying libraries come from plain Ubuntu 14.04 so they may be slightly outdated.
Comment 4 Sebastian Dröge (slomo) 2016-04-12 12:05:14 UTC
That could mean that the audio sink ringbuffer underruns and never fills up again, continuing to output silence because the decoded output doesn't catch up.

(didn't look at the log yet)
Comment 5 Marcin Lewandowski 2016-04-12 14:29:33 UTC
I have tried to revert to 1.6.3 on the client side and it plays silence all the time, despite RTSP being connected.

Can audiorate help with potential issues with buffer underrun so it will always output perfect stream to the sink?
Comment 6 Sebastian Dröge (slomo) 2016-04-12 14:33:40 UTC
If my guess about the problem is correct, no. That should be checked from the logs first though before trying anything else. Check if the ringbuffer runs empty and stays behind.
Comment 7 Marcin Lewandowski 2016-04-12 14:35:40 UTC
Antother stack trace:

(lldb) attach -p 57147
Process 57147 stopped
* thread #1: tid = 0x25d1dd, 0x00007fff91cf7386 libsystem_kernel.dylib`mach_msg_trap + 10, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
    frame #0: 0x00007fff91cf7386 libsystem_kernel.dylib`mach_msg_trap + 10
libsystem_kernel.dylib`mach_msg_trap:
->  0x7fff91cf7386 <+10>: retq
    0x7fff91cf7387 <+11>: nop

libsystem_kernel.dylib`mach_msg_overwrite_trap:
    0x7fff91cf7388 <+0>:  movq   %rcx, %r10
    0x7fff91cf738b <+3>:  movl   $0x1000020, %eax

Executable module set to "/Library/Frameworks/GStreamer.framework/Versions/1.0/Commands/gst-launch-1.0".
Architecture set to: x86_64-apple-macosx.
(lldb) bt all
* thread #1: tid = 0x25d1dd, 0x00007fff91cf7386 libsystem_kernel.dylib`mach_msg_trap + 10, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0: 0x00007fff91cf7386 libsystem_kernel.dylib`mach_msg_trap + 10
    frame #1: 0x00007fff91cf67c7 libsystem_kernel.dylib`mach_msg + 55
    frame #2: 0x00007fff9bab4624 CoreFoundation`__CFRunLoopServiceMachPort + 212
    frame #3: 0x00007fff9bab3aec CoreFoundation`__CFRunLoopRun + 1356
    frame #4: 0x00007fff9bab3338 CoreFoundation`CFRunLoopRunSpecific + 296
    frame #5: 0x00007fff9e3c0935 HIToolbox`RunCurrentEventLoopInMode + 235
    frame #6: 0x00007fff9e3c076f HIToolbox`ReceiveNextEventCommon + 432
    frame #7: 0x00007fff9e3c05af HIToolbox`_BlockUntilNextEventMatchingListInModeWithFilter + 71
    frame #8: 0x00007fff8fd500ee AppKit`_DPSNextEvent + 1067
    frame #9: 0x00007fff9011c943 AppKit`-[NSApplication _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 454
    frame #10: 0x00000001005fec23 libglib-2.0.0.dylib`cocoa_poll_func + 179
    frame #11: 0x00000001005ffc9d libglib-2.0.0.dylib`g_main_context_iterate + 333
    frame #12: 0x000000010060001f libglib-2.0.0.dylib`g_main_loop_run + 223
    frame #13: 0x00000001003f995e libgstreamer-1.0.0.dylib`gst_bus_poll + 286
    frame #14: 0x00000001003d5004 gst-launch-1.0`event_loop + 3412
    frame #15: 0x00000001003d3cfa gst-launch-1.0`main + 2010
    frame #16: 0x00007fff987d25ad libdyld.dylib`start + 1

  thread #2: tid = 0x25d1e0, 0x00007fff91cfdff6 libsystem_kernel.dylib`kevent_qos + 10, queue = 'com.apple.libdispatch-manager'
    frame #0: 0x00007fff91cfdff6 libsystem_kernel.dylib`kevent_qos + 10
    frame #1: 0x00007fff9a4b7099 libdispatch.dylib`_dispatch_mgr_invoke + 216
    frame #2: 0x00007fff9a4b6d01 libdispatch.dylib`_dispatch_mgr_thread + 52

  thread #3: tid = 0x25d1fb, 0x00007fff91cfceb2 libsystem_kernel.dylib`__psynch_cvwait + 10, name = 'queue2-0:src'
    frame #0: 0x00007fff91cfceb2 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff91935150 libsystem_pthread.dylib`_pthread_cond_wait + 767
    frame #2: 0x000000010064708f libglib-2.0.0.dylib`g_cond_wait + 47
    frame #3: 0x0000000101179742 libgstcoreelements.so`gst_queue2_loop + 866
    frame #4: 0x000000010045b5a3 libgstreamer-1.0.0.dylib`gst_task_func + 339
    frame #5: 0x00000001006283c2 libglib-2.0.0.dylib`g_thread_pool_thread_proxy + 50
    frame #6: 0x000000010062744a libglib-2.0.0.dylib`g_thread_proxy + 90
    frame #7: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #8: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #9: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13

  thread #4: tid = 0x25d1fc, 0x00007fff91cfd176 libsystem_kernel.dylib`__select + 10, name = 'task0'
    frame #0: 0x00007fff91cfd176 libsystem_kernel.dylib`__select + 10
    frame #1: 0x000000010060e0fa libglib-2.0.0.dylib`g_poll + 410
    frame #2: 0x0000000100b1a5ea libgio-2.0.0.dylib`g_socket_condition_timed_wait + 362
    frame #3: 0x0000000100b190a7 libgio-2.0.0.dylib`g_socket_receive_with_blocking + 359
    frame #4: 0x0000000100afdfef libgio-2.0.0.dylib`g_input_stream_read + 207
    frame #5: 0x00000001009e5469 libgstrtsp-1.0.0.dylib`fill_raw_bytes + 89
    frame #6: 0x00000001009e1f84 libgstrtsp-1.0.0.dylib`read_bytes + 292
    frame #7: 0x00000001009e2728 libgstrtsp-1.0.0.dylib`build_next + 1144
    frame #8: 0x00000001009e215d libgstrtsp-1.0.0.dylib`gst_rtsp_connection_receive + 173
    frame #9: 0x00000001009b7aa2 libgstrtsp.so`gst_rtspsrc_thread + 1874
    frame #10: 0x000000010045b5a3 libgstreamer-1.0.0.dylib`gst_task_func + 339
    frame #11: 0x00000001006283c2 libglib-2.0.0.dylib`g_thread_pool_thread_proxy + 50
    frame #12: 0x000000010062744a libglib-2.0.0.dylib`g_thread_proxy + 90
    frame #13: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #14: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #15: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13

  thread #5: tid = 0x25d1fd, 0x00007fff91cfd176 libsystem_kernel.dylib`__select + 10, name = 'gmain'
    frame #0: 0x00007fff91cfd176 libsystem_kernel.dylib`__select + 10
    frame #1: 0x000000010060e0fa libglib-2.0.0.dylib`g_poll + 410
    frame #2: 0x00000001005ffc9d libglib-2.0.0.dylib`g_main_context_iterate + 333
    frame #3: 0x00000001005ffd84 libglib-2.0.0.dylib`g_main_context_iteration + 100
    frame #4: 0x00000001006015c6 libglib-2.0.0.dylib`glib_worker_main + 54
    frame #5: 0x000000010062744a libglib-2.0.0.dylib`g_thread_proxy + 90
    frame #6: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #7: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #8: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13

  thread #6: tid = 0x25d201, 0x00007fff91cfd176 libsystem_kernel.dylib`__select + 10, name = 'CocoaSelectThread'
    frame #0: 0x00007fff91cfd176 libsystem_kernel.dylib`__select + 10
    frame #1: 0x000000010060e0fa libglib-2.0.0.dylib`g_poll + 410
    frame #2: 0x0000000100601bea libglib-2.0.0.dylib`cocoa_select_thread_func + 122
    frame #3: 0x000000010062744a libglib-2.0.0.dylib`g_thread_proxy + 90
    frame #4: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #5: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #6: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13

  thread #7: tid = 0x25d205, 0x00007fff91cfceb2 libsystem_kernel.dylib`__psynch_cvwait + 10, name = 'fakesrc0:src'
    frame #0: 0x00007fff91cfceb2 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff91935150 libsystem_pthread.dylib`_pthread_cond_wait + 767
    frame #2: 0x000000010064708f libglib-2.0.0.dylib`g_cond_wait + 47
    frame #3: 0x000000010045b5d5 libgstreamer-1.0.0.dylib`gst_task_func + 389
    frame #4: 0x00000001006283c2 libglib-2.0.0.dylib`g_thread_pool_thread_proxy + 50
    frame #5: 0x000000010062744a libglib-2.0.0.dylib`g_thread_proxy + 90
    frame #6: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #7: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #8: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13

  thread #8: tid = 0x25d206, 0x00007fff91cfce3a libsystem_kernel.dylib`__pselect + 10, name = 'rtpsession-rtcp-thread'
    frame #0: 0x00007fff91cfce3a libsystem_kernel.dylib`__pselect + 10
    frame #1: 0x00007fff91cfa51f libsystem_kernel.dylib`pselect$1050 + 82
    frame #2: 0x000000010043ce6f libgstreamer-1.0.0.dylib`gst_poll_wait + 1231
    frame #3: 0x0000000100454da6 libgstreamer-1.0.0.dylib`gst_system_clock_id_wait_jitter_unlocked + 774
    frame #4: 0x0000000100401f81 libgstreamer-1.0.0.dylib`gst_clock_id_wait + 97
    frame #5: 0x0000000103a38579 libgstrtpmanager.so`rtcp_thread + 409
    frame #6: 0x000000010062744a libglib-2.0.0.dylib`g_thread_proxy + 90
    frame #7: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #8: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #9: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13

  thread #9: tid = 0x25d207, 0x00007fff91cfd176 libsystem_kernel.dylib`__select + 10, name = 'udpsrc1:src'
    frame #0: 0x00007fff91cfd176 libsystem_kernel.dylib`__select + 10
    frame #1: 0x000000010060e0fa libglib-2.0.0.dylib`g_poll + 410
    frame #2: 0x0000000100b1a5ea libgio-2.0.0.dylib`g_socket_condition_timed_wait + 362
    frame #3: 0x00000001039ef8a6 libgstudp.so`gst_udpsrc_create + 486
    frame #4: 0x0000000100a83cac libgstbase-1.0.0.dylib`gst_base_src_get_range + 380
    frame #5: 0x0000000100a833d4 libgstbase-1.0.0.dylib`gst_base_src_loop + 1684
    frame #6: 0x000000010045b5a3 libgstreamer-1.0.0.dylib`gst_task_func + 339
    frame #7: 0x00000001006283c2 libglib-2.0.0.dylib`g_thread_pool_thread_proxy + 50
    frame #8: 0x000000010062744a libglib-2.0.0.dylib`g_thread_proxy + 90
    frame #9: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #10: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #11: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13

  thread #10: tid = 0x25d208, 0x00007fff91cfd176 libsystem_kernel.dylib`__select + 10, name = 'udpsrc2:src'
    frame #0: 0x00007fff91cfd176 libsystem_kernel.dylib`__select + 10
    frame #1: 0x000000010060e0fa libglib-2.0.0.dylib`g_poll + 410
    frame #2: 0x0000000100b1a5ea libgio-2.0.0.dylib`g_socket_condition_timed_wait + 362
    frame #3: 0x00000001039ef8a6 libgstudp.so`gst_udpsrc_create + 486
    frame #4: 0x0000000100a83cac libgstbase-1.0.0.dylib`gst_base_src_get_range + 380
    frame #5: 0x0000000100a833d4 libgstbase-1.0.0.dylib`gst_base_src_loop + 1684
    frame #6: 0x000000010045b5a3 libgstreamer-1.0.0.dylib`gst_task_func + 339
    frame #7: 0x00000001006283c2 libglib-2.0.0.dylib`g_thread_pool_thread_proxy + 50
    frame #8: 0x000000010062744a libglib-2.0.0.dylib`g_thread_proxy + 90
    frame #9: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #10: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #11: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13

  thread #11: tid = 0x25d209, 0x00007fff91cfceb2 libsystem_kernel.dylib`__psynch_cvwait + 10, name = 'timer'
    frame #0: 0x00007fff91cfceb2 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff91935150 libsystem_pthread.dylib`_pthread_cond_wait + 767
    frame #2: 0x000000010064708f libglib-2.0.0.dylib`g_cond_wait + 47
    frame #3: 0x0000000103a19ab1 libgstrtpmanager.so`wait_next_timeout + 6385
    frame #4: 0x000000010062744a libglib-2.0.0.dylib`g_thread_proxy + 90
    frame #5: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #6: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #7: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13

  thread #12: tid = 0x25d20a, 0x00007fff91cfceb2 libsystem_kernel.dylib`__psynch_cvwait + 10, name = 'rtpjitterbuffer0:src'
    frame #0: 0x00007fff91cfceb2 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff91935150 libsystem_pthread.dylib`_pthread_cond_wait + 767
    frame #2: 0x000000010064708f libglib-2.0.0.dylib`g_cond_wait + 47
    frame #3: 0x0000000103a1588a libgstrtpmanager.so`gst_rtp_jitter_buffer_loop + 330
    frame #4: 0x000000010045b5a3 libgstreamer-1.0.0.dylib`gst_task_func + 339
    frame #5: 0x00000001006283c2 libglib-2.0.0.dylib`g_thread_pool_thread_proxy + 50
    frame #6: 0x000000010062744a libglib-2.0.0.dylib`g_thread_proxy + 90
    frame #7: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #8: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #9: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13

  thread #13: tid = 0x25d220, 0x00007fff91cf7386 libsystem_kernel.dylib`mach_msg_trap + 10, name = 'com.apple.audio.IOThread.client'
    frame #0: 0x00007fff91cf7386 libsystem_kernel.dylib`mach_msg_trap + 10
    frame #1: 0x00007fff91cf67c7 libsystem_kernel.dylib`mach_msg + 55
    frame #2: 0x00007fff8a6405ee CoreAudio`HALB_MachPort::SendMessageWithReply(unsigned int, unsigned int, unsigned int, unsigned int, mach_msg_header_t*, bool, unsigned int) + 98
    frame #3: 0x00007fff8a64057c CoreAudio`HALB_MachPort::SendSimpleMessageWithSimpleReply(unsigned int, unsigned int, int, int&, bool, unsigned int) + 42
    frame #4: 0x00007fff8a63e939 CoreAudio`HALC_ProxyIOContext::IOWorkLoop() + 1149
    frame #5: 0x00007fff8a63e3ee CoreAudio`HALC_ProxyIOContext::IOThreadEntry(void*) + 88
    frame #6: 0x00007fff8a63e2c3 CoreAudio`HALB_IOThread::Entry(void*) + 75
    frame #7: 0x00007fff91934c13 libsystem_pthread.dylib`_pthread_body + 131
    frame #8: 0x00007fff91934b90 libsystem_pthread.dylib`_pthread_start + 168
    frame #9: 0x00007fff91932375 libsystem_pthread.dylib`thread_start + 13
Comment 8 Marcin Lewandowski 2016-04-12 14:48:30 UTC
I have found another pattern. I can't say whether this behaviour is justified or not, but I prefer to share.

When playback stops to occur, messages from level stop being emitted. rtspsession however keeps posting such message once per second:

/GstPipeline:pipeline0/GstRTSPSrc:rtspsrc0/GstRtpBin:manager/GstRtpSession:rtpsession0: stats = "application/x-rtp-session-stats\,\ rtx-drop-count\=\(uint\)0\,\ sent-nack-count\=\(uint\)0\,\ recv-nack-count\=\(uint\)0\,\ source-stats\=\(GValueArray\)NULL\,\ rtx-count\=\(uint\)0\;"


If then I attach debugger and keep it attached for a while (+/- minute or more) once I detach, the EOS is emitted:


Got message #3223 from element "level0" (element): level, endtime=(guint64)300040000000, timestamp=(guint64)300019433997, stream-time=(guint64)300000000000, running-time=(guint64)300019433997, duration=(guint64)40000000, rms=(GValueArray)NULL, peak=(GValueArray)NULL, decay=(GValueArray)NULL;
/GstPipeline:pipeline0/GstRTSPSrc:rtspsrc0/GstRtpBin:manager/GstRtpSession:rtpsession0: stats = "application/x-rtp-session-stats\,\ rtx-drop-count\=\(uint\)0\,\ sent-nack-count\=\(uint\)0\,\ recv-nack-count\=\(uint\)0\,\ source-stats\=\(GValueArray\)NULL\,\ rtx-count\=\(uint\)0\;"
Got message #3221 from element "pipeline0" (eos): no message details
Got EOS from element "pipeline0".
Execution ended after 0:09:10.356259000
Setting pipeline to PAUSED ...
Setting pipeline to READY ...
Setting pipeline to NULL ...
Freeing pipeline ...


If I don't attach the debugger or attach it for very short time the pipeline remains hanged forever.
Comment 9 Marcin Lewandowski 2016-04-12 15:49:10 UTC
This log report may be more meaningful

https://pub.radiokit.org/gstbug764905/log6-2.txt.xz

The last message from level is at line 3420081 so probably interesting stuff happens afterwards.
Comment 10 Marcin Lewandowski 2016-04-12 16:02:38 UTC
As far as I can understand the logs it blocks on select call in udpsrc. This is the last call after which the only messages in the log come from sink's ringbuffer.

0:05:06.860973000 57676 0x7fd54b12a400 LOG                   udpsrc gstudpsrc.c:538:gst_udpsrc_create:<udpsrc1> doing select, timeout -1
0:05:06.868756000 57676 0x7fd54ad33a70 LOG               ringbuffer gstaudioringbuffer.c:1862:gst_audio_ring_buffer_prepare_read:<osxaudioringbuffer0> prepare read from segment 0 (real 30520) @0x7fd54b840c00
0:05:06.868806000 57676 0x7fd54ad33a70 LOG               ringbuffer gstaudioringbuffer.c:1931:gst_audio_ring_buffer_clear:<osxaudioringbuffer0> clear segment 0 @0x7fd54b840c00
0:05:06.868823000 57676 0x7fd54ad33a70 LOG               ringbuffer gstaudioringbuffer.c:1862:gst_audio_ring_buffer_prepare_read:<osxaudioringbuffer0> prepare read from segment 1 (real 30521) @0x7fd54b841380
0:05:06.879379000 57676 0x7fd54ad33a70 LOG               ringbuffer gstaudioringbuffer.c:1862:gst_audio_ring_buffer_prepare_read:<osxaudioringbuffer0> prepare read from segment 1 (real 30521) @0x7fd54b841380
0:05:06.879450000 57676 0x7fd54ad33a70 LOG               ringbuffer gstaudioringbuffer.c:1931:gst_audio_ring_buffer_clear:<osxaudioringbuffer0> clear segment 1 @0x7fd54b841380
0:05:06.879479000 57676 0x7fd54ad33a70 LOG               ringbuffer gstaudioringbuffer.c:1862:gst_audio_ring_buffer_prepare_read:<osxaudioringbuffer0> prepare read from segment 2 (real 30522) @0x7fd54b841b00
0:05:06.890052000 57676 0x7fd54ad33a70 LOG               ringbuffer gstaudioringbuffer.c:1862:gst_audio_ring_buffer_prepare_read:<osxaudioringbuffer0> prepare read from segment 2 (real 30522) @0x7fd54b841b00
0:05:06.890102000 57676 0x7fd54ad33a70 LOG               ringbuffer gstaudioringbuffer.c:1931:gst_audio_ring_buffer_clear:<osxaudioringbuffer0> clear segment 2 @0x7fd54b841b00
0:05:06.890126000 57676 0x7fd54ad33a70 LOG               ringbuffer gstaudioringbuffer.c:1862:gst_audio_ring_buffer_prepare_read:<osxaudioringbuffer0> prepare read from segment 3 (real 30523) @0x7fd54b842280
0:05:06.900691000 57676 0x7fd54ad33a70 LOG               ringbuffer gstaudioringbuffer.c:1862:gst_audio_ring_buffer_prepare_read:<osxaudioringbuffer0> prepare read from segment 3 (real 30523) @0x7fd54b842280
0:05:06.900741000 57676 0x7fd54ad33a70 LOG               ringbuffer gstaudioringbuffer.c:1931:gst_audio_ring_buffer_clear:<osxaudioringbuffer0> clear segment 3 @0x7fd54b842280
0:05:06.900769000 57676 0x7fd54ad33a70 LOG               ringbuffer gstaudioringbuffer.c:1862:gst_audio_ring_buffer_prepare_read:<osxaudioringbuffer0> prepare read from segment 4 (real 30524) @0x7fd54b842a00
0:05:06.911386000 57676 0x7fd54ad33a70 LOG               ringbuffer gstaudioringbuffer.c:1862:gst_audio_ring_buffer_prepare_read:<osxaudioringbuffer0> prepare read from segment 4 (real 30524) @0x7fd54b842a00
0:05:06.911534000 57676 0x7fd54ad33a70 LOG               ringbuffer gstaudioringbuffer.c:1931:gst_audio_ring_buffer_clear:<osxaudioringbuffer0> clear segment 4 @0x7fd54b842a00
0:05:06.911590000 57676 0x7fd54ad33a70 LOG               ringbuffer gstaudioringbuffer.c:1862:gst_audio_ring_buffer_prepare_read:<osxaudioringbuffer0> prepare read from segment 5 (real 30525) @0x7fd54b843180
0:05:06.922052000 57676 0x7fd54ad33a70 LOG               ringbuffer gstaudioringbuffer.c:1862:gst_audio_ring_buffer_prepare_read:<osxaudioringbuffer0> prepare read from segment 5 (real 30525) @0x7fd54b843180
Comment 11 Marcin Lewandowski 2016-04-12 16:24:37 UTC
Created attachment 325812 [details]
Network dump
Comment 12 Marcin Lewandowski 2016-04-12 16:26:23 UTC
I have managed to capture network traffic with wireshark, the log is attached.

It seems that UDP frames stop flowing at some point, and then RTCP ping-pong starts to happen. So there are actually two questions: why RTSP server stops sending UDP and why receiver does not post EOS.
Comment 13 Marcin Lewandowski 2016-04-12 16:33:04 UTC
Created attachment 325813 [details]
Network dump
Comment 14 Marcin Lewandowski 2016-05-25 18:43:54 UTC
I have abandoned RTSP for that purpose so I am unable to contribute any more to this bug. I also provided all information I could. I think NEEDINFO is misleading.