rtsp-server onvif backchannel: examples stopped working between v1.18.5 and v1.20.3

[Christian Wick]

Hi,

I am currently experimenting with the following two examples:
test-onvif-backchannel (server) and test-onvif (client)
https://gitlab.freedesktop.org/gstreamer/gstreamer/-/blob/main/subprojects/gst-rtsp-server/examples/test-onvif-backchannel.c
https://gitlab.freedesktop.org/gstreamer/gstreamer/-/blob/main/subprojects/gst-plugins-good/tests/examples/rtsp/test-onvif.c

Both examples are executed on the same host with same IP address in two 
different VS code terminals.
The only change I applied to the source code in test-onvif.c is that I 
replaced both "xvimagesink" and "pulsesink" with "fakesink".

Unfortunately, the backchannel example stopped working in Ubuntu 22.04 
which uses gstreamer-1.20.3.
However, running the same code on Ubuntu 21.10 with gstreamer-1.18.5 
seems to work without any issue.

Using gstreamer-1.20.3 seems to result in some kind of deadlock in the 
RTSP server.
This is what I see in the server logs:

stream ready at rtsp://127.0.0.1:8554/test
0:00:08.060710610 439984 0x7fb5e40030c0 WARN rtsplatencybin 
rtsp-latency-bin.c:278:gst_rtsp_latency_bin_recalculate_latency:<rtsplatencybin0> 
Sending latency event to stream failed
0:00:08.060786450 439984 0x7fb5e40030c0 WARN rtsplatencybin 
rtsp-latency-bin.c:295:gst_rtsp_latency_bin_message_handler:<rtsplatencybin0> 
Could not recalculate latency
0:00:08.062314850 439984 0x7fb5dc0096a0 FIXME default 
gstutils.c:4025:gst_pad_create_stream_id_internal:<appsrc0:src> Creating 
random stream-id, consider implementing a deterministic way of creating 
a stream-id
0:00:08.062446731 439984 0x7fb5dc009580 FIXME default 
gstutils.c:4025:gst_pad_create_stream_id_internal:<audiotestsrc0:src> 
Creating random stream-id, consider implementing a deterministic way of 
creating a stream-id
0:00:08.063438807 439984 0x7fb5dc0095e0 FIXME default 
gstutils.c:4025:gst_pad_create_stream_id_internal:<videotestsrc0:src> 
Creating random stream-id, consider implementing a deterministic way of 
creating a stream-id
0:00:28.050764749 439984 0x55f93ed4e0c0 WARN rtspmedia 
rtsp-media.c:3594:wait_preroll: failed to preroll pipeline
0:00:28.050826630 439984 0x55f93ed4e0c0 WARN rtspmedia 
rtsp-media.c:3964:gst_rtsp_media_prepare: failed to preroll pipeline
0:00:28.232219329 439984 0x55f93ed4e0c0 ERROR rtspclient 
rtsp-client.c:1087:find_media: client 0x55f93ed5c120: can't prepare media
0:00:28.232635642 439984 0x55f93ed4e0c0 ERROR rtspclient 
rtsp-client.c:3376:handle_describe_request: client 0x55f93ed5c120: no media

With a higher log level (rtsp*:5) I can see:
0:00:05.752331867 440641 0x7fecd400f760 DEBUG             rtspstream 
rtsp-stream.c:5399:rtcp_pad_blocking:<rtpbin0:send_rtcp_src_1> Now 
blocking on buffer
0:00:05.809350504 440641 0x7fecd4039800 DEBUG rtspstream 
rtsp-stream.c:5399:rtcp_pad_blocking:<rtpbin0:send_rtcp_src_0> Now 
blocking on buffer
0:00:23.175552058 440641 0x560c198e84c0 DEBUG rtspmedia 
rtsp-media.c:2818:gst_rtsp_media_get_status: timeout, assuming error status
0:00:23.175615788 440641 0x560c198e84c0 DEBUG rtspmedia 
rtsp-media.c:2824:gst_rtsp_media_get_status: got status 5
0:00:23.175625468 440641 0x560c198e84c0 WARN rtspmedia 
rtsp-media.c:3594:wait_preroll: failed to preroll pipeline

With gstreamer-1.18.5 the relevant part looks different in the server logs:
0:00:07.053729565 189229 0x7f1efc00f5e0 DEBUG             rtspstream 
rtsp-stream.c:5293:pad_blocking:<rtpbin0:send_rtp_src_0> Now blocking
0:00:07.053772775 189229 0x7f1efc00f5e0 DEBUG rtspstream 
rtsp-stream.c:5295:pad_blocking:<GstRTSPStream at 0x7f1f0404e3e0> position: 
1000:00:00.000000000
0:00:07.053879586 189229 0x7f1f040038c0 DEBUG rtspmedia 
rtsp-media.c:3285:default_handle_message:<GstRTSPOnvifMedia at 0x7f1f0404c1f0> 
media received blocking message, n_active_sender_streams = 0, 
is_complete = 0
0:00:08.140100487 189229 0x7f1efc00f760 DEBUG rtspstream 
rtsp-stream.c:5293:pad_blocking:<rtpbin0:send_rtcp_src_1> Now blocking
0:00:08.140169037 189229 0x7f1efc00f760 DEBUG rtspstream 
rtsp-stream.c:5295:pad_blocking:<GstRTSPStream at 0x7f1f0404e740> position: 
99:99:99.999999999
0:00:08.140249557 189229 0x7f1f040038c0 DEBUG rtspmedia 
rtsp-media.c:3285:default_handle_message:<GstRTSPOnvifMedia at 0x7f1f0404c1f0> 
media received blocking message, n_active_sender_streams = 0, 
is_complete = 0
0:00:08.140272697 189229 0x7f1f040038c0 DEBUG rtspmedia 
rtsp-media.c:3298:default_handle_message:<pay1> media is blocking
0:00:08.140280707 189229 0x7f1f040038c0 INFO rtspmedia 
rtsp-media.c:870:collect_media_stats: collect media stats
0:00:08.140289447 189229 0x7f1f040038c0 DEBUG rtspmedia 
rtsp-media.c:2773:gst_rtsp_media_set_status: setting new status to 3
0:00:08.140323777 189229 0x55b4c6d978c0 DEBUG rtspmedia 
rtsp-media.c:2806:gst_rtsp_media_get_status: got status 3
0:00:08.140344817 189229 0x55b4c6d978c0 INFO rtspmedia 
rtsp-media.c:3892:gst_rtsp_media_prepare: object 0x7f1f0404c1f0 is prerolled
0:00:08.140390969 189229 0x55b4c6d978c0 INFO rtspmedia 
rtsp-media.c:870:collect_media_stats: collect media stats
0:00:08.140719840 189229 0x55b4c6d978c0 FIXME rtspmedia 
rtsp-media.c:4557:gst_rtsp_media_suspend: suspend for dynamic pipelines 
needs fixing
0:00:08.140776771 189229 0x55b4c6d978c0 DEBUG rtspmedia 
rtsp-media.c:4497:default_suspend: media 0x7f1f0404c1f0 no suspend
0:00:08.140806731 189229 0x55b4c6d978c0 DEBUG rtspmedia 
rtsp-media.c:2773:gst_rtsp_media_set_status: setting new status to 4

I wonder if this happens because of the recent changes that addressed 
block/unblocking the streams:
https://github.com/GStreamer/gstreamer/commit/79f11eb77804d7f70f2bc8e062c2201cd1f191b6

Does somebody else experience this behaviour and could confirm that a 
bug was introduced here?

Best regards,
Christian