Video stream lost on reInvite from WebRTC client

252 views
Skip to first unread message

Walter Schober

unread,
Aug 2, 2023, 9:53:14 AM8/2/23
to rtpengine
Hello!

I tried to analyze why video gets lost (not forwarded any more by rtpengine) after reInvite (session-timer). My deep knowloedge is not enough to have clue, why only audio ICE candiatates are considered after dropping the ice canditates on reInvite in favour of the "new" ones.

Can one of you guys give me an advice please, what going on here?

Scenario:

A (SIP) -> Kamailio/RTPEngine (both latest versions) -> Chrome WebRTC
audio + video: OK until reInvite from WebRTC client due to session timer.

The rtpengine log at the moment of reInvite:

On a reInvite the RTPengine removes the existing media streams (from kernel only?)

```
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2 port 10069]: [core] Successful STUN binding request from 10.123.255.221:52064
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/1 port 11561]: [core] Successful STUN binding request from 10.123.255.221:62937
...
Aug  2 14:48:29 p01t-1 rtpengine[3076]: INFO: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [control] Received command 'offer' from 10.55.33.129:52939
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [control] Dump for 'offer' from 10.55.33.129:52939: { "supports": [ "load limit" ], "sdp": "v=0
Aug  2 14:48:29 p01t-1 rtpengine[3076]: o=- 2290955861283766428 3 IN IP4 127.0.0.1
Aug  2 14:48:29 p01t-1 rtpengine[3076]: s=WebRTC session
Aug  2 14:48:29 p01t-1 rtpengine[3076]: t=0 0
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=group:BUNDLE 0 1
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=extmap-allow-mixed
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=msid-semantic: WMS d5822d97-23c7-4203-8edd-a0770cece28f
Aug  2 14:48:29 p01t-1 rtpengine[3076]: m=audio 57447 UDP/TLS/RTP/SAVPF 9 103 0 8 101 121
Aug  2 14:48:29 p01t-1 rtpengine[3076]: c=IN IP4 91.237.65.129
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=rtcp:9 IN IP4 192.168.229.217
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=candidate:4062660976 1 udp 2122260223 192.168.41.91 57447 typ host generation 0 network-id 1
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=candidate:3237821287 1 udp 2122194687 10.123.255.221 62937 typ host generation 0 network-id 2
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=candidate:4079434582 1 udp 1686052607 91.237.65.129 57447 typ srflx raddr 192.168.41.91 rport 57447 generation 0 network-id 1
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-ufrag:hWob
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-pwd:fAyQicrTCmoG3y2tczi94gll
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-options:trickle
...
Aug  2 14:48:29 p01t-1 rtpengine[3076]: m=video 61130 UDP/TLS/RTP/SAVPF 102 98 100 97 127 104 108 110 39 112
Aug  2 14:48:29 p01t-1 rtpengine[3076]: i=1·VIDEO½50013½Walter½21
Aug  2 14:48:29 p01t-1 rtpengine[3076]: c=IN IP4 91.237.65.129
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=rtcp:9 IN IP4 192.168.229.217
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=candidate:4062660976 1 udp 2122260223 192.168.41.91 61130 typ host generation 0 network-id 1
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=candidate:3237821287 1 udp 2122194687 10.123.255.221 52064 typ host generation 0 network-id 2
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=candidate:4079434582 1 udp 1686052607 91.237.65.129 61130 typ srflx raddr 192.168.41.91 rport 61130 generation 0 network-id 1
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-ufrag:hWob
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-pwd:fAyQicrTCmoG3y2tczi94gll
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-options:trickle

Aug  2 14:48:29 p01t-1 rtpengine[3076]: ", "flags": [ "trust-address", "media-handover" ], "replace": [ "origin", "session-connection" ], "codec": { "strip": [ "PCMU" ], "mask": [ "PCMA" ], "except": [ "OPUS", "G722" ], "transcode": [ "PCMA", "telephone-event" ] }, "tr
ansport-protocol": "RTP/AVP", "rtcp-mux": [ "demux" ], "call-id": "o-5hD0BCZsxNeV6ijjJvOi-CQ-100-", "via-branch": "z9hG4bK1044972", "received-from": [ "IP4", "10.123.255.221" ], "from-tag": "dk78v8tpq1", "to-tag": "1c531917440", "command": "offer" }
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/1c531917440/2 port 10972]: [core] Handling packet: remote 91.237.65.132:10410 (expected: 91.237.65.132:10410) -> local 193.84.65.132:10972 (RTP seq 973 TS 1814941633 SSRC 454eec01)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2 port 10069]: [core] Forward to sink endpoint: local 193.84.65.132:10069 -> remote 10.123.255.221:52064 (RTP seq 973 TS 1814941633 SSRC 454eec01)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] Using default bitrate of 32000 bps for 2-channel Opus
Aug  2 14:48:29 p01t-1 rtpengine[3076]: INFO: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] Removing media stream from kernel: local 193.84.65.132:11561 (dialogue signalling event)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] Unconfirming peer address for local 193.84.65.132:11561 (dialogue signalling event)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: INFO: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] Removing media stream from kernel: local 193.84.65.132:10792 (dialogue signalling event)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] Unconfirming peer address for local 193.84.65.132:10792 (dialogue signalling event)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: INFO: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] Removing media stream from kernel: local 193.84.65.132:10793 (dialogue signalling event)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] Unconfirming peer address for local 193.84.65.132:10793 (dialogue signalling event)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] Unconfirming peer address for local 193.84.65.132:0 (dialogue signalling event)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: INFO: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] Removing media stream from kernel: local 193.84.65.132:10069 (dialogue signalling event)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] Unconfirming peer address for local 193.84.65.132:10069 (dialogue signalling event)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: INFO: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] Removing media stream from kernel: local 193.84.65.132:10972 (dialogue signalling event)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] Unconfirming peer address for local 193.84.65.132:10972 (dialogue signalling event)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: INFO: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] Removing media stream from kernel: local 193.84.65.132:10973 (dialogue signalling event)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] Unconfirming peer address for local 193.84.65.132:10973 (dialogue signalling event)
...
Aug  2 14:48:29 p01t-1 rtpengine[3076]: INFO: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [crypto] ICE restart without TLS-ID, restarting DTLS
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [crypto] Resetting DTLS connection context
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [crypto] Resetting DTLS connection context
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] Resetting crypto context
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [crypto] Creating passive DTLS connection context
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [crypto] Creating passive DTLS connection context
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/1]: [ice] Dropping new ICE candidate 4062660976 in favour of 4062660976:1
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/1]: [ice] Dropping new ICE candidate 3237821287 in favour of 3237821287:1
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/1]: [ice] Dropping new ICE candidate 4079434582 in favour of 4079434582:1
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2]: [ice] ICE restart detected, resetting ICE agent
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2]: [ice] Learning new ICE candidate 4062660976:1
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2]: [ice] Created candidate pair uz7akZM3T4eiw64N:4062660976:1 between 193.84.65.132 and 192.168.41.91:61130, type host
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2]: [ice] Learning new ICE candidate 3237821287:1
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2]: [ice] Created candidate pair uz7akZM3T4eiw64N:3237821287:1 between 193.84.65.132 and 10.123.255.221:52064, type host
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2]: [ice] Learning new ICE candidate 4079434582:1
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2]: [ice] Created candidate pair uz7akZM3T4eiw64N:4079434582:1 between 193.84.65.132 and 91.237.65.129:61130, type srflx
```

No (new?) crypto was negotiated (yet?), so "SRTP output wanted, but no crypto suite was negotiated":

This is from A leg (inside) -> B leg (WebRTC) video port 10972:

```
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/1c531917440/2 port 10972]: [core] Handling packet: remote 91.237.65.132:10410 (expected: 91.237.65.132:10410) -> local 193.84.65.132:10972 (RTP seq 974 TS 1814941633 SSRC 454eec01)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: ERR: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/1c531917440/2 port 10972]: [srtp] SRTP output wanted, but no crypto suite was negotiated
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/1c531917440/2 port 10972]: [core] Error when sending message. Error: Inappropriate ioctl for device
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/1c531917440/2 port 10972]: [core] Handling packet: remote 91.237.65.132:10410 (expected: 91.237.65.132:10410) -> local 193.84.65.132:10972 (RTP seq 975 TS 1814941633 SSRC 454eec01)
```

but audio port 10792 is still forwarded:

```
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/1c531917440/1 port 10792]: [core] Handling packet: remote 91.237.65.132:10405 (expected: 91.237.65.132:10405) -> local 193.84.65.132:10792 (RTP seq 50918 TS 2678695991 SSRC 3a9e61ed)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/1 port 11561]: [core] Forward to sink endpoint: local 193.84.65.132:11561 -> remote 10.123.255.221:62937 (RTP seq 50918 TS 2678695991 SSRC 3a9e61ed)
```

While audio is forwarded (ports 10792 - 11561) video is dropped:

```
Aug  2 14:48:29 p01t-1 rtpengine[3076]: ", "result": "ok" }
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/1c531917440/2 port 10972]: [core] Handling packet: remote 91.237.65.132:10410 (expected: 91.237.65.132:10410) -> local 193.84.65.132:10972 (RTP seq 976 TS 1814941633 SSRC 454eec01)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/1c531917440/2 port 10972]: [core] Handling packet: remote 91.237.65.132:10410 (expected: 91.237.65.132:10410) -> local 193.84.65.132:10972 (RTP seq 977 TS 1814941633 SSRC 454eec01)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/1 port 11561]: [core] Handling packet: remote 10.123.255.221:62937 (expected: 10.123.255.221:62937) -> local 193.84.65.132:11561 (RTP seq 24241 TS 3242274125 SSRC 9f6c35ba)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/1c531917440/1 port 10792]: [core] Forward to sink endpoint: local 193.84.65.132:10792 -> remote 91.237.65.132:10405 (RTP seq 24241 TS 3242274125 SSRC 9f6c35ba)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/1c531917440/2 port 10972]: [core] Handling packet: remote 91.237.65.132:10410 (expected: 91.237.65.132:10410) -> local 193.84.65.132:10972 (RTP seq 978 TS 1814941633 SSRC 454eec01)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/1c531917440/2 port 10972]: [core] Handling packet: remote 91.237.65.132:10410 (expected: 91.237.65.132:10410) -> local 193.84.65.132:10972 (RTP seq 979 TS 1814941633 SSRC 454eec01)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/1 port 11561]: [core] Handling packet: remote 10.123.255.221:62937 (expected: 10.123.255.221:62937) -> local 193.84.65.132:11561 (RTP seq 24242 TS 3242274285 SSRC 9f6c35ba)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/1c531917440/1 port 10792]: [core] Forward to sink endpoint: local 193.84.65.132:10792 -> remote 91.237.65.132:10405 (RTP seq 24242 TS 3242274285 SSRC 9f6c35ba)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/1c531917440/1 port 10792]: [core] Handling packet: remote 91.237.65.132:10405 (expected: 91.237.65.132:10405) -> local 193.84.65.132:10792 (RTP seq 50919 TS 2678696151 SSRC 3a9e61ed)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/1 port 11561]: [core] Forward to sink endpoint: local 193.84.65.132:11561 -> remote 10.123.255.221:62937 (RTP seq 50919 TS 2678696151 SSRC 3a9e61ed)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2 port 10069]: [core] Handling packet: remote 10.123.255.221:52064 (expected: 10.123.255.221:52064) -> local 193.84.65.132:10069 (RTP seq 19646 TS 17454095 SSRC 3034df99)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: ERR: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2 port 10069]: [srtp] SRTP output wanted, but no crypto suite was negotiated
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2 port 10069]: [core] Handling packet: remote 10.123.255.221:52064 (expected: 10.123.255.221:52064) -> local 193.84.65.132:10069 (RTP seq 19647 TS 17454095 SSRC 3034df99)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2 port 10069]: [core] Handling packet: remote 10.123.255.221:52064 (expected: 10.123.255.221:52064) -> local 193.84.65.132:10069 (RTP seq 19648 TS 17454095 SSRC 3034df99)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2 port 10069]: [core] Handling packet: remote 10.123.255.221:52064 (expected: 10.123.255.221:52064) -> local 193.84.65.132:10069 (RTP seq 19649 TS 17454095 SSRC 3034df99)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2 port 10069]: [core] Handling packet: remote 10.123.255.221:52064 (expected: 10.123.255.221:52064) -> local 193.84.65.132:10069 (RTP seq 19650 TS 17454095 SSRC 3034df99)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2 port 10069]: [core] Handling packet: remote 10.123.255.221:52064 (expected: 10.123.255.221:52064) -> local 193.84.65.132:10069 (RTP seq 19651 TS 17454095 SSRC 3034df99)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2 port 10069]: [core] Handling packet: remote 10.123.255.221:52064 (expected: 10.123.255.221:52064) -> local 193.84.65.132:10069 (RTP seq 19652 TS 17454095 SSRC 3034df99)
```

then the 200 OK:

```
Aug  2 14:48:29 p01t-1 rtpengine[3076]: INFO: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [control] Received command 'answer' from 10.55.33.129:53229
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [control] Dump for 'answer' from 10.55.33.129:53229: { "supports": [ "load limit" ], "sdp": "v=0
...
Aug  2 14:48:29 p01t-1 rtpengine[3076]: m=audio 10405 RTP/AVP 9 101
...
Aug  2 14:48:29 p01t-1 rtpengine[3076]: m=video 10410 RTP/AVP 102
...
Aug  2 14:48:29 p01t-1 rtpengine[3076]: ", "DTLS": "passive", "flags": [ "trust-address", "pad-crypto" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "UDP/TLS/RTP/SAVPF", "rtcp-mux": [ "accept", "require" ], "call-id": "o-5hD0BCZsxNeV6ijjJvOi-C
Q-100-", "via-branch": "z9hG4bK1044972", "received-from": [ "IP4", "192.168.48.74" ], "from-tag": "dk78v8tpq1", "to-tag": "1c531917440", "command": "answer" }
```

anwser from RTPEngine: watch out: RTPENGINE also sets up the same ICE ID for audio and video:

```
Aug  2 14:48:29 p01t-1 rtpengine[3076]: INFO: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [control] Replying to 'answer' from 10.55.33.129:53229 (elapsed time 0.000876 sec)
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [control] Response dump for 'answer' to 10.55.33.129:53229: { "sdp": "v=0
Aug  2 14:48:29 p01t-1 rtpengine[3076]: o=- 152450196 1573096262 IN IP4 193.84.65.132
Aug  2 14:48:29 p01t-1 rtpengine[3076]: s=pjmedia
Aug  2 14:48:29 p01t-1 rtpengine[3076]: t=0 0
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-lite
Aug  2 14:48:29 p01t-1 rtpengine[3076]: m=audio 11561 UDP/TLS/RTP/SAVPF 9 101
...
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=tls-id:341b2760440a14652d9c02f8532f6d51
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-ufrag:fMeAXdxv
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-pwd:IFQEkD2fjncPmaSmfFiN3HnSHQ
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-options:trickle
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=candidate:uz7akZM3T4eiw64N 1 UDP 2130706431 193.84.65.132 11561 typ host
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=end-of-candidates
Aug  2 14:48:29 p01t-1 rtpengine[3076]: m=video 10069 UDP/TLS/RTP/SAVPF 102
...
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=setup:passive
...
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=tls-id:fbf972dbb6b79e38f73e853899763473
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-ufrag:nqetXVL2
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-pwd:EO3VngkxQ0yw4Vop6iSA0RraLU
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-options:trickle
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=candidate:uz7akZM3T4eiw64N 1 UDP 2130706431 193.84.65.132 10069 typ host
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=end-of-candidates
Aug  2 14:48:29 p01t-1 rtpengine[3076]: ", "result": "ok" }
Aug  2 14:48:29 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2 port 10069]: [core] Ignoring stray RTCP packet from 10.123.255.221:52064 for peer address confirmation purposes
```

received traffic on port 10972 (RTP video) is not handled any more.
received traffic von port 10972 (SRTP video) seems to be decrypted (`port 10069]: [srtp] Crypto debug: RTCP SSRC 99df3430`), but is not forwarded any more.

Use less filter `/10972|10069` to mark video ports in log.

Full debug log attached.

Pls advice - I'm looking into this for days now :-) Tried several options on reInvite in call to rtpmanage() without any difference in result.

Many thanks!
Walter
reInvite_video_not_handled.log

Richard Fuchs

unread,
Aug 2, 2023, 11:07:27 AM8/2/23
to rtpe...@googlegroups.com
On 02/08/2023 09.53, [EXT] Walter Schober wrote:
> Aug  2 14:48:29 p01t-1 rtpengine[3076]: INFO:
> [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [crypto] ICE restart without TLS-ID,
> restarting DTLS

This mention of ICE restart makes me suspicious. What did the original
offer/answer exchange look like?

Cheers

Walter Schober

unread,
Aug 2, 2023, 11:31:52 AM8/2/23
to rtpengine
Kamailio does (you see: I tried with trickle, no ice-lit, with ice-lite, differently on reInivte/initial Invite):

```
        if ($proto =~ "ws") {
                # web rtc--> SIP : DECRYPT DTLS
                xlog("L_INFO", "> WebRTC -> SIP, bridging SRTP-DTLS->RTP and removing ICE - $avp(rtpp-cid)");
                # INBOUND_CODEC: filter codes, adds AMR_WB, if WITH_AMR is defined
                #$avp(_R) = $avp(_R) + " rtcp-mux-demux DTLS=off SDES-off ICE=remove ICE-lite=backward RTP/AVPF INBOUND_CODEC";
                $avp(_R) = $avp(_R) + " rtcp-mux-demux";
                #if (!isflagset(FL_LOOSE)) $avp(_R) = $avp(_R) + " DTLS=off SDES-off ICE=remove ICE-lite=backward"; # ICE only on initial setup
                if (!isflagset(FL_LOOSE)) $avp(_R) = $avp(_R) + " DTLS=off SDES-off ICE=remove"; # no ICE lite
                if (isflagset(FL_LOOSE)) $avp(_R) = $avp(_R) + " reuse-codecs";
                $avp(_R) = $avp(_R) + " RTP/AVP INBOUND_CODEC";
        } else if ($dP =~ "ws" || isbflagset(FLB_DTLS)) {
                xlog("L_INFO", "> SIP -> WebRTC, bridging RTP->SRTP-DTLS and adding ICE - $avp(rtpp-cid)");
                #$avp(_R) = $avp(_R) + " rtcp-mux-accept rtcp-mux-require generate-mid DTLS=passive ICE=force ICE-lite=forward UDP/TLS/RTP/SAVPF SDES-off pad-crypto";
                $avp(_R) = $avp(_R) + " rtcp-mux-accept rtcp-mux-require DTLS=passive";
                #if (!isflagset(FL_LOOSE)) $avp(_R) = $avp(_R) + " SDES-off ICE=force ICE-lite=forward"; # ICE only on initial setup
                if (!isflagset(FL_LOOSE)) $avp(_R) = $avp(_R) + " SDES-off ICE=force trickle-ICE"; # no ICE lite
                if (isflagset(FL_LOOSE)) $avp(_R) = $avp(_R) + " reuse-codecs";
                $avp(_R) = $avp(_R) + " UDP/TLS/RTP/SAVPF pad-crypto";
```

This resulted at that moment of the call into:

```
Aug  2 14:47:41 p01t-1 rtpengine[3076]: INFO: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [control] Received command 'offer' from 10.55.33.129:53229
Aug  2 14:47:41 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [control] Dump for 'offer' from 10.55.33.129:53229: { "supports": [ "load limit" ], "sdp": "v=0
Aug  2 14:47:41 p01t-1 rtpengine[3076]: o=- 152450196 1573096261 IN IP4 91.237.65.132
Aug  2 14:47:41 p01t-1 rtpengine[3076]: s=pjmedia
Aug  2 14:47:41 p01t-1 rtpengine[3076]: c=IN IP4 91.237.65.132
Aug  2 14:47:41 p01t-1 rtpengine[3076]: t=0 0
Aug  2 14:47:41 p01t-1 rtpengine[3076]: m=audio 10405 RTP/AVP 9 8 103 101 121
Aug  2 14:47:41 p01t-1 rtpengine[3076]: b=TIAS:96000
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=sendrecv
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtcp:10406 IN IP4 91.237.65.132
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtpmap:9 G722/8000
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtpmap:8 PCMA/8000
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtpmap:103 OPUS/48000/2
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=fmtp:103 minptime=20; maxplaybackrate=16000; maxaveragebitrate=50000; useinbandfec=1
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtpmap:101 telephone-event/8000
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=fmtp:101 0-15
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtpmap:121 telephone-event/48000
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=fmtp:121 0-15
Aug  2 14:47:41 p01t-1 rtpengine[3076]: m=video 10410 RTP/AVP 102 97 96
Aug  2 14:47:41 p01t-1 rtpengine[3076]: i=1·VIDEO½49809½Walter½22
Aug  2 14:47:41 p01t-1 rtpengine[3076]: c=IN IP4 91.237.65.132
Aug  2 14:47:41 p01t-1 rtpengine[3076]: b=TIAS:1024000
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=sendrecv
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtpmap:102 VP8/90000
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=fmtp:102 max-fr=30; max-fs=8576
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtpmap:97 H264/90000
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=fmtp:97 profile-level-id=42e028; packetization-mode=1
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtpmap:96 H263-1998/90000
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=fmtp:96 CIF=1;QCIF=1
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=ssrc:1162800129 cname:102b697f121b1924
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtcp:10411 IN IP4 91.237.65.132
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtcp-fb:* nack pli
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=label:1
Aug  2 14:47:41 p01t-1 rtpengine[3076]: ", "DTLS": "passive", "ICE": "force", "ICE-lite": "forward", "flags": [ "trust-address", "pad-crypto" ], "replace": [ "origin", "session-connection" ], "transport-protocol": "UDP/TLS/RTP/SAVPF", "rtcp-mux": [ "accept", "require" ], "SDES": [ "off" ], "call-id": "o-5hD0BCZsxNeV6ijjJvOi-CQ-100-", "via-branch": "z9hG4bKQbByrBOYeo", "received-from": [ "IP4", "192.168.48.74" ], "from-tag": "1c531917440", "command": "offer" }
...
Aug  2 14:47:41 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [crypto] Creating passive DTLS connection context
Aug  2 14:47:41 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [crypto] Creating passive DTLS connection context
Aug  2 14:47:41 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [crypto] Creating passive DTLS connection context
Aug  2 14:47:41 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [crypto] Creating passive DTLS connection context
Aug  2 14:47:41 p01t-1 rtpengine[3076]: INFO: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [control] Replying to 'offer' from 10.55.33.129:53229 (elapsed time 0.005313 sec)
Aug  2 14:47:41 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [control] Response dump for 'offer' to 10.55.33.129:53229: { "sdp": "v=0
Aug  2 14:47:41 p01t-1 rtpengine[3076]: o=- 152450196 1573096261 IN IP4 193.84.65.132
Aug  2 14:47:41 p01t-1 rtpengine[3076]: s=pjmedia
Aug  2 14:47:41 p01t-1 rtpengine[3076]: c=IN IP4 193.84.65.132
Aug  2 14:47:41 p01t-1 rtpengine[3076]: t=0 0
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=ice-lite
Aug  2 14:47:41 p01t-1 rtpengine[3076]: m=audio 11561 UDP/TLS/RTP/SAVPF 9 8 103 101 121
Aug  2 14:47:41 p01t-1 rtpengine[3076]: b=TIAS:96000
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtpmap:9 G722/8000
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtpmap:8 PCMA/8000
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtpmap:103 OPUS/48000/2
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=fmtp:103 useinbandfec=1; maxplaybackrate=16000; maxaveragebitrate=50000; minptime=20
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtpmap:101 telephone-event/8000
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=fmtp:101 0-15
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtpmap:121 telephone-event/48000
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=fmtp:121 0-15
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=sendrecv
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtcp:11561
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtcp-mux
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=setup:actpass
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=fingerprint:sha-256 04:5F:A1:79:2B:24:43:4D:72:CF:A7:1D:8A:FC:40:2D:62:68:AA:52:7A:E7:BC:D2:39:23:18:F9:A2:57:4B:F2
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=tls-id:341b2760440a14652d9c02f8532f6d51
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=ice-ufrag:fMeAXdxv
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=ice-pwd:IFQEkD2fjncPmaSmfFiN3HnSHQ
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=candidate:uz7akZM3T4eiw64N 1 UDP 2130706431 193.84.65.132 11561 typ host
Aug  2 14:47:41 p01t-1 rtpengine[3076]: m=video 10069 UDP/TLS/RTP/SAVPF 102 97 96
Aug  2 14:47:41 p01t-1 rtpengine[3076]: i=1·VIDEO½49809½Walter½22
Aug  2 14:47:41 p01t-1 rtpengine[3076]: c=IN IP4 193.84.65.132
Aug  2 14:47:41 p01t-1 rtpengine[3076]: b=TIAS:1024000
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=ssrc:1162800129 cname:102b697f121b1924
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtcp-fb:* nack pli
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=label:1
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtpmap:102 VP8/90000
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=fmtp:102 max-fr=30; max-fs=8576
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtpmap:97 H264/90000
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=fmtp:97 profile-level-id=42e028; packetization-mode=1
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtpmap:96 H263-1998/90000
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=fmtp:96 CIF=1;QCIF=1
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=sendrecv
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtcp:10069
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=rtcp-mux
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=setup:actpass
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=fingerprint:sha-256 04:5F:A1:79:2B:24:43:4D:72:CF:A7:1D:8A:FC:40:2D:62:68:AA:52:7A:E7:BC:D2:39:23:18:F9:A2:57:4B:F2
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=tls-id:c96e41cac0847a5f73ba7f1a70f0ab85
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=ice-ufrag:WhRdtQmE
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=ice-pwd:EOVw51qINK2wNwzMyb51klwZWE
Aug  2 14:47:41 p01t-1 rtpengine[3076]: a=candidate:uz7akZM3T4eiw64N 1 UDP 2130706431 193.84.65.132 10069 typ host
Aug  2 14:47:41 p01t-1 rtpengine[3076]: ", "result": "ok" }
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-//2 port 10069]: [ice] Created candidate pair uz7akZM3T4eiw64N:fc2c252b37e6d2790:1 between 193.84.65.132 and 193.84.65.130:61130, type prflx
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-//2 port 10069]: [core] Successful STUN binding request from 193.84.65.130:61130
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-//1 port 11561]: [ice] Created candidate pair uz7akZM3T4eiw64N:fc2c2b8637e6d2790:1 between 193.84.65.132 and 193.84.65.130:57447, type prflx
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-//1 port 11561]: [core] Successful STUN binding request from 193.84.65.130:57447
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-//2 port 10069]: [srtp] Processing incoming DTLS packet
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-//1 port 11561]: [srtp] Processing incoming DTLS packet
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-//2 port 10069]: [srtp] Sending DTLS packet
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-//1 port 11561]: [srtp] Sending DTLS packet
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-//2 port 10069]: [srtp] Processing incoming DTLS packet
```

with the answer:

```
Aug  2 14:47:44 p01t-1 rtpengine[3076]: INFO: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [control] Received command 'answer' from 10.55.33.129:59321
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [control] Dump for 'answer' from 10.55.33.129:59321: { "supports": [ "load limit" ], "sdp": "v=0
Aug  2 14:47:44 p01t-1 rtpengine[3076]: o=- 2290955861283766428 2 IN IP4 127.0.0.1
Aug  2 14:47:44 p01t-1 rtpengine[3076]: s=WebRTC session
Aug  2 14:47:44 p01t-1 rtpengine[3076]: t=0 0
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=msid-semantic: WMS d5822d97-23c7-4203-8edd-a0770cece28f
Aug  2 14:47:44 p01t-1 rtpengine[3076]: m=audio 57447 UDP/TLS/RTP/SAVPF 9 8 103 101 121
Aug  2 14:47:44 p01t-1 rtpengine[3076]: c=IN IP4 91.237.65.129
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtcp:9 IN IP4 192.168.229.217
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=candidate:4062660976 1 udp 2122260223 192.168.41.91 57447 typ host generation 0 network-id 1
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=candidate:3237821287 1 udp 2122194687 10.123.255.221 62937 typ host generation 0 network-id 2
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=candidate:4079434582 1 udp 1686052607 91.237.65.129 57447 typ srflx raddr 192.168.41.91 rport 57447 generation 0 network-id 1
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ice-ufrag:hWob
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ice-pwd:fAyQicrTCmoG3y2tczi94gll
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ice-options:trickle
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=fingerprint:sha-256 1E:9C:83:6B:15:B2:A5:55:34:AF:C7:C1:E2:73:A3:84:38:86:55:5C:43:F4:04:29:FB:B0:F9:A0:50:24:E0:3A
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=setup:active
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=mid:0
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=sendrecv
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=msid:d5822d97-23c7-4203-8edd-a0770cece28f 68ff392f-df15-4fde-afb1-d740d60efc45
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtcp-mux
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtpmap:9 G722/8000
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtpmap:8 PCMA/8000
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtpmap:103 OPUS/48000/2
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=fmtp:103 minptime=10;useinbandfec=1
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtpmap:101 telephone-event/8000
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtpmap:121 telephone-event/48000
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ssrc:2674668986 cname:Nr8NOa7VxnTBQXe7
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ssrc:2674668986 msid:d5822d97-23c7-4203-8edd-a0770cece28f 68ff392f-df15-4fde-afb1-d740d60efc45
Aug  2 14:47:44 p01t-1 rtpengine[3076]: m=video 61130 UDP/TLS/RTP/SAVPF 102 97
Aug  2 14:47:44 p01t-1 rtpengine[3076]: i=1·VIDEO½50013½Walter½21
Aug  2 14:47:44 p01t-1 rtpengine[3076]: c=IN IP4 91.237.65.129
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtcp:9 IN IP4 192.168.229.217
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=candidate:4062660976 1 udp 2122260223 192.168.41.91 61130 typ host generation 0 network-id 1
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=candidate:3237821287 1 udp 2122194687 10.123.255.221 52064 typ host generation 0 network-id 2
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=candidate:4079434582 1 udp 1686052607 91.237.65.129 61130 typ srflx raddr 192.168.41.91 rport 61130 generation 0 network-id 1
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ice-ufrag:ukDb
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ice-pwd:0f7Z0gWMDxutXfCOFgdthOCa
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ice-options:trickle
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=fingerprint:sha-256 1E:9C:83:6B:15:B2:A5:55:34:AF:C7:C1:E2:73:A3:84:38:86:55:5C:43:F4:04:29:FB:B0:F9:A0:50:24:E0:3A
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=setup:active
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=mid:1
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=sendrecv
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=msid:d5822d97-23c7-4203-8edd-a0770cece28f e2631945-3eef-4893-a722-5e3e8799ea7e
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtcp-mux
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtpmap:102 VP8/90000
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtcp-fb:102 nack pli
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtpmap:97 H264/90000
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtcp-fb:97 nack pli
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=fmtp:97 level-asymmetry-allowed=1;packetization-mode=1;profile-level-id=42e01f
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ssrc:808771481 cname:Nr8NOa7VxnTBQXe7
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ssrc:808771481 msid:d5822d97-23c7-4203-8edd-a0770cece28f e2631945-3eef-4893-a722-5e3e8799ea7e
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=label:1
Aug  2 14:47:44 p01t-1 rtpengine[3076]: ", "DTLS": "off", "ICE": "remove", "ICE-lite": "backward", "flags": [ "trust-address" ], "replace": [ "origin", "session-connection" ], "codec": { "strip": [ "PCMU" ], "mask": [ "PCMA" ], "except": [ "OPUS", "G722" ], "transcode": [ "PCMA", "telephone-
event" ] }, "transport-protocol": "RTP/AVP", "rtcp-mux": [ "demux" ], "SDES": [ "off" ], "call-id": "o-5hD0BCZsxNeV6ijjJvOi-CQ-100-", "via-branch": "z9hG4bKQbByrBOYeo", "received-from": [ "IP4", "10.123.255.221" ], "from-tag": "1c531917440", "to-tag": "dk78v8tpq1", "command": "answer" }
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-//2 port 10069]: [crypto] DTLS handshake successful
Aug  2 14:47:44 p01t-1 rtpengine[3076]: INFO: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-//2 port 10069]: [crypto] DTLS-SRTP successfully negotiated using AEAD_AES_256_GCM

... bla DTLS-SRTP success ...

Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] set FILLED flag for stream, local 193.84.65.132:11561 remote 91.237.65.129:57447
Aug  2 14:47:44 p01t-1 rtpengine[3076]: INFO: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [crypto] DTLS: Peer certificate accepted
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] set FILLED flag for stream, local 193.84.65.132:0 remote 192.168.229.217:9
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/1]: [ice] Learning new ICE candidate 4062660976:1
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/1]: [ice] Created candidate pair uz7akZM3T4eiw64N:4062660976:1 between 193.84.65.132 and 192.168.41.91:57447, type host
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/1]: [ice] Learning new ICE candidate 3237821287:1
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/1]: [ice] Created candidate pair uz7akZM3T4eiw64N:3237821287:1 between 193.84.65.132 and 10.123.255.221:62937, type host
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/1]: [ice] Learning new ICE candidate 4079434582:1
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/1]: [ice] Created candidate pair uz7akZM3T4eiw64N:4079434582:1 between 193.84.65.132 and 91.237.65.129:57447, type srflx
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] set FILLED flag for stream, local 193.84.65.132:10069 remote 91.237.65.129:61130
Aug  2 14:47:44 p01t-1 rtpengine[3076]: INFO: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [crypto] DTLS: Peer certificate accepted
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [core] set FILLED flag for stream, local 193.84.65.132:0 remote 192.168.229.217:9
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2]: [ice] Learning new ICE candidate 4062660976:1
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2]: [ice] Created candidate pair uz7akZM3T4eiw64N:4062660976:1 between 193.84.65.132 and 192.168.41.91:61130, type host
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2]: [ice] Learning new ICE candidate 3237821287:1
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2]: [ice] Created candidate pair uz7akZM3T4eiw64N:3237821287:1 between 193.84.65.132 and 10.123.255.221:52064, type host
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2]: [ice] Learning new ICE candidate 4079434582:1
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-/dk78v8tpq1/2]: [ice] Created candidate pair uz7akZM3T4eiw64N:4079434582:1 between 193.84.65.132 and 91.237.65.129:61130, type srflx
Aug  2 14:47:44 p01t-1 rtpengine[3076]: INFO: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [control] Replying to 'answer' from 10.55.33.129:59321 (elapsed time 0.003052 sec)
Aug  2 14:47:44 p01t-1 rtpengine[3076]: DEBUG: [o-5hD0BCZsxNeV6ijjJvOi-CQ-100-]: [control] Response dump for 'answer' to 10.55.33.129:59321: { "sdp": "v=0
Aug  2 14:47:44 p01t-1 rtpengine[3076]: o=- 2290955861283766428 2 IN IP4 193.84.65.132
Aug  2 14:47:44 p01t-1 rtpengine[3076]: s=WebRTC session
Aug  2 14:47:44 p01t-1 rtpengine[3076]: t=0 0
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=msid-semantic: WMS d5822d97-23c7-4203-8edd-a0770cece28f
Aug  2 14:47:44 p01t-1 rtpengine[3076]: m=audio 10792 RTP/AVP 9 8 103 101 121
Aug  2 14:47:44 p01t-1 rtpengine[3076]: c=IN IP4 193.84.65.132
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=msid:d5822d97-23c7-4203-8edd-a0770cece28f 68ff392f-df15-4fde-afb1-d740d60efc45
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ssrc:2674668986 cname:Nr8NOa7VxnTBQXe7
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ssrc:2674668986 msid:d5822d97-23c7-4203-8edd-a0770cece28f 68ff392f-df15-4fde-afb1-d740d60efc45
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtpmap:9 G722/8000
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtpmap:8 PCMA/8000
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtpmap:103 OPUS/48000/2
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=fmtp:103 useinbandfec=1; minptime=10
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtpmap:101 telephone-event/8000
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtpmap:121 telephone-event/48000
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=sendrecv
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtcp:10793
Aug  2 14:47:44 p01t-1 rtpengine[3076]: m=video 10972 RTP/AVP 102 97
Aug  2 14:47:44 p01t-1 rtpengine[3076]: i=1·VIDEO½50013½Walter½21
Aug  2 14:47:44 p01t-1 rtpengine[3076]: c=IN IP4 193.84.65.132
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=msid:d5822d97-23c7-4203-8edd-a0770cece28f e2631945-3eef-4893-a722-5e3e8799ea7e
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ssrc:808771481 cname:Nr8NOa7VxnTBQXe7
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ssrc:808771481 msid:d5822d97-23c7-4203-8edd-a0770cece28f e2631945-3eef-4893-a722-5e3e8799ea7e
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=label:1
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtpmap:102 VP8/90000
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtcp-fb:102 nack pli
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtpmap:97 H264/90000
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=fmtp:97 level-asymmetry-allowed=1;packetization-mode=1;profile-level-id=42e01f
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtcp-fb:97 nack pli
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=sendrecv
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=rtcp:10973
Aug  2 14:47:44 p01t-1 rtpengine[3076]: ", "result": "ok" }
```

Here you can see that ICE candidates from the video section are also "learned".

Attached the full call log now.

lg
Walter

full-debug.log.gz

Richard Fuchs

unread,
Aug 2, 2023, 11:50:13 AM8/2/23
to rtpe...@googlegroups.com
On 02/08/2023 11.31, [EXT] Walter Schober wrote:
Attached the full call log now.

It sure looks like the client is doing an ICE restart. The first answer from the client has:

Aug  2 14:47:44 p01t-1 rtpengine[3076]: m=audio 57447 UDP/TLS/RTP/SAVPF 9 8 103 101 121
Aug  2 14:47:44 p01t-1 rtpengine[3076]: c=IN IP4 91.237.65.129

...
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ice-ufrag:hWob


Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ice-pwd:fAyQicrTCmoG3y2tczi94gll
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ice-options:trickle
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=fingerprint:sha-256 1E:9C:83:6B:15:B2:A5:55:34:AF:C7:C1:E2:73:A3:84:38:86:55:5C:43:F4:04:29:FB:B0:F9:A0:50:24:E0:3A
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=setup:active

...
Aug  2 14:47:44 p01t-1 rtpengine[3076]: m=video 61130 UDP/TLS/RTP/SAVPF 102 97


Aug  2 14:47:44 p01t-1 rtpengine[3076]: i=1·VIDEO½50013½Walter½21
Aug  2 14:47:44 p01t-1 rtpengine[3076]: c=IN IP4 91.237.65.129

...
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ice-ufrag:ukDb


Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ice-pwd:0f7Z0gWMDxutXfCOFgdthOCa
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=ice-options:trickle
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=fingerprint:sha-256 1E:9C:83:6B:15:B2:A5:55:34:AF:C7:C1:E2:73:A3:84:38:86:55:5C:43:F4:04:29:FB:B0:F9:A0:50:24:E0:3A
Aug  2 14:47:44 p01t-1 rtpengine[3076]: a=setup:active

But the re-invite from the same client has:

Aug  2 14:48:29 p01t-1 rtpengine[3076]: m=audio 57447 UDP/TLS/RTP/SAVPF 9 103 0 8 101 121
Aug  2 14:48:29 p01t-1 rtpengine[3076]: c=IN IP4 91.237.65.129
...
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-ufrag:hWob
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-pwd:fAyQicrTCmoG3y2tczi94gll
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-options:trickle
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=fingerprint:sha-256 1E:9C:83:6B:15:B2:A5:55:34:AF:C7:C1:E2:73:A3:84:38:86:55:5C:43:F4:04:29:FB:B0:F9:A0:50:24:E0:3A
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=setup:actpass
...
Aug  2 14:48:29 p01t-1 rtpengine[3076]: m=video 61130 UDP/TLS/RTP/SAVPF 102 98 100 97 127 104 108 110 39 112
Aug  2 14:48:29 p01t-1 rtpengine[3076]: i=1·VIDEO½50013½Walter½21
Aug  2 14:48:29 p01t-1 rtpengine[3076]: c=IN IP4 91.237.65.129
...
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-ufrag:hWob
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-pwd:fAyQicrTCmoG3y2tczi94gll
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=ice-options:trickle
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=fingerprint:sha-256 1E:9C:83:6B:15:B2:A5:55:34:AF:C7:C1:E2:73:A3:84:38:86:55:5C:43:F4:04:29:FB:B0:F9:A0:50:24:E0:3A
Aug  2 14:48:29 p01t-1 rtpengine[3076]: a=setup:actpass

Relevant portions highlighted.

A change in ICE ufrag indicates an ICE restart. This only happens for the video stream. A ICE restart would entail a new DTLS connection as well (although the RFCs are a bit ambiguous here, which is why `a=tls-id` is a thing).

Since the client is playing the active role, it would be up to the client to establish a new DTLS connection, after doing a fresh ICE handshake. But this doesn't happen, and so the connection breaks.

It could be that the client is confused about the BUNDLE negotiation against rtpengine, but most likely it should not indicate an ICE restart at all.

Cheers

Walter Schober

unread,
Aug 2, 2023, 11:55:18 AM8/2/23
to rtpengine
Thank you very much helping out here! I will forward this to our client developer and ask for this specific behaviour. Strange enough the same client works with Audiocodes SBC. But there is less log about DTLS and ICE restarts at all.
I'm curious if this is a Google Chrome Browser thing or the WebApp itself ... Always thought WebRTC is done by the browser.

lg
Walter

Richard Fuchs

unread,
Aug 2, 2023, 12:07:07 PM8/2/23
to rtpe...@googlegroups.com
On 02/08/2023 11.55, [EXT] Walter Schober wrote:
> Thank you very much helping out here! I will forward this to our
> client developer and ask for this specific behaviour. Strange enough
> the same client works with Audiocodes SBC. But there is less log about
> DTLS and ICE restarts at all.

Could be that Audiocodes has proper BUNDLE support, which is one thing
that rtpengine is still missing for better WebRTC support.

Cheers

Walter Schober

unread,
Aug 2, 2023, 12:37:53 PM8/2/23
to rtpengine
No, Audiocodes has no BUNDLE support (in the 7.40 stable release), too. Not checked, if they have it in the latest unstable one.
Checked too: Audiocodes is answering with `a=setup:passive`, too. So it also does not change to active mode here. So I assume they just do no ICE restart. Anyway, off topic. We will fix the client.

Tried to force rtpengie to change to a:setup=active in the reInvite 200 response, but was not lucky yet.

Walter Schober

unread,
Aug 8, 2023, 9:32:05 PM8/8/23
to rtpengine
Hi!

Surprising feedback from the client developer: It is not the app, it is the Google Chrome's WebRTC stack doing this. And we would need to have high efforts doing a workaround in the client. Well, it's only another opinion.

I wonder: No one out there is using a WebRTC client on Google Chrome with Video together with RTPEngine and Session Timers? Or reInvites the video stream?
Well, then I'll have to talk to Google....

br
Walter

Walter Schober

unread,
Sep 21, 2023, 7:53:17 AM9/21/23
to rtpengine
Hi Richard!

Back from vacation and did some more research and more testing.
Findings:

* "Browser Phone" on Firefox and Chrome (so using an other App, SIP.js 0.20.0) has the same behaviour. Although there is no Session Timer support the situation is the unpredictable with hold/unhold. Needs more debugging.
* Firefox use same ufrag value in initial INVITE in audio and video SDP body, but still video is broken after reInvite. Needs more debugging.
* More readings of RFC8842 indicate that ICE restart can occur without DTLS restart.

RFC 8842 states in chapter 1:

[...] but the ufrag value is changed both when ICE is negotiated and when ICE restart [RFC8445] occurs.
These events do not always require a new DTLS association to be established, [...]

And in chapter 3.1:
A new DTLS association must be established between two endpoints after a successful SDP offer/answer exchange in the following cases:

* The negotiated DTLS setup roles change; or
* One or more fingerprint values are modified, added, or removed in either an SDP offer or answer; or
* The intent to establish a new DTLS association is explicitly signaled using SDP, by changing the value of the SDP "tls-id" attribute defined in this document;

The JavaScript Session Establishment Protocol (draft-ietf-rtcweb-jsep-latest) states in chapter 5.11:

If an ICE restart is performed without a change in tls-id or fingerprint, then the same DTLS connection is continued over the new ICE channel.

This seems to be what Chrome does.

I saw in a wireshark trace, that after changing the ufrag in the session refresh, it actually performed an ICE restart, sending STUN messages using the new ufrag pair.
But it did not send a DTLS client hello, since the fingerprints were unmodified.

The AudioCodes SBC seems to understand this, video continued.

Any comments on this? I can provide more traces with rtpengine-20230917 daily build - still the same there.

It would be very nice if rtpengine could deal with session-timer reInvites with WebRTC on Google Chrome. I wonder that nobody uses Session Timer.

br
Walter

Richard Fuchs

unread,
Sep 21, 2023, 12:38:48 PM9/21/23
to rtpe...@googlegroups.com
On 21/09/2023 07.53, [EXT] Walter Schober wrote:
RFC 8842 states in chapter 1:

[...] but the ufrag value is changed both when ICE is negotiated and when ICE restart [RFC8445] occurs.
These events do not always require a new DTLS association to be established, [...]

And in chapter 3.1:
A new DTLS association must be established between two endpoints after a successful SDP offer/answer exchange in the following cases:

* The negotiated DTLS setup roles change; or
* One or more fingerprint values are modified, added, or removed in either an SDP offer or answer; or
* The intent to establish a new DTLS association is explicitly signaled using SDP, by changing the value of the SDP "tls-id" attribute defined in this document;

The JavaScript Session Establishment Protocol (draft-ietf-rtcweb-jsep-latest) states in chapter 5.11:

If an ICE restart is performed without a change in tls-id or fingerprint, then the same DTLS connection is continued over the new ICE channel.

This seems to be what Chrome does.

I saw in a wireshark trace, that after changing the ufrag in the session refresh, it actually performed an ICE restart, sending STUN messages using the new ufrag pair.
But it did not send a DTLS client hello, since the fingerprints were unmodified.

The AudioCodes SBC seems to understand this, video continued.

Any comments on this? I can provide more traces with rtpengine-20230917 daily build - still the same there.

I've mostly lost the context on this in the meantime, but from what I remember:

The problem is that in the absence of `tls-id` there is ambiguity of whether an ICE restart also requires a DTLS restart.

In rtpengine we used to have the behaviour that an ICE restart doesn't implicitly also restart DTLS, but this caused audio breakage in certain scenarios: A client would restart its entire SIP/RTP stack, would send an updated offer, would indicate an ICE restart in it, and would expect to set up a new DTLS connection as well. With rtpengine then not doing a DTLS restart, you would have no audio. The client would expect a new DTLS connection, or try to set up a new one, but rtpengine would still be using the old one.

And without an implicit restart of DTLS there really wasn't a way to indicate whether a new DTLS connection ought to be used at all. An unchanged fingerprint doesn't necessarily mean that the DTLS connection wasn't reset. It just means that the certificate didn't change.

So we added support for `a=tls-id` which exists solely for that purpose, to indicate whether to restart DTLS or not. And in the absence of that attribute, the behaviour was changed to understand an ICE restart to also require a DTLS restart, in order to fix the breakage just mentioned.

There is no way to support both scenarios at the same time without explicit signalling of `a=tls-id` and without getting into the nitty-gritty of the raw contents of DTLS packets.

Cheers

Richard Fuchs

unread,
Sep 22, 2023, 9:59:08 AM9/22/23
to rtpe...@googlegroups.com
On 21/09/2023 13.29, [EXT] Walter Schober wrote:
> I try to understand what you explained here and will do some more
> debugging. The point is, that google chrome does not work with video
> and session timer refreshes.
> It is not the application, it is the browser that does this. So I
> wonder why not everybody is having this issue on a WebRTC gateway?
Can't answer that. Maybe they do? Or maybe they have support for
`a=tls-id`? Maybe someone with more experience in the WebRTC world can
answer that.
> IMHO I cannot do anything in the kamailio with some flags that help us
> out of here, correct?

We don't currently have an option to influence the behaviour here, no.
It could be added of course, but right now there isn't.

Cheers

Walter Schober

unread,
Sep 26, 2023, 1:19:06 PM9/26/23
to rtpengine
Four meassures:

* Patched RTPEngine 11.3.1.11 and reverted Patch https://github.com/sipwise/rtpengine/commit/614aa1a50ab93bd60db574da6c7cbe76f135c2fb
* disabled AMR-WB transcoding of OPUS on RTPEngine
* added to media handling towards WSS:
                if (is_request()) $avp(_R) = $avp(_R) + " ICE-lite=forward";
                else  $avp(_R) = $avp(_R) + " ICE-lite=backward";
* dtls=active all the time (like Audiocodes), since DTLS is always after STUN request (which opens SRTP NAT UDP port)

Now it is working and video stream is stable. I'm not sure if it was the AMR-WB transcoding mostly or the reverting of your patch. Will contiune, but for the moment I have a solution.

Maybe this helps someone. ;-)

Cheers!

Richard Fuchs

unread,
Sep 26, 2023, 1:40:42 PM9/26/23
to rtpe...@googlegroups.com
On 26/09/2023 13.19, [EXT] Walter Schober wrote:
> Four meassures:
>
> * Patched RTPEngine 11.3.1.11 and reverted Patch
> https://github.com/sipwise/rtpengine/commit/614aa1a50ab93bd60db574da6c7cbe76f135c2fb
> * disabled AMR-WB transcoding of OPUS on RTPEngine
> * added to media handling towards WSS:
>                 if (is_request()) $avp(_R) = $avp(_R) + "
> ICE-lite=forward";
>                 else  $avp(_R) = $avp(_R) + " ICE-lite=backward";
> * dtls=active all the time (like Audiocodes), since DTLS is always
> after STUN request (which opens SRTP NAT UDP port)
>
> Now it is working and video stream is stable. I'm not sure if it was
> the AMR-WB transcoding mostly or the reverting of your patch. Will
> contiune, but for the moment I have a solution.

Feel free to open a pull request if you want to make this optional and
include it in the mainline code.

Cheers

Hexagram_vall

unread,
Jan 30, 2026, 10:34:52 AM (3 days ago) Jan 30
to Sipwise rtpengine
Hi!
Thank you for a great product!

Is there any plans for making "use tls-id" flag or config option for old behaviour?

вторник, 26 сентября 2023 г. в 20:40:42 UTC+3, rfuchs:
Reply all
Reply to author
Forward
0 new messages