search

Kurento / bugtracker

[ARCHIVED] Contents migrated to monorepo: https://github.com/Kurento/kurento
46 stars 10 forks source link

Not a bug, a question #639

Closed neilyoung closed 1 year ago

neilyoung commented 2 years ago

Prerequisites

These are MANDATORY, otherwise the issue will be automatically closed.

Issue description

Hi guys,

trying to get some help on this problem:

Works absolutely brilliant if the browser sends VP8 and KMS is doing the transcoding. I can consume the video with ffplay, gstreamer or vlc and it rocks. It also kind of works, if the H.264 from the browser is just forwarded, but I'm facing the problem, that I'm missing the intra frames...

Think about: The publisher session runs already for a long time, there is no resolution change anymore, it is stable at 1280x720, no errors. Now I come with an RTSP client and I'm getting the video as it comes. I can observe that on the client: Gray soup on the screen. I can wipe over the camera and all is fine, but I'm not always having the camera in front of my nose.

For a while, for a long while no intra frame appears. Sometimes more than a minute. Whenever the browser thinks it is time to send an intra frame...

Is there any way, that I can make KMS send a PLI or FIR or whatever RTCP packet to the upstream WebRTC publisher source, whenever a new RTSP client joins (not sure if I will be able to detect that, but at least that would be a way).

Or even a regular FIR/PLI request upstream?

Anything?

Again: It works, if KMS does the transcoding

I have seen another post here, where Juan stated:

You can use Wireshark and see the packets flying in and out of Kurento. KMS forwards PLI and FIR requests to the encoder of the video (e.g. a web browser), so the sender can decide if a new keyframe should be generated. Sometimes Kurento itself acts as encoder when transcoding is enabled, in this case it is Kurento itself the one generating keyframes.

This confirms IMHO why it works with transcoding, but for other reasons I would like to get rid of that

Context

How to reproduce?

Expected & current behavior

(Optional) Possible solution

Info about your environment

About Kurento Media Server

About your Application Server

About end-user clients

Run these commands

cat /etc/lsb-release
kurento-media-server --version
dpkg -l | grep -Pi 'kurento|kms-|gst.*1.5|nice'
github-actions[bot] commented 2 years ago

Hello @neilyoung! :wave: we're sorry you found a bug... so first of all, thank you very much for reporting it.

To know about progress, check in Triage. All issues are considered Backlog Candidates until work priorities align and the issue is selected for development. It will then become part of our official Backlog.

j1elo commented 1 year ago

If the receiver was another WebRTC connection, probably it would be possible to somehow force a PLI request from time to time... given that Kurento just redirects it.

But right now it doesn't seem possible to force request new keyframes. I've taken a look and the important pieces of the puzzle are just there (an action signal called request-local-key-frame, implemented years ago by other devs, but never surfaced to the Client API), but a proper feature implementation is missing. This could be interesting, I'll take note and consider it for addition to future development.

neilyoung commented 1 year ago

Thanks Juan. As I tried to explain, the publisher is a WebRTC browser client. Those just issue every 100 s a key frame (at of course at the beginning of the connection). The receiver is an RTSP client, which is fed by a nice bridge between the browser input and ffmpeg using RtpEndpoint in the KMS controlling app (Node JS). By this I'm bridging WebRTC input to RTSP/RTMP/HLS output and the results are stunning (with RTSP). Felt lower latency, even if KMS transcoded compared to another subscriber using WebRTC. This is strange but a matter of fact :)

So now the publisher runs unattended and if the RTSP client once in a while connects, it doesn't see an intra frame for 100 s, which can be messy. You can clean-sweep the camera, but what if the publisher is an edge device...

However, all my Edge device representations are based on GStreamer and most of them doing transcoding, so the intra frame rate is way higher. Makes an update at least in between 5 s.

However, this situation is not satisfying. I know, that W3C works on something similar for browsers, because they seem to see the same problem in SFU connections. So once it is there at the "producer side" it would be just great to have a means to kick-start it by PLI. I could take the time when an RTSP client joins in order to provoke a PLI...

Let's see. For now the problem is not that urgent anymore, since I mostly use that "edge device" scenario. Just with browsers and just with H.264 SFU - that's the remaining problem.

j1elo commented 1 year ago

Yeah I know. I believe that Kurento would send a PLI/FIR whenever a new downstream endpoint was connected to the upstream WebRtcEndpoint. But the problem here is that new clients connect to your RTSP server, which lives outside of Kurento, so Kurento only sees that there is an RtpEndpoint happily receiving data from the WebRtcEndpoint, thus no PLI is apparently needed at any moment.

A couple years ago I thought of adding an RtspServerEndpoint to Kurento, but that was quite an effort that needed to be employed elsewhere :) but it still remains a conceptually cool idea, as then Kurento would behave more as an all-in-one server. But I digress.

What would be helpful in this case is that the WebRtcEndpoint had a Client API method such as forceKeyframeRequest(). You could then call this method to force a new PLI/FIR request from that endpoint. This, or a similar method / configuration setting for requests on a fixed time interval.

Apparently, initial developers of Kurento had the same idea. The source code of the BaseRtpEndpoint (parent of both Rtp and WebRtc endpoints) contains the mentioned request-local-key-frame action signal. I believe this could be an easy to do addition, so I'll propose it to the team. But for now I'm afraid that there is no API control of the keyframes.

I'm thinking that you could fake it by connecting a new consumer, e.g. a fake WebRtcEndpoint or RtpEndpoint. At some point a new keyframe will be requested from the sender, but right now I'm not sure if this was just when connecting elements (sender.connect(receiver)) or when media buffers started to actually flow through (which is more cumbersome as you would need to actually set a receiver up). But it might be a good way to "trick" your way to the keyframe request functionality within the internals of the server.

neilyoung commented 1 year ago

But the problem here is that new clients connect to your RTSP server, which lives outside of Kurento, so Kurento only sees that there is an RtpEndpoint happily receiving data from the WebRtcEndpoint, thus no PLI is apparently needed at any moment.

Exactly.

A couple years ago I thought of adding an RtspServerEndpoint to Kurento, but that was quite an effort that needed to be employed elsewhere :) but it still remains a conceptually cool idea, as then Kurento would behave more as an all-in-one server.

This is exactly the point. It makes KMS with one strike the one and all solution for everything :) I feel as if I would have fitted my KMS solution with a new world wide known standard outlet, able to connect to whatever device is there, having the same plug. Even more it also supports audio.

I'm thinking that you could fake it by connecting a new consumer, e.g. a fake WebRtcEndpoint or RtpEndpoint.

That would be a way, but it would only work if KMS is doing transcoding. A new WebRtcEndpoint from a subscriber in fact tears down the resolution to 640x360 for all clients before it ramps up again and this resolution change causes also a new intra frame. In fact I tried that, using just an ordinary subscriber session from another browser window. Has no impact, if the KMS just SFUs

What would be helpful in this case is that the WebRtcEndpoint had a Client API method such as forceKeyframeRequest(). You could then call this method to force a new PLI/FIR request from that endpoint. This, or a similar method / configuration setting for requests on a fixed time interval.

That would be awesome :)

Apparently, initial developers of Kurento had the same idea. The source code of the BaseRtpEndpoint (parent of both Rtp and WebRtc endpoints) contains the mentioned request-local-key-frame action signal. I believe this could be an easy to do addition, so I'll propose it to the team. But for now I'm afraid that there is no API control of the keyframes.

I see. Thanks for your efforts.

neilyoung commented 1 year ago

Patched a bit in BaseRtpEndpointImpl.cpp (kms-core) and BaseRtpEndpoint.js (kurento-client-lib), but all I get is this so far:

Trace: Error: Method 'forceKeyframeRequest' with 0 parameters not found
    at /home/ubuntu/webrtc-server/node_modules/kurento-client/lib/KurentoClient.js:365:24
    at Object.dispatchCallback [as callback] (/home/ubuntu/webrtc-server/node_modules/kurento-jsonrpc/lib/index.js:546:9)
    at processResponse (/home/ubuntu/webrtc-server/node_modules/kurento-jsonrpc/lib/index.js:667:15)
    at RpcBuilder.decode (/home/ubuntu/webrtc-server/node_modules/kurento-jsonrpc/lib/index.js:723:5)
    at Stream.transportMessage (/home/ubuntu/webrtc-server/node_modules/kurento-jsonrpc/lib/index.js:208:10)
    at Stream.emit (events.js:400:28)
    at Stream.emit (domain.js:475:12)
    at drain (/home/ubuntu/webrtc-server/node_modules/through/index.js:36:16)
    at Stream.stream.queue.stream.push (/home/ubuntu/webrtc-server/node_modules/through/index.js:45:5)
    at WebsocketStream.onMessage (/home/ubuntu/webrtc-server/node_modules/websocket-stream/index.js:45:15) {
  code: 40008,
  data: { type: 'MALFORMED_TRANSACTION' }
}
    at Object.noop (/home/ubuntu/webrtc-server/node_modules/kurento-client-core/lib/abstracts/BaseRtpEndpoint.js:35:22)
    at callback2 (/home/ubuntu/webrtc-server/node_modules/promisecallback/index.js:27:25)
    at processTicksAndRejections (internal/process/task_queues.js:95:5)
    at async /home/ubuntu/webrtc-server/ms.js:835:17
neilyoung commented 1 year ago

@j1elo Juan, sorry for asking directly: Has there been any development in this matter or would you have some idea how to make forceKeyFrameRequest accessible?

neilyoung commented 1 year ago

OK, so if I already unluckily have just to talk to myself, here the progress:

I'm aware of having made very clumsy steps to reach the target. In the end I'm able to send FIR requests on demand from my subscriber session (which I don't need).

Too bad, I'm lost :(

neilyoung commented 1 year ago

In case somebody is concerned: This is what happens if I issue the "setMtu(1)" from the publisher webRtcEndpoint:

0:00:10.938199948  9555 0x7fe070004400 INFO    KurentoBaseRtpEndpointImpl BaseRtpEndpointImpl.cpp:392:setMtu: Set MTU for RTP: 1
0:00:10.938331809  9555 0x7fe070004400 WARN         basertpendpoint kmsbasertpendpoint.c:2527:kms_base_rtp_endpoint_set_property:<kmswebrtcendpoint0> Trying to set request_key_frame
0:00:10.938360713  9555 0x7fe070004400 INFO        GST_ELEMENT_PADS gstelement.c:907:gst_element_get_static_pad: found pad rtpbin0:send_rtp_src_1
0:00:10.938450054  9555 0x7fe070004400 WARN         basertpendpoint kmsbasertpendpoint.c:1193:kms_base_rtp_endpoint_request_local_key_frame:<kmswebrtcendpoint0> Keyframe request not handled

Nothing happens. If I do that from a subscriber webrtcEndpoint the result is this:

0:03:38.551865192  9555 0x55f1a2a13070 INFO    KurentoBaseRtpEndpointImpl BaseRtpEndpointImpl.cpp:392:setMtu: Set MTU for RTP: 1
0:03:38.552017548  9555 0x55f1a2a13070 WARN         basertpendpoint kmsbasertpendpoint.c:2527:kms_base_rtp_endpoint_set_property:<kmswebrtcendpoint2> Trying to set request_key_frame
0:03:38.552037697  9555 0x55f1a2a13070 INFO        GST_ELEMENT_PADS gstelement.c:907:gst_element_get_static_pad: found pad rtpbin2:send_rtp_src_1
0:03:38.552116446  9555 0x55f1a2a13070 INFO               h264parse gsth264parse.c:2776:gst_h264_parse_src_event:<h264parse3> received upstream force-key-unit event, seqnum 2784 running_time 99:99:99.999999999 all_headers 1 count 0
0:03:38.671475445  9555 0x7fe00c003c50 INFO               h264parse gsth264parse.c:2132:check_pending_key_unit_event: now 0:00:38.934061013 wanted 99:99:99.999999999
0:03:38.671576234  9555 0x7fe00c003c50 INFO               h264parse gsth264parse.c:2178:gst_h264_parse_prepare_key_unit:<h264parse3> pushing downstream force-key-unit event 2784 0:00:38.934061013 count 0
0:03:38.671623471  9555 0x7fe00c003c50 INFO               h264parse gsth264parse.c:2197:gst_h264_parse_prepare_key_unit:<h264parse3> preparing key unit, have sps 1 have pps 1
0:03:41.319636709  9555 0x7fe07800ba30 INFO          dtlsconnection gstdtlsconnection.c:687:openssl_poll:<GstDtlsConnection@0x7fe028041bf0> handshake is completed

Here it works.

neilyoung commented 1 year ago

OK, disregard. I have it. I forgot that I have a "subscribing" client, when I launch an RTSP session - the RtpEndpoint. You pointed me to this by this phrase:

The source code of the BaseRtpEndpoint (parent of both Rtp and WebRtc endpoints) contains the mentioned request-local-key-frame action signal.

I was too focused to fire FIR into the publisher's WebRtcEndpoint. But it is even more logical and better to do this into the dynamically created RtpEndpoint.

With the exception of having an own property/method/signal for this, everything works as expected now :)

j1elo commented 1 year ago

Hi @neilyoung not that you were talking to yourself here, but these days I've been focusing on the latest release of Openvidu and also holidays got in the way too

Thanks for tinkering with it and testing the private signal to verify that it works. I guess given the dates, the most appropriate thing for me to do is to bring a present so what better than surfacing this mechanism to the public API of the server :) also docs & server logs have been updated to better convey the information for users of this feature.

Have a look at the commit; it also is a good example of how to add new stuff to the API; in this case, a method: https://github.com/Kurento/kms-core/commit/a3466ae9fe7c1a0472cd2eb6b8d12bfe86a8d145

(I'll run new CI builds for the media server, and the client SDK, so everything gets auto-generated and dev packages are published)

Regards and happy holidays

neilyoung commented 1 year ago

Wow. That‘s awesome. And you know what? This is my birthday today. And I really appreciate that gift. Will check it out next days. Have a merry Christmas and thanks again

neilyoung commented 1 year ago

Hi @j1elo, thanks again for this. I reviewed it and I'm convinced it will work. However, I'm missing the the binding from the JS client side. I guess there the new method needs to to find an expression to, or?

j1elo commented 1 year ago

Hi, feliz navidad! I ran the client SDK CI jobs so the Java & JS clients should have got the new method, I'll check on Tuesday if they got uploaded successfully (remember to add the snapshot profile, to get the latest version, 6.18.1-SNAPSHOT, from the snapshots repo: https://doc-kurento.readthedocs.io/en/latest/user/installation_dev.html#kurento-java-client, or if using JS, directly from the js repos)

neilyoung commented 1 year ago

Thanks. Feliz Navidad to you too :)

Tuesday is ok for me.

Regards

neilyoung commented 1 year ago

Found requestKeyFrame here https://github.com/Kurento/kurento-client-core-js/blob/26137a9aa973aae28b06b72bc1d4bbf9ead68478/lib/abstracts/BaseRtpEndpoint.js#L893

So all should be fine

neilyoung commented 1 year ago

OK, hope you had some nice days. I can confirm, this commit works. Unfortunately I cannot mix it with 6.18.0 source compilation of other modules, since it insists to have >= 6.18.1 environment. But I re-compiled everything for the test.

Two things could or should be done, IMHO, to make it a full solution:

What do you think?

Thanks so far, this was a nice gift. But in the meantime I have to stick with my "solution", since I cannot update a couple of productive installations by recompiling everything just for this. My "solution" just requires me to patch kms-core a bit and recompile this. I would favour this for now, because it can be done quickly and works too

neilyoung commented 1 year ago

Hehe, now it is getting weird, but I have double checked it twice.

However, the keyframe is produced...

Again: My client script calls await publisherSession.rtpEndpointRTSP.requestKeyframe() using kurento-client-lib 6.18.1 and KMS 6.18.0 server reacts like so:

0:12:17.447607368 20082 0x7f8d24005030 INFO        GST_ELEMENT_PADS gstelement.c:907:gst_element_get_static_pad: found pad rtpbin3:send_rtp_src_1
0:12:17.447672499 20082 0x7f8d24005030 INFO               h264parse gsth264parse.c:2776:gst_h264_parse_src_event:<h264parse3> received upstream force-key-unit event, seqnum 3919 running_time 99:99:99.999999999 all_headers 1 count 0
0:12:17.466187106 20082 0x7f8cb4003ca0 INFO               h264parse gsth264parse.c:2132:check_pending_key_unit_event: now 0:10:02.768030052 wanted 99:99:99.999999999
0:12:17.493156317 20082 0x7f8cb4003ca0 INFO               h264parse gsth264parse.c:2132:check_pending_key_unit_event: now 0:10:02.801030052 wanted 99:99:99.999999999
0:12:17.493249033 20082 0x7f8cb4003ca0 INFO               h264parse gsth264parse.c:2178:gst_h264_parse_prepare_key_unit:<h264parse3> pushing downstream force-key-unit event 3919 0:10:02.801030052 count 0
0:12:17.493313798 20082 0x7f8cb4003ca0 INFO               h264parse gsth264parse.c:2197:gst_h264_parse_prepare_key_unit:<h264parse3> preparing key unit, have sps 1 have pps 1

I mean this is what I wanted at really low cost, but how does it work ? :)

neilyoung commented 1 year ago

More traces. You see the requestKeyframe:

0:00:21.987457248 27411 0x7f3b24002150 DEBUG   KurentoWebSocketTransport WebSocketTransport.cpp:557:processMessage: Message: {"jsonrpc":"2.0","method":"invoke","params":{"object":"05d1b21b-d6f1-4f54-a345-6aa9891c4344_kurento.MediaPipeline/d19fa2c4-20b9-4424-8dd5-86f9d09f2403_kurento.RtpEndpoint","operation":"requestKeyframe","sessionId":"886e404d-0c17-443c-9e20-3e7f791aaa64"},"id":491}
0:00:21.987659405 27411 0x7f3b24002150 INFO        GST_ELEMENT_PADS gstelement.c:907:gst_element_get_static_pad: found pad rtpbin1:send_rtp_src_1
0:00:21.987752858 27411 0x7f3b24002150 INFO               h264parse gsth264parse.c:2776:gst_h264_parse_src_event:<h264parse0> received upstream force-key-unit event, seqnum 681 running_time 99:99:99.999999999 all_headers 1 count 0
0:00:21.987936156 27411 0x7f3b24002150 DEBUG   KurentoWebSocketTransport WebSocketTransport.cpp:559:processMessage: Response: {"id":491,"jsonrpc":"2.0","result":{"sessionId":"886e404d-0c17-443c-9e20-3e7f791aaa64","value":null}}
0:00:22.062264370 27411 0x7f3af000b630 INFO               h264parse gsth264parse.c:2132:check_pending_key_unit_event: now 0:00:13.090923220 wanted 99:99:99.999999999
0:00:22.062348293 27411 0x7f3af000b630 INFO               h264parse gsth264parse.c:2178:gst_h264_parse_prepare_key_unit:<h264parse0> pushing downstream force-key-unit event 681 0:00:13.090923220 count 0
0:00:22.062396684 27411 0x7f3af000b630 INFO               h264parse gsth264parse.c:2197:gst_h264_parse_prepare_key_unit:<h264parse0> preparing key unit, have sps 1 have pps 1
0:00:22.465318974 27411 0x7f3af000b630 INFO               GST_EVENT gstevent.c:679:gst_event_new_caps: creating caps event video/x-h264, stream-format=(string)avc, alignment=(string)au, codec_data=(buffer)0142c020ffe1000f6742c0208c8d407808bf700f08846a01000468ce3c80, level=(string)3.2, profile=(string)constrained-baseline
0:00:22.465521877 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:907:gst_element_get_static_pad: found pad h264parse0:sink
0:00:22.465591733 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstpad.c:2069:gst_pad_unlink: unlinking agnosticbin_tee1:src_1(0x7f3a9800b800) and h264parse0:sink(0x7f3b24008ff0)
0:00:22.465731739 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:776:gst_element_remove_pad:<agnosticbin_tee1> removing pad 'src_1'
0:00:22.465747661 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstpad.c:2069:gst_pad_unlink: unlinking agnosticbin_tee1:src_1(0x7f3a9800b800) and kmsparsetreebin0:ghost0(0x7f3a98008c80)
0:00:22.465770798 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstpad.c:2123:gst_pad_unlink: unlinked agnosticbin_tee1:src_1 and kmsparsetreebin0:ghost0
0:00:22.465831372 27411 0x7f3af000b630 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:364:gst_element_factory_create: creating element "tee"
0:00:22.465891527 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:659:gst_element_add_pad:<GstTee@0x7f3aa400c490> adding pad 'sink'
0:00:22.465920839 27411 0x7f3af000b630 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:364:gst_element_factory_create: creating element "fakesink"
0:00:22.465954964 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:659:gst_element_add_pad:<GstBaseSink@0x7f3a980c5090> adding pad 'sink'
0:00:22.465982571 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:907:gst_element_get_static_pad: found pad treebin_tee3:sink
0:00:22.466105664 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstutils.c:1573:gst_element_link_pads_full: trying to link element treebin_tee3:(any) to element treebin_fakesink3:(any)
0:00:22.466289850 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:659:gst_element_add_pad:<treebin_tee3> adding pad 'src_0'
0:00:22.466315669 27411 0x7f3af000b630 INFO                GST_PADS gstutils.c:1446:prepare_link_maybe_ghosting: treebin_tee3 and treebin_fakesink3 in same bin, no need for ghost pads
0:00:22.466335776 27411 0x7f3af000b630 INFO                GST_PADS gstpad.c:2313:gst_pad_link_prepare: trying to link treebin_tee3:src_0 and treebin_fakesink3:sink
0:00:22.466356621 27411 0x7f3af000b630 INFO                GST_PADS gstpad.c:4093:gst_pad_peer_query:<treebin_tee3:sink> pad has no peer
0:00:22.466383957 27411 0x7f3af000b630 INFO                GST_PADS gstpad.c:2519:gst_pad_link_full: linked treebin_tee3:src_0 and treebin_fakesink3:sink, successful
0:00:22.466398243 27411 0x7f3af000b630 INFO               GST_EVENT gstevent.c:1382:gst_event_new_reconfigure: creating reconfigure event
0:00:22.466484286 27411 0x7f3af000b630 INFO               GST_EVENT gstpad.c:5629:gst_pad_send_event_unchecked:<treebin_tee3:src_0> Received event on flushing pad. Discarding
0:00:22.467095236 27411 0x7f3af000b630 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:364:gst_element_factory_create: creating element "h264parse"
0:00:22.467174349 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:659:gst_element_add_pad:<GstBaseParse@0x7f3a980c9b00> adding pad 'sink'
0:00:22.467195286 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:659:gst_element_add_pad:<GstBaseParse@0x7f3a980c9b00> adding pad 'src'
0:00:22.467230870 27411 0x7f3af000b630 INFO               baseparse gstbaseparse.c:3942:gst_base_parse_set_pts_interpolation:<GstH264Parse@0x7f3a980c9b00> PTS interpolation: no
0:00:22.467269727 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<h264parse1> completed state change to NULL
0:00:22.467297502 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:907:gst_element_get_static_pad: found pad treebin_tee3:sink
0:00:22.467313417 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstutils.c:1573:gst_element_link_pads_full: trying to link element h264parse1:(any) to element treebin_tee3:(any)
0:00:22.467328226 27411 0x7f3af000b630 INFO                GST_PADS gstutils.c:932:gst_pad_check_link: trying to link h264parse1:src and treebin_tee3:sink
0:00:22.467372265 27411 0x7f3af000b630 INFO                GST_PADS gstutils.c:1446:prepare_link_maybe_ghosting: h264parse1 and treebin_tee3 in same bin, no need for ghost pads
0:00:22.467399922 27411 0x7f3af000b630 INFO                GST_PADS gstpad.c:2313:gst_pad_link_prepare: trying to link h264parse1:src and treebin_tee3:sink
0:00:22.467431602 27411 0x7f3af000b630 INFO                GST_PADS gstpad.c:2519:gst_pad_link_full: linked h264parse1:src and treebin_tee3:sink, successful
0:00:22.467454226 27411 0x7f3af000b630 INFO               GST_EVENT gstevent.c:1382:gst_event_new_reconfigure: creating reconfigure event
0:00:22.467465575 27411 0x7f3af000b630 INFO               GST_EVENT gstpad.c:5629:gst_pad_send_event_unchecked:<h264parse1:src> Received event on flushing pad. Discarding
0:00:22.467491673 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:907:gst_element_get_static_pad: found pad h264parse1:src
0:00:22.467560978 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<treebin_fakesink3> current NULL pending VOID_PENDING, desired next READY
0:00:22.467580244 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<treebin_fakesink3> completed state change to READY
0:00:22.467600113 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<treebin_fakesink3> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:22.467730211 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<kmsparsetreebin1> child 'treebin_fakesink3' changed state to 2(READY) successfully
0:00:22.467917148 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<treebin_tee3> current NULL pending VOID_PENDING, desired next READY
0:00:22.467942406 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<treebin_tee3> completed state change to READY
0:00:22.467964184 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<treebin_tee3> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:22.467991181 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<kmsparsetreebin1> child 'treebin_tee3' changed state to 2(READY) successfully
0:00:22.468009253 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<h264parse1> current NULL pending VOID_PENDING, desired next READY
0:00:22.468031199 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<h264parse1> completed state change to READY
0:00:22.468043888 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<h264parse1> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:22.468068545 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<kmsparsetreebin1> child 'h264parse1' changed state to 2(READY) successfully
0:00:22.468093151 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2347:gst_element_continue_state:<kmsparsetreebin1> committing state from NULL to READY, pending PLAYING, next PAUSED
0:00:22.468122175 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<kmsparsetreebin1> notifying about state-changed NULL to READY (PLAYING pending)
0:00:22.468147142 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2354:gst_element_continue_state:<kmsparsetreebin1> continue state change READY to PAUSED, final PLAYING
0:00:22.468176747 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<treebin_fakesink3> current READY pending VOID_PENDING, desired next PAUSED
0:00:22.468207208 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<treebin_fakesink3> completed state change to PAUSED
0:00:22.468226984 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<treebin_fakesink3> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:22.468264027 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<kmsparsetreebin1> child 'treebin_fakesink3' changed state to 3(PAUSED) successfully
0:00:22.468287756 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<treebin_tee3> current READY pending VOID_PENDING, desired next PAUSED
0:00:22.468316131 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<treebin_tee3> completed state change to PAUSED
0:00:22.468336105 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<treebin_tee3> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:22.468354545 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<kmsparsetreebin1> child 'treebin_tee3' changed state to 3(PAUSED) successfully
0:00:22.468376312 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<h264parse1> current READY pending VOID_PENDING, desired next PAUSED
0:00:22.468423235 27411 0x7f3af000b630 INFO                GST_PADS gstpad.c:4093:gst_pad_peer_query:<h264parse1:sink> pad has no peer
0:00:22.468743316 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<h264parse1> completed state change to PAUSED
0:00:22.468769077 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<h264parse1> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:22.468795721 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<kmsparsetreebin1> child 'h264parse1' changed state to 3(PAUSED) successfully
0:00:22.468812786 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2347:gst_element_continue_state:<kmsparsetreebin1> committing state from READY to PAUSED, pending PLAYING, next PLAYING
0:00:22.468830783 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<kmsparsetreebin1> notifying about state-changed READY to PAUSED (PLAYING pending)
0:00:22.468846084 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2354:gst_element_continue_state:<kmsparsetreebin1> continue state change PAUSED to PLAYING, final PLAYING
0:00:22.468884548 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<treebin_fakesink3> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:22.468908691 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<treebin_fakesink3> completed state change to PLAYING
0:00:22.468919141 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<treebin_fakesink3> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:22.468954045 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<kmsparsetreebin1> child 'treebin_fakesink3' changed state to 4(PLAYING) successfully
0:00:22.468976819 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<treebin_tee3> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:22.468992300 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<treebin_tee3> completed state change to PLAYING
0:00:22.469004401 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<treebin_tee3> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:22.469020678 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<kmsparsetreebin1> child 'treebin_tee3' changed state to 4(PLAYING) successfully
0:00:22.469045626 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<h264parse1> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:22.469069747 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<h264parse1> completed state change to PLAYING
0:00:22.469089444 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<h264parse1> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:22.469122424 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<kmsparsetreebin1> child 'h264parse1' changed state to 4(PLAYING) successfully
0:00:22.469144635 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<kmsparsetreebin1> completed state change to PLAYING
0:00:22.469165142 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<kmsparsetreebin1> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:22.469192334 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstutils.c:1573:gst_element_link_pads_full: trying to link element agnosticbin_tee1:(any) to element h264parse1:(any)
0:00:22.469271196 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:659:gst_element_add_pad:<agnosticbin_tee1> adding pad 'src_2'
0:00:22.469302956 27411 0x7f3af000b630 INFO                GST_PADS gstutils.c:1451:prepare_link_maybe_ghosting: agnosticbin_tee1 and h264parse1 not in same bin, making ghost pads
0:00:22.469355213 27411 0x7f3af000b630 INFO                GST_PADS gstpad.c:2313:gst_pad_link_prepare: trying to link ghost1:proxypad37 and h264parse1:sink
0:00:22.469378790 27411 0x7f3af000b630 INFO                GST_PADS gstpad.c:2519:gst_pad_link_full: linked ghost1:proxypad37 and h264parse1:sink, successful
0:00:22.469399975 27411 0x7f3af000b630 INFO               GST_EVENT gstevent.c:1382:gst_event_new_reconfigure: creating reconfigure event
0:00:22.469482630 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:659:gst_element_add_pad:<kmsparsetreebin1> adding pad 'ghost1'
0:00:22.469510367 27411 0x7f3af000b630 INFO                GST_PADS gstpad.c:2313:gst_pad_link_prepare: trying to link agnosticbin_tee1:src_2 and kmsparsetreebin1:ghost1
0:00:22.469583011 27411 0x7f3af000b630 INFO                GST_PADS gstpad.c:2519:gst_pad_link_full: linked agnosticbin_tee1:src_2 and kmsparsetreebin1:ghost1, successful
0:00:22.469610366 27411 0x7f3af000b630 INFO               GST_EVENT gstevent.c:1382:gst_event_new_reconfigure: creating reconfigure event
0:00:22.469788331 27411 0x7f3af000b630 INFO           GST_PARENTAGE gstbin.c:1630:gst_bin_remove_func:<kmswebrtcendpoint0_kmsagnosticbin2-0> removed child "kmsparsetreebin0"
0:00:22.469832499 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<treebin_fakesink2> current PLAYING pending VOID_PENDING, desired next PAUSED
0:00:22.469859291 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<treebin_fakesink2> completed state change to PAUSED
0:00:22.469880636 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<treebin_fakesink2> notifying about state-changed PLAYING to PAUSED (VOID_PENDING pending)
0:00:22.469897998 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<kmsparsetreebin0> child 'treebin_fakesink2' changed state to 3(PAUSED) successfully
0:00:22.469922224 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<treebin_tee2> current PLAYING pending VOID_PENDING, desired next PAUSED
0:00:22.469938468 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<treebin_tee2> completed state change to PAUSED
0:00:22.469948776 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<treebin_tee2> notifying about state-changed PLAYING to PAUSED (VOID_PENDING pending)
0:00:22.469964322 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<kmsparsetreebin0> child 'treebin_tee2' changed state to 3(PAUSED) successfully
0:00:22.469992923 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<h264parse0> current PLAYING pending VOID_PENDING, desired next PAUSED
0:00:22.470007746 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<h264parse0> completed state change to PAUSED
0:00:22.470020590 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<h264parse0> notifying about state-changed PLAYING to PAUSED (VOID_PENDING pending)
0:00:22.470037231 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<kmsparsetreebin0> child 'h264parse0' changed state to 3(PAUSED) successfully
0:00:22.470066901 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2347:gst_element_continue_state:<kmsparsetreebin0> committing state from PLAYING to PAUSED, pending NULL, next READY
0:00:22.470339579 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<kmsparsetreebin0> notifying about state-changed PLAYING to PAUSED (NULL pending)
0:00:22.470366768 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2354:gst_element_continue_state:<kmsparsetreebin0> continue state change PAUSED to READY, final NULL
0:00:22.470387350 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<treebin_fakesink2> current PAUSED pending VOID_PENDING, desired next READY
0:00:22.470416822 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<treebin_fakesink2> completed state change to READY
0:00:22.470437271 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<treebin_fakesink2> notifying about state-changed PAUSED to READY (VOID_PENDING pending)
0:00:22.470464991 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<kmsparsetreebin0> child 'treebin_fakesink2' changed state to 2(READY) successfully
0:00:22.470492022 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<treebin_tee2> current PAUSED pending VOID_PENDING, desired next READY
0:00:22.470537844 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<treebin_tee2> completed state change to READY
0:00:22.470557780 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<treebin_tee2> notifying about state-changed PAUSED to READY (VOID_PENDING pending)
0:00:22.470582786 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<kmsparsetreebin0> child 'treebin_tee2' changed state to 2(READY) successfully
0:00:22.470611513 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<h264parse0> current PAUSED pending VOID_PENDING, desired next READY
0:00:22.470757364 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<h264parse0> completed state change to READY
0:00:22.470882221 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<h264parse0> notifying about state-changed PAUSED to READY (VOID_PENDING pending)
0:00:22.470920961 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<kmsparsetreebin0> child 'h264parse0' changed state to 2(READY) successfully
0:00:22.470964588 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2347:gst_element_continue_state:<kmsparsetreebin0> committing state from PAUSED to READY, pending NULL, next NULL
0:00:22.470987572 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<kmsparsetreebin0> notifying about state-changed PAUSED to READY (NULL pending)
0:00:22.471002282 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2354:gst_element_continue_state:<kmsparsetreebin0> continue state change READY to NULL, final NULL
0:00:22.471022712 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<treebin_fakesink2> current READY pending VOID_PENDING, desired next NULL
0:00:22.471049981 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<treebin_fakesink2> completed state change to NULL
0:00:22.471070261 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<treebin_fakesink2> notifying about state-changed READY to NULL (VOID_PENDING pending)
0:00:22.471085990 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<kmsparsetreebin0> child 'treebin_fakesink2' changed state to 1(NULL) successfully
0:00:22.471109022 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<treebin_tee2> current READY pending VOID_PENDING, desired next NULL
0:00:22.471134590 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<treebin_tee2> completed state change to NULL
0:00:22.471153890 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<treebin_tee2> notifying about state-changed READY to NULL (VOID_PENDING pending)
0:00:22.471178789 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<kmsparsetreebin0> child 'treebin_tee2' changed state to 1(NULL) successfully
0:00:22.471205713 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2316:gst_bin_element_set_state:<h264parse0> current READY pending VOID_PENDING, desired next NULL
0:00:22.471229573 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<h264parse0> completed state change to NULL
0:00:22.471248970 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<h264parse0> notifying about state-changed READY to NULL (VOID_PENDING pending)
0:00:22.471283490 27411 0x7f3af000b630 INFO              GST_STATES gstbin.c:2764:gst_bin_change_state_func:<kmsparsetreebin0> child 'h264parse0' changed state to 1(NULL) successfully
0:00:22.471298600 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<kmsparsetreebin0> completed state change to NULL
0:00:22.471309672 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<kmsparsetreebin0> notifying about state-changed READY to NULL (VOID_PENDING pending)
0:00:22.471333050 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstpad.c:2069:gst_pad_unlink: unlinking ghost0:proxypad36(0x7f3a9800ba60) and h264parse0:sink(0x7f3b24008ff0)
0:00:22.471386511 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstpad.c:2123:gst_pad_unlink: unlinked ghost0:proxypad36 and h264parse0:sink
0:00:22.471408388 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstpad.c:2069:gst_pad_unlink: unlinking h264parse0:src(0x7f3b24009230) and treebin_tee2:sink(0x7f3b24008b70)
0:00:22.471426430 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstpad.c:2123:gst_pad_unlink: unlinked h264parse0:src and treebin_tee2:sink
0:00:22.471585128 27411 0x7f3af000b630 INFO           GST_PARENTAGE gstbin.c:1630:gst_bin_remove_func:<kmsparsetreebin0> removed child "h264parse0"
0:00:22.471663943 27411 0x7f3af000b630 INFO         GST_REFCOUNTING gstelement.c:2947:gst_element_dispose:<h264parse0> dispose
0:00:22.471674752 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:776:gst_element_remove_pad:<h264parse0> removing pad 'sink'
0:00:22.471698068 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:776:gst_element_remove_pad:<h264parse0> removing pad 'src'
0:00:22.471710042 27411 0x7f3af000b630 INFO         GST_REFCOUNTING gstelement.c:2992:gst_element_dispose:<h264parse0> parent class dispose
0:00:22.471745338 27411 0x7f3af000b630 INFO         GST_REFCOUNTING gstelement.c:3023:gst_element_finalize:<h264parse0> finalize
0:00:22.471762803 27411 0x7f3af000b630 INFO         GST_REFCOUNTING gstelement.c:3028:gst_element_finalize:<h264parse0> finalize parent
0:00:22.471774885 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstpad.c:2069:gst_pad_unlink: unlinking treebin_tee2:src_0(0x7f3a9800b5b0) and treebin_fakesink2:sink(0x7f3b24008db0)
0:00:22.471800701 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstpad.c:2123:gst_pad_unlink: unlinked treebin_tee2:src_0 and treebin_fakesink2:sink
0:00:22.471825214 27411 0x7f3af000b630 INFO           GST_PARENTAGE gstbin.c:1630:gst_bin_remove_func:<kmsparsetreebin0> removed child "treebin_fakesink2"
0:00:22.471845107 27411 0x7f3af000b630 INFO         GST_REFCOUNTING gstelement.c:2947:gst_element_dispose:<treebin_fakesink2> dispose
0:00:22.471870259 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:776:gst_element_remove_pad:<treebin_fakesink2> removing pad 'sink'
0:00:22.471883825 27411 0x7f3af000b630 INFO         GST_REFCOUNTING gstelement.c:2992:gst_element_dispose:<treebin_fakesink2> parent class dispose
0:00:22.471901425 27411 0x7f3af000b630 INFO         GST_REFCOUNTING gstelement.c:3023:gst_element_finalize:<treebin_fakesink2> finalize
0:00:22.471910232 27411 0x7f3af000b630 INFO         GST_REFCOUNTING gstelement.c:3028:gst_element_finalize:<treebin_fakesink2> finalize parent
0:00:22.471932616 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstpad.c:2069:gst_pad_unlink: unlinking treebin_tee2:src_1(0x7f3a9800bca0) and agnosticbin_queue0:sink(0x7f3b24009470)
0:00:22.471963722 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:776:gst_element_remove_pad:<treebin_tee2> removing pad 'src_1'
0:00:22.471987193 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstpad.c:2123:gst_pad_unlink: unlinked '':src_1 and agnosticbin_queue0:sink
0:00:22.472015078 27411 0x7f3af000b630 INFO           GST_PARENTAGE gstbin.c:1630:gst_bin_remove_func:<kmsparsetreebin0> removed child "treebin_tee2"
0:00:22.472039134 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:776:gst_element_remove_pad:<treebin_tee2> removing pad 'src_0'
0:00:22.472060463 27411 0x7f3af000b630 INFO         GST_REFCOUNTING gstelement.c:2947:gst_element_dispose:<treebin_tee2> dispose
0:00:22.472079270 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:776:gst_element_remove_pad:<treebin_tee2> removing pad 'sink'
0:00:22.472109774 27411 0x7f3af000b630 INFO         GST_REFCOUNTING gstelement.c:2992:gst_element_dispose:<treebin_tee2> parent class dispose
0:00:22.472130307 27411 0x7f3af000b630 INFO         GST_REFCOUNTING gstelement.c:3023:gst_element_finalize:<treebin_tee2> finalize
0:00:22.472139124 27411 0x7f3af000b630 INFO         GST_REFCOUNTING gstelement.c:3028:gst_element_finalize:<treebin_tee2> finalize parent
0:00:22.472156613 27411 0x7f3af000b630 INFO         GST_REFCOUNTING gstelement.c:2947:gst_element_dispose:<kmsparsetreebin0> dispose
0:00:22.472165387 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:776:gst_element_remove_pad:<kmsparsetreebin0> removing pad 'ghost0'
0:00:22.472188103 27411 0x7f3af000b630 INFO         GST_REFCOUNTING gstelement.c:2992:gst_element_dispose:<kmsparsetreebin0> parent class dispose
0:00:22.472207046 27411 0x7f3af000b630 INFO         GST_REFCOUNTING gstelement.c:3023:gst_element_finalize:<kmsparsetreebin0> finalize
0:00:22.472229309 27411 0x7f3af000b630 INFO         GST_REFCOUNTING gstelement.c:3028:gst_element_finalize:<kmsparsetreebin0> finalize parent
0:00:22.472257652 27411 0x7f3af000b630 INFO                kmsutils kmsutils.c:518:kms_utils_pad_monitor_gaps:<kmswebrtcendpoint0_kmsagnosticbin2-0:sink> Add probe: DISCONT buffers and GAP events
0:00:22.472431209 27411 0x7f3af000b630 INFO               h264parse gsth264parse.c:1736:gst_h264_parse_update_src_caps:<h264parse1> resolution changed 960x540
0:00:22.472480960 27411 0x7f3af000b630 INFO               GST_EVENT gstevent.c:679:gst_event_new_caps: creating caps event video/x-h264, stream-format=(string)avc, alignment=(string)au, codec_data=(buffer)0142c020ffe1000f6742c0208c8d407808bf700f08846a01000468ce3c80, level=(string)3.2, profile=(string)constrained-baseline, width=(int)960, height=(int)540, framerate=(fraction)0/1, parsed=(boolean)true
0:00:22.472533551 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstpad.c:2069:gst_pad_unlink: unlinking agnosticbin_queue0:src(0x7f3b240096b0) and src_0:proxypad35(0x7f3a9800b370)
0:00:22.472557816 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:907:gst_element_get_static_pad: found pad agnosticbin_queue0:sink
0:00:22.472596313 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstpad.c:2123:gst_pad_unlink: unlinked agnosticbin_queue0:src and src_0:proxypad35
0:00:22.472627449 27411 0x7f3af000b630 INFO                GST_PADS gstpad.c:4093:gst_pad_peer_query:<src_0:proxypad35> pad has no peer
0:00:22.472763689 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:907:gst_element_get_static_pad: found pad treebin_tee3:sink
0:00:22.472826506 27411 0x7f3af000b630 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:364:gst_element_factory_create: creating element "queue"
0:00:22.472809872 27411 0x7f3b08012680 INFO        GST_ELEMENT_PADS gstelement.c:1555:gst_element_default_send_event: can't send eos event on element agnosticbin_queue0
0:00:22.472922680 27411 0x7f3b08012680 INFO           GST_PARENTAGE gstbin.c:1630:gst_bin_remove_func:<kmswebrtcendpoint0_kmsagnosticbin2-0> removed child "agnosticbin_queue0"
0:00:22.472964945 27411 0x7f3b08012680 INFO              GST_STATES gstelement.c:2347:gst_element_continue_state:<agnosticbin_queue0> committing state from PLAYING to PAUSED, pending NULL, next READY
0:00:22.472998804 27411 0x7f3b08012680 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<agnosticbin_queue0> notifying about state-changed PLAYING to PAUSED (NULL pending)
0:00:22.473038550 27411 0x7f3b08012680 INFO              GST_STATES gstelement.c:2354:gst_element_continue_state:<agnosticbin_queue0> continue state change PAUSED to READY, final NULL
0:00:22.472876942 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:659:gst_element_add_pad:<GstQueue@0x7f3a9804c9a0> adding pad 'sink'
0:00:22.473124422 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:659:gst_element_add_pad:<GstQueue@0x7f3a9804c9a0> adding pad 'src'
0:00:22.473177047 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2347:gst_element_continue_state:<agnosticbin_queue1> committing state from NULL to READY, pending PLAYING, next PAUSED
0:00:22.473199673 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<agnosticbin_queue1> notifying about state-changed NULL to READY (PLAYING pending)
0:00:22.473235261 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2354:gst_element_continue_state:<agnosticbin_queue1> continue state change READY to PAUSED, final PLAYING
0:00:22.473263318 27411 0x7f3af000b630 INFO                    task gsttask.c:473:gst_task_set_lock: setting stream lock 0x7f3a980a89d0 on task 0x7f3acc04c950
0:00:22.473288125 27411 0x7f3af000b630 INFO                GST_PADS gstpad.c:5975:gst_pad_start_task:<agnosticbin_queue1:src> created task 0x7f3acc04c950
0:00:22.473317855 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2347:gst_element_continue_state:<agnosticbin_queue1> committing state from READY to PAUSED, pending PLAYING, next PLAYING
0:00:22.473339557 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<agnosticbin_queue1> notifying about state-changed READY to PAUSED (PLAYING pending)
0:00:22.473371375 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2354:gst_element_continue_state:<agnosticbin_queue1> continue state change PAUSED to PLAYING, final PLAYING
0:00:22.473391359 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<agnosticbin_queue1> completed state change to PLAYING
0:00:22.473408921 27411 0x7f3af000b630 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<agnosticbin_queue1> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:22.473435682 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:907:gst_element_get_static_pad: found pad agnosticbin_queue1:src
0:00:22.473459576 27411 0x7f3af000b630 INFO                GST_PADS gstpad.c:2313:gst_pad_link_prepare: trying to link agnosticbin_queue1:src and src_0:proxypad35
0:00:22.473470393 27411 0x7f3b08012680 INFO              GST_STATES gstelement.c:2347:gst_element_continue_state:<agnosticbin_queue0> committing state from PAUSED to READY, pending NULL, next NULL
0:00:22.473540868 27411 0x7f3b08012680 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<agnosticbin_queue0> notifying about state-changed PAUSED to READY (NULL pending)
0:00:22.473481758 27411 0x7f3af000b630 INFO                GST_PADS gstpad.c:2519:gst_pad_link_full: linked agnosticbin_queue1:src and src_0:proxypad35, successful
0:00:22.473588943 27411 0x7f3b08012680 INFO              GST_STATES gstelement.c:2354:gst_element_continue_state:<agnosticbin_queue0> continue state change READY to NULL, final NULL
0:00:22.473591683 27411 0x7f3af000b630 INFO               GST_EVENT gstevent.c:1382:gst_event_new_reconfigure: creating reconfigure event
0:00:22.473609179 27411 0x7f3b08012680 INFO              GST_STATES gstelement.c:2372:gst_element_continue_state:<agnosticbin_queue0> completed state change to NULL
0:00:22.473714325 27411 0x7f3b08012680 INFO              GST_STATES gstelement.c:2277:_priv_gst_element_state_changed:<agnosticbin_queue0> notifying about state-changed READY to NULL (VOID_PENDING pending)
0:00:22.473732910 27411 0x7f3b08012680 INFO         GST_REFCOUNTING gstelement.c:2947:gst_element_dispose:<agnosticbin_queue0> dispose
0:00:22.473752680 27411 0x7f3b08012680 INFO        GST_ELEMENT_PADS gstelement.c:776:gst_element_remove_pad:<agnosticbin_queue0> removing pad 'sink'
0:00:22.473757138 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:659:gst_element_add_pad:<treebin_tee3> adding pad 'src_1'
0:00:22.473795965 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:907:gst_element_get_static_pad: found pad agnosticbin_queue1:sink
0:00:22.473831588 27411 0x7f3af000b630 INFO        GST_ELEMENT_PADS gstelement.c:907:gst_element_get_static_pad: found pad agnosticbin_queue1:src
0:00:22.473774612 27411 0x7f3b08012680 INFO        GST_ELEMENT_PADS gstelement.c:776:gst_element_remove_pad:<agnosticbin_queue0> removing pad 'src'
0:00:22.473866216 27411 0x7f3af000b630 INFO                GST_PADS gstpad.c:2313:gst_pad_link_prepare: trying to link treebin_tee3:src_1 and agnosticbin_queue1:sink
0:00:22.473898441 27411 0x7f3af000b630 INFO                GST_PADS gstpad.c:2519:gst_pad_link_full: linked treebin_tee3:src_1 and agnosticbin_queue1:sink, successful
0:00:22.473910981 27411 0x7f3af000b630 INFO               GST_EVENT gstevent.c:1382:gst_event_new_reconfigure: creating reconfigure event
0:00:22.473871164 27411 0x7f3b08012680 INFO         GST_REFCOUNTING gstelement.c:2992:gst_element_dispose:<agnosticbin_queue0> parent class dispose
0:00:22.473959676 27411 0x7f3b08012680 INFO         GST_REFCOUNTING gstelement.c:3023:gst_element_finalize:<agnosticbin_queue0> finalize
0:00:22.473970528 27411 0x7f3b08012680 INFO         GST_REFCOUNTING gstelement.c:3028:gst_element_finalize:<agnosticbin_queue0> finalize parent
0:00:22.474437348 27411 0x7f3af000b630 INFO               h264parse gsth264parse.c:2776:gst_h264_parse_src_event:<h264parse1> received upstream force-key-unit event, seqnum 766 running_time 99:99:99.999999999 all_headers 1 count 0
0:00:22.475325109 27411 0x7f3af000b630 INFO               h264parse gsth264parse.c:2132:check_pending_key_unit_event: now 0:00:13.524923220 wanted 99:99:99.999999999
0:00:22.475385299 27411 0x7f3af000b630 INFO               h264parse gsth264parse.c:2178:gst_h264_parse_prepare_key_unit:<h264parse1> pushing downstream force-key-unit event 766 0:00:13.524923220 count 0
0:00:22.475406705 27411 0x7f3af000b630 INFO               h264parse gsth264parse.c:2197:gst_h264_parse_prepare_key_unit:<h264parse1> preparing key unit, have sps 1 have pps 1
neilyoung commented 1 year ago

No, forget about my last posts. I seem to have still been working with a 6.18.1 KMS server, even though I strictly compiled from tag/6.18.0. And all version indications told me that I was on 6.18.0. But some unknown debris of 6.18.1 tricked me. This is the more disturbing, that I really removed everything from that box which smelled like "kurento" last time I tried to restore 6.18.0...

This is bad, since it means, that I cannot really up or downgrade KMS correctly :(

I setup a new VM, with the same procedures as before. There is no requestKeyframe support in 6.18.0. But I have no clue, how to get rid of an existing KMS installation entirely so that the newly installed will be as like the first morning for KMS on this box :(

j1elo commented 1 year ago

Hi, if you're using plain apt-get install commands for Kurento, then you'll have to keep an eye on the shortcomings of this tool. Namely, that it won't uninstall all the relevant packages when uninstalling Kurento!

This had affected enough users that made into the instructions page: https://doc-kurento.readthedocs.io/en/latest/user/installation.html#local-upgrade

As mentioned, aptitude seems to be much better, and will ask to uninstall all related packages when you try to remove the kurento-media-server package.

Otherwise, given how we work internally, heavily based on Docker, I just use containers for mostly everything. It allows me to ensure that I have a pristine environment, whenever needed, regardless of how much I had modified and broke the previous system with manual edits or replacing custom-built libraries... it's a really useful tool and it directly removes a whole category of mistakes that would otherwise be possible.

Today I just added a new utility script that creates a new Docker development image, which then can be used to spawn clean containers from; it's the way I usually develop with Kurento and adding it to the repo was in my list of things to do: https://github.com/Kurento/kms-omni-build/blob/7.0.0/bin/kms-make-dev-container.sh (it's in the "7.0.0" branch, where development for Kurento 7.0 happens)

neilyoung commented 1 year ago

Yes, I know. No, my KMS installation is building module for module from source, always checking out the particular tag required. I should also go for Docker, but somehow I like to not depend on those things. I also have a couple of own plugins, which I have to fiddle into this container. All doable, but not on my favourite to do list.

I also compile the latest OpenCV4.x from source and GStreamer 18.4 (may also change).

I really don't know, why I wasn't able to remove the 6.18.1 by over installing 6.18.0 _fromsource...

Since it all just boils down to changes in KMS-CORE here my ansible snippet for this module:

    #
    # ------ KMS-CORE (Step 19) -----------------
    #

    - name: KMS-CORE - Clone (run as non-privileged user)
      tags: kms-core
      git:
        repo: 'https://github.com/Kurento/kms-core'
        dest: ~/{{ kms_build_dir }}/kms-core
        version: tags/{{ kurento_media_server_version }}
        force: yes
      become: yes
      become_user: "{{ non_root_user }}"

    - name: KMS-CORE - Create build dir (run as non-privileged user)
      tags: kms-core
      file:
        path: ~/{{ kms_build_dir }}/kms-core/build
        state: directory
      become: yes
      become_user: "{{ non_root_user }}"

    - name: KMS-CORE  - Build (run as non-privileged user)
      tags: kms-core
      shell: |
        cmake \
          -D CMAKE_MODULE_PATH=/usr/local/share/"`cmake --version | awk '{split($0,a," "); split($a[3],a,"."); print "cmake-"a[1]"."a[2];exit}'`"/Modules \
          -D CMAKE_BUILD_TYPE=Release \
          -D CMAKE_INSTALL_PREFIX=/usr/. \
          ..
        make -j$(nproc)
      args:
        chdir: ~/{{ kms_build_dir }}/kms-core/build
      become: yes
      become_user: "{{ non_root_user }}"

    - name: KMS-CORE - Install
      tags: kms-core
      shell: |
        make install
        ldconfig
      args:
        chdir: /home/{{ ansible_user }}/{{ kms_build_dir }}/kms-core/build

I mean I didn't call sudo make uninstall from the kms-core/build dir before (maybe I should try that next time). But how is it possible, that - given {{ kurento_media_server_version }} is set to 6.18.0 - compilation works, the files were from 6.18.0, but nonetheless kurento-media-server was still working with the 6.18.1 version, even though the version indication was 6.18.0...

Don't get it... And that grieves me...

neilyoung commented 1 year ago

PS: What do you think about this?

Two things could or should be done, IMHO, to make it a full solution:

j1elo commented 1 year ago

16.8.1 doesn't exist, it's just how the code from "master" branch (i.e. in active development) shows itself. The next actually released version will probably be 6.19.0, or even 7.0 if things evolve according to plan.

So, to use new developments that happen in the master branch, you should either checkout the desired commit, or just stay on the master branch of all repos. Client SDKs for master branch are also generated and made available as shown here https://doc-kurento.readthedocs.io/en/latest/user/installation_dev.html but it is also possible (albeit a bit of a hassle) to build them yourself if you want (although right now I don't have ready made instructions that I could share)

neilyoung commented 1 year ago

16.8.1 doesn't exist, it's just how the code from "master" branch (i.e. in active development) shows itself. The next actually released version will probably be 6.19.0, or even 7.0 if things evolve according to plan.

Yes, I know. Just took your name. I don't care, what it is, but I NEED that tag :) And an NPM version of the client libs with the same version then. Would that be possible? I mean not today or tomorrow, but maybe after having finished the backports?

neilyoung commented 1 year ago

My solution now is to have a recurring timer which fires requestKeyframe every N secs in order to overcome possible packet losses for RTSP clients. And RTSP clients trigger a requestKeyframe when they join. Works perfectly. I have chosen N=5. Any objections on this value?

j1elo commented 1 year ago

I'm afraid that the release process is very complex with all moving parts of kurento, so we only do them when several improvements have been added over time... this is a pending improvement point, granted.

Meanwhile, if you are building from sources, this patch should be easy to integrate in your build, lots of people have customized builds of Kurento so they can apply patches or private changes, so it's a matter of having it integrated (maybe as simple as applying a .patch file before compilation)

Re: 5 seconds, nothing to object on that. If 5 is a good equilibrium between having to wait for a screen refresh, and the potebtial increase in bandwidth usage, then go for it. Providers like Wowza even suggest shorter time frames, but again, if 5 seconds is acceptable for you, then that's perfectly fine.

https://www.wowza.com/community/t/the-correct-keyframe-interval-in-obs-studio/95162

neilyoung commented 1 year ago

Thanks for confirmation. OK, no issue. You are right I could patch that into. But I'm fine with "my solution" so far (the setMtu abuse) and I have also already all the means included to be forward compatible once a KMS version appears, which has that "requestKeyframe"

Thanks for the nice discussion and all your efforts. I will be patient and check out for announcements :)

Regards

neilyoung commented 1 year ago

@j1elo I'm wondering if this solution also works if the publisher sends VP8, the RtpEndpoint negotiates H.264 and internal transcoding is made. From what I can see the "requestKeyframe" then does nothing. But I can only judge this for "my" solution (setMtu abuse). But since we both end up in gst_video_event_new_upstream_force_key_unit, I would expect, it would be the same with your's.

I cannot see that somewhat like a key frame is generated by the VP8 source (I don't even know, if VP8 supports that concept)

neilyoung commented 1 year ago

Hmm. Wait... I can see regular key frames in the RTSP output, so something must happen. It is just not traced somewhere...

[h264 @ 0x122817050] nal_unit_type: 7(SPS), nal_ref_idc: 3B f=0/0   
[h264 @ 0x122817050] nal_unit_type: 8(PPS), nal_ref_idc: 3
[h264 @ 0x122817050] nal_unit_type: 7(SPS), nal_ref_idc: 3
[h264 @ 0x122817050] nal_unit_type: 8(PPS), nal_ref_idc: 3
[h264 @ 0x122817050] nal_unit_type: 5(IDR), nal_ref_idc: 3
neilyoung commented 1 year ago

No, all fine. The FIRs land most likely in the internal transcoding phalanx, not at the far VP8 end (as with no transcoding)