Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

DTLS rekeying causes calls to lose audio #1705

Open
dadrc opened this issue Aug 10, 2023 · 9 comments
Open

DTLS rekeying causes calls to lose audio #1705

dadrc opened this issue Aug 10, 2023 · 9 comments

Comments

@dadrc
Copy link

dadrc commented Aug 10, 2023

We've been using rtpengine 11.2.1.12 with the corresponding kernel module to connect WebRTC calls to Asterisk (16.x and 20.x) via Kamailio (5.7). This setup has been working for quite a while. After an update to basically any newer rtpengine release (we've tried 11.3.1.11 and 11.4.1.3 initially), calls lose audio after exactly 2 minutes, which corresponds to the DTLS rekeying interval specified in our Asterisk PJSIP configuration for those endpoints.

Asterisk logs unprotect errors for both SRTP and SRTCP packets:

VERBOSE[66457][C-00000012] res_srtp.c: SRTP unprotect failed on SSRC 458523204 because of authentication failure 160
VERBOSE[66457][C-00000012] res_srtp.c: SRTCP unprotect failed on SSRC 458523204 because of authentication failure

rtpengine also logs INFO and WARNING level messages:

INFO: [i6qrqdih95obm7i4auob/6eddbd88-a2d6-42bd-83cf-a41c51d78507/1 port 11248]: [crypto] DTLS data received after handshake, code: 2
INFO: [27f810d3-8b40-4464-81b5-f6f43dc62610/3bbc999a-c4ba-493b-bb81-4f719d8b3ead/1 port 10264]: [crypto] DTLS data received after handshake, code: 2
INFO: [i6qrqdih95obm7i4auob/6eddbd88-a2d6-42bd-83cf-a41c51d78507/1 port 11248]: [crypto] DTLS data received after handshake, code: 2
INFO: [27f810d3-8b40-4464-81b5-f6f43dc62610/3bbc999a-c4ba-493b-bb81-4f719d8b3ead/1 port 10264]: [crypto] DTLS data received after handshake, code: 2
INFO: [27f810d3-8b40-4464-81b5-f6f43dc62610/3bbc999a-c4ba-493b-bb81-4f719d8b3ead/1 port 10264]: [crypto] DTLS data received after handshake, code: 2
WARNING: [27f810d3-8b40-4464-81b5-f6f43dc62610/3bbc999a-c4ba-493b-bb81-4f719d8b3ead/1 port 10264]: [rtcp] Discarded invalid SRTCP packet: authentication failed
WARNING: [i6qrqdih95obm7i4auob/6eddbd88-a2d6-42bd-83cf-a41c51d78507/1 port 11248]: [rtcp] Discarded invalid SRTCP packet: authentication failed

With git bisect, we narrowed down the cause to commit 2f4f6d5. As soon as this commit is reverted, calls no longer lose audio after 2 minutes. Also, disabling DTLS rekeying for the endpoints in Asterisk fixes the issue.

We thus suspect the code added in the mentioned commit does not handle DTLS rekeying correctly.

@rfuchs
Copy link
Member

rfuchs commented Aug 10, 2023

For comparison, what does the log show during rekeying in the working version?

I guess @Den4t might be interested in this as well

@dadrc
Copy link
Author

dadrc commented Aug 10, 2023

Here's the log of a call lasting about 2 minutes 30 seconds using rtpengine master with a revert commit for 2f4f6d5 on top, no special logging configuration:

INFO: [smda3fjmoj3tvj3hefco]: [control] Received command 'offer' from 127.0.0.1:40378
NOTICE: [smda3fjmoj3tvj3hefco]: [core] Creating new call
INFO: [smda3fjmoj3tvj3hefco]: [control] Replying to 'offer' from 127.0.0.1:40378 (elapsed time 0.003673 sec)
INFO: [smda3fjmoj3tvj3hefco/9l5vtmamkk/1 port 13728]: [ice] ICE negotiated: peer for component 1 is 172.17.30.201:53133
INFO: [smda3fjmoj3tvj3hefco/9l5vtmamkk/1 port 13728]: [ice] ICE negotiated: local interface 172.17.10.19
INFO: [smda3fjmoj3tvj3hefco/9l5vtmamkk/1 port 13728]: [ice] ICE negotiated: peer for component 1 is 172.17.30.201:53133
INFO: [smda3fjmoj3tvj3hefco/9l5vtmamkk/1 port 13728]: [ice] ICE negotiated: local interface 172.17.10.19
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40]: [control] Received command 'offer' from 127.0.0.1:37919
NOTICE: [bad49ddf-514e-4b85-be9b-9db68d22cc40]: [core] Creating new call
WARNING: [bad49ddf-514e-4b85-be9b-9db68d22cc40/5578a313-4421-4938-b848-f6c65b575ab8/1]: [ice] Priority collision between candidate pairs SWNhhzdNiRqpz39s:Hc0a86402:1 and SWNhhzdNiRqpz39s:Hac110a13:1 - ICE will likely fail
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40]: [control] Replying to 'offer' from 127.0.0.1:37919 (elapsed time 0.001194 sec)
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40]: [control] Received command 'answer' from 127.0.0.1:38085
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40//1 port 17706]: [crypto] DTLS-SRTP successfully negotiated using AEAD_AES_256_GCM
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40//1 port 17706]: [crypto] DTLS-SRTP successfully negotiated using AEAD_AES_256_GCM
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40]: [crypto] DTLS: Peer certificate accepted
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40]: [control] Replying to 'answer' from 127.0.0.1:38085 (elapsed time 0.000770 sec)
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40/et8l4u4048/1 port 17706]: [ice] ICE negotiated: peer for component 1 is 172.17.30.201:48526
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40/et8l4u4048/1 port 17706]: [ice] ICE negotiated: local interface 172.17.10.19
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40/5578a313-4421-4938-b848-f6c65b575ab8/1 port 14624]: [crypto] DTLS: Peer certificate accepted
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40/et8l4u4048/1 port 17706]: [ice] ICE negotiated: peer for component 1 is 172.17.30.201:48526
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40/et8l4u4048/1 port 17706]: [ice] ICE negotiated: local interface 172.17.10.19
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40/5578a313-4421-4938-b848-f6c65b575ab8/1 port 14624]: [crypto] DTLS-SRTP successfully negotiated using AES_CM_128_HMAC_SHA1_80
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40/5578a313-4421-4938-b848-f6c65b575ab8/1 port 14624]: [crypto] DTLS-SRTP successfully negotiated using AES_CM_128_HMAC_SHA1_80
INFO: [smda3fjmoj3tvj3hefco]: [control] Received command 'answer' from 127.0.0.1:55948
INFO: [smda3fjmoj3tvj3hefco]: [control] Replying to 'answer' from 127.0.0.1:55948 (elapsed time 0.000961 sec)
INFO: [smda3fjmoj3tvj3hefco/a626be95-e213-4823-902c-571bd7b307a8/1 port 14234]: [crypto] DTLS: Peer certificate accepted
INFO: [smda3fjmoj3tvj3hefco/a626be95-e213-4823-902c-571bd7b307a8/1 port 14234]: [crypto] DTLS-SRTP successfully negotiated using AES_CM_128_HMAC_SHA1_80
INFO: [smda3fjmoj3tvj3hefco/a626be95-e213-4823-902c-571bd7b307a8/1 port 14234]: [crypto] DTLS-SRTP successfully negotiated using AES_CM_128_HMAC_SHA1_80
ERR: [smda3fjmoj3tvj3hefco/a626be95-e213-4823-902c-571bd7b307a8/1 port 14234]: [srtp] SRTP output wanted, but no crypto suite was negotiated
INFO: [smda3fjmoj3tvj3hefco/9l5vtmamkk/1 port 13728]: [ice] ICE negotiated: peer for component 1 is 172.17.30.201:53133
INFO: [smda3fjmoj3tvj3hefco/9l5vtmamkk/1 port 13728]: [ice] ICE negotiated: local interface 172.17.10.19
INFO: [smda3fjmoj3tvj3hefco/9l5vtmamkk/1 port 13728]: [crypto] DTLS: Peer certificate accepted
INFO: [smda3fjmoj3tvj3hefco/9l5vtmamkk/1 port 13728]: [crypto] DTLS-SRTP successfully negotiated using AES_CM_128_HMAC_SHA1_80
INFO: [smda3fjmoj3tvj3hefco/9l5vtmamkk/1 port 13728]: [crypto] DTLS-SRTP successfully negotiated using AES_CM_128_HMAC_SHA1_80
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40/et8l4u4048/1 port 17706]: [ice] ICE negotiated: peer for component 1 is 172.17.30.201:48526
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40/et8l4u4048/1 port 17706]: [ice] ICE negotiated: local interface 172.17.10.19
INFO: [smda3fjmoj3tvj3hefco/9l5vtmamkk/1 port 13728]: [core] Confirmed peer address as 172.17.30.201:53133
INFO: [smda3fjmoj3tvj3hefco/9l5vtmamkk/1 port 13728]: [core] Kernelizing media stream: 172.17.30.201:53133 -> 172.17.10.19:13728 | 127.0.0.1:14234 -> 127.0.50.1:16400
INFO: [smda3fjmoj3tvj3hefco/9l5vtmamkk/1 port 13728]: [core] Kernelizing media stream: 172.17.30.201:53133 -> 172.17.10.19:13728 | 127.0.0.1:14234 -> 127.0.50.1:16400
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40/5578a313-4421-4938-b848-f6c65b575ab8/1 port 14624]: [core] Confirmed peer address as 127.0.50.1:17944
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40/5578a313-4421-4938-b848-f6c65b575ab8/1 port 14624]: [core] Kernelizing media stream: 127.0.50.1:17944 -> 127.0.0.1:14624 | 172.17.10.19:17706 -> 172.17.30.201:48526
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40/5578a313-4421-4938-b848-f6c65b575ab8/1 port 14624]: [core] Kernelizing media stream: 127.0.50.1:17944 -> 127.0.0.1:14624 | 172.17.10.19:17706 -> 172.17.30.201:48526
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40/et8l4u4048/1 port 17706]: [core] Confirmed peer address as 172.17.30.201:48526
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40/et8l4u4048/1 port 17706]: [core] Kernelizing media stream: 172.17.30.201:48526 -> 172.17.10.19:17706 | 127.0.0.1:14624 -> 127.0.50.1:17944
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40/et8l4u4048/1 port 17706]: [core] Kernelizing media stream: 172.17.30.201:48526 -> 172.17.10.19:17706 | 127.0.0.1:14624 -> 127.0.50.1:17944
INFO: [smda3fjmoj3tvj3hefco/a626be95-e213-4823-902c-571bd7b307a8/1 port 14234]: [core] Confirmed peer address as 127.0.50.1:16400
INFO: [smda3fjmoj3tvj3hefco/a626be95-e213-4823-902c-571bd7b307a8/1 port 14234]: [core] Kernelizing media stream: 127.0.50.1:16400 -> 127.0.0.1:14234 | 172.17.10.19:13728 -> 172.17.30.201:53133
INFO: [smda3fjmoj3tvj3hefco/a626be95-e213-4823-902c-571bd7b307a8/1 port 14234]: [core] Kernelizing media stream: 127.0.50.1:16400 -> 127.0.0.1:14234 | 172.17.10.19:13728 -> 172.17.30.201:53133
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40/5578a313-4421-4938-b848-f6c65b575ab8/1 port 14624]: [core] Removing media stream from kernel: local 127.0.0.1:14624 (SSRC changed)
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40/5578a313-4421-4938-b848-f6c65b575ab8/1 port 14624]: [core] Kernelizing media stream: 127.0.50.1:17944 -> 127.0.0.1:14624 | 172.17.10.19:17706 -> 172.17.30.201:48526
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40/5578a313-4421-4938-b848-f6c65b575ab8/1 port 14624]: [core] Kernelizing media stream: 127.0.50.1:17944 -> 127.0.0.1:14624 | 172.17.10.19:17706 -> 172.17.30.201:48526
INFO: [smda3fjmoj3tvj3hefco/a626be95-e213-4823-902c-571bd7b307a8/1 port 14234]: [core] Removing media stream from kernel: local 127.0.0.1:14234 (SSRC changed)
INFO: [smda3fjmoj3tvj3hefco/a626be95-e213-4823-902c-571bd7b307a8/1 port 14234]: [core] Kernelizing media stream: 127.0.50.1:16400 -> 127.0.0.1:14234 | 172.17.10.19:13728 -> 172.17.30.201:53133
INFO: [smda3fjmoj3tvj3hefco/a626be95-e213-4823-902c-571bd7b307a8/1 port 14234]: [core] Kernelizing media stream: 127.0.50.1:16400 -> 127.0.0.1:14234 | 172.17.10.19:13728 -> 172.17.30.201:53133
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40]: [control] Received command 'delete' from 127.0.0.1:34667
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40]: [core] Scheduling deletion of call branch 'et8l4u4048' (via-branch '') in 30 seconds
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40]: [core] Scheduling deletion of call branch '5578a313-4421-4938-b848-f6c65b575ab8' (via-branch '') in 30 seconds
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40]: [core] Scheduling deletion of entire call in 30 seconds
INFO: [bad49ddf-514e-4b85-be9b-9db68d22cc40]: [control] Replying to 'delete' from 127.0.0.1:34667 (elapsed time 0.001087 sec)
INFO: [smda3fjmoj3tvj3hefco]: [control] Received command 'delete' from 127.0.0.1:55948
INFO: [smda3fjmoj3tvj3hefco]: [core] Scheduling deletion of call branch 'a626be95-e213-4823-902c-571bd7b307a8' (via-branch '') in 30 seconds
INFO: [smda3fjmoj3tvj3hefco]: [core] Scheduling deletion of call branch '9l5vtmamkk' (via-branch '') in 30 seconds
INFO: [smda3fjmoj3tvj3hefco]: [core] Scheduling deletion of entire call in 30 seconds
INFO: [smda3fjmoj3tvj3hefco]: [control] Replying to 'delete' from 127.0.0.1:55948 (elapsed time 0.000187 sec)

Same setup, with log-level-crypto = 7 and log-level-srtp = 7 in the attached log file rtpengine_with_debug.log.

@rfuchs
Copy link
Member

rfuchs commented Aug 10, 2023

So the rekeying is associated with an additional signalling event? An extra answer? Am I seeing this right? (Timestamps are missing from the log)

Does the additional answer indicate that DTLS should be re-established? Different fingerprint or tls-id?

@dadrc
Copy link
Author

dadrc commented Aug 10, 2023

As far as I understand it, there's no additional signaling involved in DTLS rekeying, it is done purely on a DTLS level without any SIP/SDP packets as per RFC5764. This matches the observed SIP traffic: There is no SIP traffic from the participants after the establishing OK/ACK until one party hangs up with a BYE.

Only the attached log had timestamps, sorry. Here's a "normal" log with timestamps:

Aug 10 14:12:45 rtpengine[109445]: INFO: [f45bfbaa-d62f-4d53-cd3c-cf2a5e9defa0]: [control] Received command 'delete' from 127.0.0.1:52820
Aug 10 14:12:45 rtpengine[109445]: INFO: [f45bfbaa-d62f-4d53-cd3c-cf2a5e9defa0]: [control] Replying to 'delete' from 127.0.0.1:52820 (elapsed time 0.000004 sec)
Aug 10 14:12:45 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [control] Received command 'offer' from 127.0.0.1:50703
Aug 10 14:12:45 rtpengine[109445]: NOTICE: [lvrp00nkp8ber3sulouq]: [core] Creating new call
Aug 10 14:12:45 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [control] Replying to 'offer' from 127.0.0.1:50703 (elapsed time 0.004352 sec)
Aug 10 14:12:45 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/0eofpc9nq2/1 port 19706]: [ice] ICE negotiated: peer for component 1 is 172.17.30.201:34237
Aug 10 14:12:45 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/0eofpc9nq2/1 port 19706]: [ice] ICE negotiated: local interface 172.17.10.19
Aug 10 14:12:45 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/0eofpc9nq2/1 port 19706]: [ice] ICE negotiated: peer for component 1 is 172.17.30.201:34237
Aug 10 14:12:45 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/0eofpc9nq2/1 port 19706]: [ice] ICE negotiated: local interface 172.17.10.19
Aug 10 14:12:45 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [control] Received command 'offer' from 127.0.0.1:50806
Aug 10 14:12:45 rtpengine[109445]: NOTICE: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] Creating new call
Aug 10 14:12:45 rtpengine[109445]: WARNING: [c04262e9-62bb-45de-81e5-8dfed749f05f/5e30e790-fa49-4fb6-b988-a510be9ddc69/1]: [ice] Priority collision between candidate pairs yP4eFkWM7RsbXxuz:Hc0a86402:1 and yP4eFkWM7RsbXxuz:Hac110a13:1 - ICE will likely fail
Aug 10 14:12:45 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [control] Replying to 'offer' from 127.0.0.1:50806 (elapsed time 0.001240 sec)
Aug 10 14:12:47 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f//1 port 15587]: [crypto] DTLS-SRTP successfully negotiated using AEAD_AES_256_GCM
Aug 10 14:12:47 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f//1 port 15587]: [crypto] DTLS-SRTP successfully negotiated using AEAD_AES_256_GCM
Aug 10 14:12:47 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [control] Received command 'answer' from 127.0.0.1:60056
Aug 10 14:12:47 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [crypto] DTLS: Peer certificate accepted
Aug 10 14:12:47 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [control] Replying to 'answer' from 127.0.0.1:60056 (elapsed time 0.001026 sec)
Aug 10 14:12:47 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f/cvgcimqmr8/1 port 15587]: [ice] ICE negotiated: peer for component 1 is 172.17.30.201:51150
Aug 10 14:12:47 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f/cvgcimqmr8/1 port 15587]: [ice] ICE negotiated: local interface 172.17.10.19
Aug 10 14:12:47 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f/cvgcimqmr8/1 port 15587]: [ice] ICE negotiated: peer for component 1 is 172.17.30.201:51150
Aug 10 14:12:47 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f/cvgcimqmr8/1 port 15587]: [ice] ICE negotiated: local interface 172.17.10.19
Aug 10 14:12:47 rtpengine[109445]: ERR: [c04262e9-62bb-45de-81e5-8dfed749f05f/cvgcimqmr8/1 port 15587]: [srtp] SRTP output wanted, but no crypto suite was negotiated
Aug 10 14:12:47 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [control] Received command 'answer' from 127.0.0.1:51111
Aug 10 14:12:47 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [control] Replying to 'answer' from 127.0.0.1:51111 (elapsed time 0.000533 sec)
Aug 10 14:12:47 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f/5e30e790-fa49-4fb6-b988-a510be9ddc69/1 port 11130]: [crypto] DTLS: Peer certificate accepted
Aug 10 14:12:47 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/3455dc87-ed59-4f57-9f96-8e6ea96c5045/1 port 16796]: [crypto] DTLS: Peer certificate accepted
Aug 10 14:12:47 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f/5e30e790-fa49-4fb6-b988-a510be9ddc69/1 port 11130]: [crypto] DTLS-SRTP successfully negotiated using AES_CM_128_HMAC_SHA1_80
Aug 10 14:12:47 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f/5e30e790-fa49-4fb6-b988-a510be9ddc69/1 port 11130]: [crypto] DTLS-SRTP successfully negotiated using AES_CM_128_HMAC_SHA1_80
Aug 10 14:12:47 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/3455dc87-ed59-4f57-9f96-8e6ea96c5045/1 port 16796]: [crypto] DTLS-SRTP successfully negotiated using AES_CM_128_HMAC_SHA1_80
Aug 10 14:12:47 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/3455dc87-ed59-4f57-9f96-8e6ea96c5045/1 port 16796]: [crypto] DTLS-SRTP successfully negotiated using AES_CM_128_HMAC_SHA1_80
Aug 10 14:12:47 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/0eofpc9nq2/1 port 19706]: [ice] ICE negotiated: peer for component 1 is 172.17.30.201:34237
Aug 10 14:12:47 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/0eofpc9nq2/1 port 19706]: [ice] ICE negotiated: local interface 172.17.10.19
Aug 10 14:12:47 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/0eofpc9nq2/1 port 19706]: [crypto] DTLS: Peer certificate accepted
Aug 10 14:12:47 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/0eofpc9nq2/1 port 19706]: [crypto] DTLS-SRTP successfully negotiated using AES_CM_128_HMAC_SHA1_80
Aug 10 14:12:47 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/0eofpc9nq2/1 port 19706]: [crypto] DTLS-SRTP successfully negotiated using AES_CM_128_HMAC_SHA1_80
Aug 10 14:12:47 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f/cvgcimqmr8/1 port 15587]: [ice] ICE negotiated: peer for component 1 is 172.17.30.201:51150
Aug 10 14:12:47 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f/cvgcimqmr8/1 port 15587]: [ice] ICE negotiated: local interface 172.17.10.19
Aug 10 14:12:51 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/0eofpc9nq2/1 port 19706]: [core] Confirmed peer address as 172.17.30.201:34237
Aug 10 14:12:51 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/0eofpc9nq2/1 port 19706]: [core] Kernelizing media stream: 172.17.30.201:34237 -> 172.17.10.19:19706 | 127.0.0.1:16796 -> 127.0.50.1:18382
Aug 10 14:12:51 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/0eofpc9nq2/1 port 19706]: [core] Kernelizing media stream: 172.17.30.201:34237 -> 172.17.10.19:19706 | 127.0.0.1:16796 -> 127.0.50.1:18382
Aug 10 14:12:51 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f/5e30e790-fa49-4fb6-b988-a510be9ddc69/1 port 11130]: [core] Confirmed peer address as 127.0.50.1:14556
Aug 10 14:12:51 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f/5e30e790-fa49-4fb6-b988-a510be9ddc69/1 port 11130]: [core] Kernelizing media stream: 127.0.50.1:14556 -> 127.0.0.1:11130 | 172.17.10.19:15587 -> 172.17.30.201:51150
Aug 10 14:12:51 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f/5e30e790-fa49-4fb6-b988-a510be9ddc69/1 port 11130]: [core] Kernelizing media stream: 127.0.50.1:14556 -> 127.0.0.1:11130 | 172.17.10.19:15587 -> 172.17.30.201:51150
Aug 10 14:12:51 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f/cvgcimqmr8/1 port 15587]: [core] Confirmed peer address as 172.17.30.201:51150
Aug 10 14:12:51 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f/cvgcimqmr8/1 port 15587]: [core] Kernelizing media stream: 172.17.30.201:51150 -> 172.17.10.19:15587 | 127.0.0.1:11130 -> 127.0.50.1:14556
Aug 10 14:12:51 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f/cvgcimqmr8/1 port 15587]: [core] Kernelizing media stream: 172.17.30.201:51150 -> 172.17.10.19:15587 | 127.0.0.1:11130 -> 127.0.50.1:14556
Aug 10 14:12:51 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/3455dc87-ed59-4f57-9f96-8e6ea96c5045/1 port 16796]: [core] Confirmed peer address as 127.0.50.1:18382
Aug 10 14:12:51 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/3455dc87-ed59-4f57-9f96-8e6ea96c5045/1 port 16796]: [core] Kernelizing media stream: 127.0.50.1:18382 -> 127.0.0.1:16796 | 172.17.10.19:19706 -> 172.17.30.201:34237
Aug 10 14:12:51 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/3455dc87-ed59-4f57-9f96-8e6ea96c5045/1 port 16796]: [core] Kernelizing media stream: 127.0.50.1:18382 -> 127.0.0.1:16796 | 172.17.10.19:19706 -> 172.17.30.201:34237
Aug 10 14:12:52 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f/5e30e790-fa49-4fb6-b988-a510be9ddc69/1 port 11130]: [core] Removing media stream from kernel: local 127.0.0.1:11130 (SSRC changed)
Aug 10 14:12:52 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f/5e30e790-fa49-4fb6-b988-a510be9ddc69/1 port 11130]: [core] Kernelizing media stream: 127.0.50.1:14556 -> 127.0.0.1:11130 | 172.17.10.19:15587 -> 172.17.30.201:51150
Aug 10 14:12:52 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f/5e30e790-fa49-4fb6-b988-a510be9ddc69/1 port 11130]: [core] Kernelizing media stream: 127.0.50.1:14556 -> 127.0.0.1:11130 | 172.17.10.19:15587 -> 172.17.30.201:51150
Aug 10 14:12:52 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/3455dc87-ed59-4f57-9f96-8e6ea96c5045/1 port 16796]: [core] Removing media stream from kernel: local 127.0.0.1:16796 (SSRC changed)
Aug 10 14:12:52 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/3455dc87-ed59-4f57-9f96-8e6ea96c5045/1 port 16796]: [core] Kernelizing media stream: 127.0.50.1:18382 -> 127.0.0.1:16796 | 172.17.10.19:19706 -> 172.17.30.201:34237
Aug 10 14:12:52 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq/3455dc87-ed59-4f57-9f96-8e6ea96c5045/1 port 16796]: [core] Kernelizing media stream: 127.0.50.1:18382 -> 127.0.0.1:16796 | 172.17.10.19:19706 -> 172.17.30.201:34237
Aug 10 14:13:04 rtpengine[109445]: INFO: [f2bdf977-cc97-4572-c513-1316e6de176b]: [control] Received command 'delete' from 127.0.0.1:37919
Aug 10 14:13:04 rtpengine[109445]: INFO: [f2bdf977-cc97-4572-c513-1316e6de176b]: [control] Replying to 'delete' from 127.0.0.1:37919 (elapsed time 0.000004 sec)
Aug 10 14:14:55 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [control] Received command 'delete' from 127.0.0.1:56721
Aug 10 14:14:55 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] Scheduling deletion of call branch 'cvgcimqmr8' (via-branch '') in 30 seconds
Aug 10 14:14:55 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] Scheduling deletion of call branch '5e30e790-fa49-4fb6-b988-a510be9ddc69' (via-branch '') in 30 seconds
Aug 10 14:14:55 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] Scheduling deletion of entire call in 30 seconds
Aug 10 14:14:55 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [control] Replying to 'delete' from 127.0.0.1:56721 (elapsed time 0.000344 sec)
Aug 10 14:14:56 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [control] Received command 'delete' from 127.0.0.1:40486
Aug 10 14:14:56 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] Scheduling deletion of call branch '3455dc87-ed59-4f57-9f96-8e6ea96c5045' (via-branch '') in 30 seconds
Aug 10 14:14:56 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] Scheduling deletion of call branch '0eofpc9nq2' (via-branch '') in 30 seconds
Aug 10 14:14:56 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] Scheduling deletion of entire call in 30 seconds
Aug 10 14:14:56 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [control] Replying to 'delete' from 127.0.0.1:40486 (elapsed time 0.000410 sec)
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] Final packet stats:^
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] --- Tag '5e30e790-fa49-4fb6-b988-a510be9ddc69', created 2:40 ago for branch ''
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] ---     subscribed to 'cvgcimqmr8'
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] ---     subscription for 'cvgcimqmr8'
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] ------ Media #1 (audio over RTP/SAVPF) using PCMA/8000
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] --------- Port       127.0.0.1:11130 <>      127.0.50.1:14556, SSRC 212b09fa, in 6478 p, 1173474 b, 2 e, 29 ts, out 6434 p, 1108823 b, 0 e
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] --- SSRC 212b09fa
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] ------ Average MOS 4.4, lowest MOS 4.4 (at 0:11), highest MOS 4.4 (at 0:11) lost:0
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] ------ respective (avg/min/max) jitter 1/1/1 ms, RTT-e2e 2.9/2.8/2.8 ms, RTT-dsct 0.7/0.1/0.1 ms, packet loss 0/0/0%
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] --- Tag 'cvgcimqmr8', created 2:40 ago for branch ''
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] ---     subscribed to '5e30e790-fa49-4fb6-b988-a510be9ddc69'
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] ---     subscription for '5e30e790-fa49-4fb6-b988-a510be9ddc69'
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] ------ Media #1 (audio over RTP/SAVPF) using PCMA/8000
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] --------- Port    172.17.10.19:15587 <>   172.17.30.201:51150, SSRC fb68897b, in 6538 p, 1212000 b, 0 e, 29 ts, out 6389 p, 1101805 b, 0 e
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] --- SSRC fb68897b
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] ------ Average MOS 4.4, lowest MOS 4.4 (at 0:08), highest MOS 4.4 (at 0:08) lost:0
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] ------ respective (avg/min/max) jitter 1/2/2 ms, RTT-e2e 2.9/3.4/3.4 ms, RTT-dsct 2.1/2.6/2.6 ms, packet loss 0/0/0%
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] Removing media stream from kernel: local 172.17.10.19:15587 (final call cleanup)
Aug 10 14:15:25 rtpengine[109445]: INFO: [c04262e9-62bb-45de-81e5-8dfed749f05f]: [core] Removing media stream from kernel: local 127.0.0.1:11130 (final call cleanup)
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] Final packet stats:
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] --- Tag '0eofpc9nq2', created 2:41 ago for branch ''
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] ---     subscribed to '3455dc87-ed59-4f57-9f96-8e6ea96c5045'
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] ---     subscription for '3455dc87-ed59-4f57-9f96-8e6ea96c5045'
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] ------ Media #1 (audio over UDP/TLS/RTP/SAVPF) using PCMA/8000
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] --------- Port    172.17.10.19:19706 <>   172.17.30.201:34237, SSRC c9595fa4, in 6536 p, 1174646 b, 0 e, 30 ts, out 6386 p, 1100329 b, 0 e
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] --- SSRC c9595fa4
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] ------ Average MOS 4.4, lowest MOS 4.4 (at 0:08), highest MOS 4.4 (at 0:08) lost:0
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] ------ respective (avg/min/max) jitter 1/1/1 ms, RTT-e2e 2.9/2.8/2.8 ms, RTT-dsct 2.1/2.0/2.0 ms, packet loss 0/0/0%
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] --- Tag '3455dc87-ed59-4f57-9f96-8e6ea96c5045', created 2:41 ago for branch ''
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] ---     subscribed to '0eofpc9nq2'
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] ---     subscription for '0eofpc9nq2'
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] ------ Media #1 (audio over RTP/SAVPF) using PCMA/8000
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] --------- Port       127.0.0.1:16796 <>      127.0.50.1:18382, SSRC 57ca04f1, in 6478 p, 1173464 b, 0 e, 30 ts, out 6440 p, 1110396 b, 0 e
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] --- SSRC 57ca04f1
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] ------ Average MOS 4.4, lowest MOS 4.4 (at 0:11), highest MOS 4.4 (at 0:11) lost:0
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] ------ respective (avg/min/max) jitter 1/2/2 ms, RTT-e2e 2.9/2.6/2.6 ms, RTT-dsct 0.8/0.6/0.6 ms, packet loss 0/0/0%
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] Removing media stream from kernel: local 127.0.0.1:16796 (final call cleanup)
Aug 10 14:15:26 rtpengine[109445]: INFO: [lvrp00nkp8ber3sulouq]: [core] Removing media stream from kernel: local 172.17.10.19:19706 (final call cleanup)

@rfuchs
Copy link
Member

rfuchs commented Aug 10, 2023

The thing is that in this log I don't see a new DTLS handshake after 2 minutes. And the original code (before 2f4f6d5) would simply ignore and drop DTLS packets after the initial handshake. Which makes me think that it's not a rekeying that's happening here at all.

@rfuchs
Copy link
Member

rfuchs commented Aug 10, 2023

Or perhaps your PJSIP is trying to rekey, but the old version simply ignores it and the rekey fails, so the previous key continues to be used? Does your PJSIP give any indication as to what it's doing? What do these DTLS packets look like in Wireshark?

@dadrc
Copy link
Author

dadrc commented Aug 10, 2023

The thing is that in this log I don't see a new DTLS handshake after 2 minutes. And the original code (before 2f4f6d5) would simply ignore and drop DTLS packets after the initial handshake.

There are some hints as to something related to DTLS in the attached log file above, once while establishing the call:

Aug 10 14:40:59 rtpengine[112013]: DEBUG: [smda31cmac4krhmc16l6/1r8pr5g6qp/1 port 10216]: [srtp] Processing incoming DTLS packet
Aug 10 14:40:59 rtpengine[112013]: INFO: [smda31cmac4krhmc16l6/1r8pr5g6qp/1 port 10216]: [crypto] DTLS: Peer certificate accepted
Aug 10 14:40:59 rtpengine[112013]: DEBUG: [smda31cmac4krhmc16l6/1r8pr5g6qp/1 port 10216]: [srtp] Sending DTLS packet
Aug 10 14:40:59 rtpengine[112013]: DEBUG: [smda31cmac4krhmc16l6/1r8pr5g6qp/1 port 10216]: [srtp] Processing incoming DTLS packet
Aug 10 14:40:59 rtpengine[112013]: DEBUG: [smda31cmac4krhmc16l6/1r8pr5g6qp/1 port 10216]: [crypto] DTLS handshake successful

Then again after exactly two minutes:

Aug 10 14:42:59 rtpengine[112013]: DEBUG: [smda31cmac4krhmc16l6/e1352985-88a6-4257-b920-049ac05d5f71/1 port 11864]: [srtp] Processing incoming DTLS packet
Aug 10 14:42:59 rtpengine[112013]: DEBUG: [1ba178be-3590-4bac-94cb-70947c2d8f6a/e90a49ce-6039-4680-b2a1-b4b485232e66/1 port 10522]: [srtp] Processing incoming DTLS packet

Unfortuately, there's no further information what those DTLS packets contain, as far as I can tell.

Or perhaps your PJSIP is trying to rekey, but the old version simply ignores it and the rekey fails, so the previous key continues to be used? Does your PJSIP give any indication as to what it's doing? What do these DTLS packets look like in Wireshark?

I'll convince the Asterisk to log more DTLS details tomorrow morning (UTC+2), and then report back with that data and a PCAP.

Thanks for the quick answers and the help so far!

@dadrc
Copy link
Author

dadrc commented Aug 11, 2023

I can find no issues in the Asterisk DTLS debug log, there's just an acknowledgement of the rekeying (I've highlighted the corresponding lines in bold).


[Aug 11 08:36:28] DEBUG[2132]: res_rtp_asterisk.c:2193 ast_rtp_dtls_set_configuration: (0x55a9c10734c0) DTLS RTP setup
[Aug 11 08:36:28] DEBUG[3991][C-00000005]: res_rtp_asterisk.c:3180 __rtp_recvfrom: (0x55a9c10734c0) DTLS - __rtp_recvfrom rtp=0x55a9bf8e5770 - Got SSL packet '22'
[Aug 11 08:36:28] DEBUG[3991][C-00000005]: res_rtp_asterisk.c:2915 dtls_srtp_stop_timeout_timer: (0x55a9c10734c0) DTLS srtp - stopped timeout timer'
[Aug 11 08:36:28] DEBUG[3991][C-00000005]: res_rtp_asterisk.c:765 dtls_bio_write: (0x55a9c10734c0) DTLS - sent RTP packet to 127.0.0.1:13368 (len 000689)
[Aug 11 08:36:28] DEBUG[3991][C-00000005]: res_rtp_asterisk.c:2904 dtls_srtp_start_timeout_timer: (0x55a9c10734c0) DTLS srtp - scheduled timeout timer for '998'
    -- PJSIP/test1_webrtc_1-00000009 answered PJSIP/test2_webrtc_1-00000007
[Aug 11 08:36:28] DEBUG[3993]: res_rtp_asterisk.c:2193 ast_rtp_dtls_set_configuration: (0x55a9bffb65f0) DTLS RTP setup
[Aug 11 08:36:28] DEBUG[3993]: res_rtp_asterisk.c:9509 ast_rtp_activate: (0x55a9bffb65f0) DTLS - ast_rtp_activate rtp=0x55a9bf849ff0 - setup and perform DTLS'
[Aug 11 08:36:28] DEBUG[3993]: res_rtp_asterisk.c:2590 dtls_perform_handshake: (0x55a9bf849ff0) DTLS perform handshake - ssl = 0x55a9bfa03100, setup = 0
[Aug 11 08:36:28] DEBUG[3993]: res_rtp_asterisk.c:765 dtls_bio_write: (0x55a9bffb65f0) DTLS - sent RTP packet to 127.0.0.1:11186 (len 000214)
[Aug 11 08:36:28] DEBUG[3993]: res_rtp_asterisk.c:2904 dtls_srtp_start_timeout_timer: (0x55a9bffb65f0) DTLS srtp - scheduled timeout timer for '995'
[Aug 11 08:36:28] DEBUG[3994]: res_rtp_asterisk.c:2915 dtls_srtp_stop_timeout_timer: (0x55a9bfc8fae0) DTLS srtp - stopped timeout timer'
[Aug 11 08:36:28] DEBUG[3994]: res_rtp_asterisk.c:2915 dtls_srtp_stop_timeout_timer: (0x55a9bfc8fae0) DTLS srtp - stopped timeout timer'
[Aug 11 08:36:28] DEBUG[3994]: res_rtp_asterisk.c:2317 ast_rtp_dtls_stop: (0x55a9bfc8fae0) DTLS stop
[Aug 11 08:36:28] DEBUG[3994]: res_rtp_asterisk.c:2915 dtls_srtp_stop_timeout_timer: (0x55a9bfc8fae0) DTLS srtp - stopped timeout timer'
[Aug 11 08:36:28] DEBUG[3994]: res_rtp_asterisk.c:2915 dtls_srtp_stop_timeout_timer: (0x55a9bfc8fae0) DTLS srtp - stopped timeout timer'
    -- Channel PJSIP/test1_webrtc_1-00000009 joined 'simple_bridge' basic-bridge <6fd657c8-3932-4e14-875d-b32a44a781ad>
    -- Channel PJSIP/test2_webrtc_1-00000007 joined 'simple_bridge' basic-bridge <6fd657c8-3932-4e14-875d-b32a44a781ad>
[Aug 11 08:36:28] DEBUG[3991][C-00000005]: res_rtp_asterisk.c:3180 __rtp_recvfrom: (0x55a9bffb65f0) DTLS - __rtp_recvfrom rtp=0x55a9bf849ff0 - Got SSL packet '22'
[Aug 11 08:36:28] DEBUG[3991][C-00000005]: res_rtp_asterisk.c:2915 dtls_srtp_stop_timeout_timer: (0x55a9bffb65f0) DTLS srtp - stopped timeout timer'
[Aug 11 08:36:28] DEBUG[3991][C-00000005]: res_rtp_asterisk.c:765 dtls_bio_write: (0x55a9bffb65f0) DTLS - sent RTP packet to 127.0.0.1:11186 (len 000585)
[Aug 11 08:36:28] DEBUG[3991][C-00000005]: res_rtp_asterisk.c:2904 dtls_srtp_start_timeout_timer: (0x55a9bffb65f0) DTLS srtp - scheduled timeout timer for '999'
[Aug 11 08:36:28] DEBUG[4001][C-00000005]: res_rtp_asterisk.c:3180 __rtp_recvfrom: (0x55a9c10734c0) DTLS - __rtp_recvfrom rtp=0x55a9bf8e5770 - Got SSL packet '22'
[Aug 11 08:36:28] DEBUG[4001][C-00000005]: res_rtp_asterisk.c:2915 dtls_srtp_stop_timeout_timer: (0x55a9c10734c0) DTLS srtp - stopped timeout timer'
[Aug 11 08:36:28] DEBUG[3991][C-00000005]: res_rtp_asterisk.c:3180 __rtp_recvfrom: (0x55a9bffb65f0) DTLS - __rtp_recvfrom rtp=0x55a9bf849ff0 - Got SSL packet '22'
[Aug 11 08:36:28] DEBUG[3991][C-00000005]: res_rtp_asterisk.c:2915 dtls_srtp_stop_timeout_timer: (0x55a9bffb65f0) DTLS srtp - stopped timeout timer'
[Aug 11 08:36:28] DEBUG[3991][C-00000005]: res_rtp_asterisk.c:3031 dtls_srtp_setup: (0x55a9bffb65f0) DTLS setup SRTP rtp=0x55a9bf849ff0'
[Aug 11 08:36:28] DEBUG[3991][C-00000005]: res_rtp_asterisk.c:2951 dtls_srtp_add_local_ssrc: (0x55a9bffb65f0) DTLS srtp - add local ssrc - rtcp=0, set_remote_policy=1'
[Aug 11 08:36:28] DEBUG[3991][C-00000005]: res_rtp_asterisk.c:3222 __rtp_recvfrom: (0x55a9bffb65f0) DTLS - __rtp_recvfrom rtp=0x55a9bf849ff0 - established'
[Aug 11 08:36:28] DEBUG[4001][C-00000005]: res_rtp_asterisk.c:765 dtls_bio_write: (0x55a9c10734c0) DTLS - sent RTP packet to 127.0.0.1:13368 (len 000642)
[Aug 11 08:36:28] DEBUG[4001][C-00000005]: res_rtp_asterisk.c:3031 dtls_srtp_setup: (0x55a9c10734c0) DTLS setup SRTP rtp=0x55a9bf8e5770'
[Aug 11 08:36:28] DEBUG[4001][C-00000005]: res_rtp_asterisk.c:2951 dtls_srtp_add_local_ssrc: (0x55a9c10734c0) DTLS srtp - add local ssrc - rtcp=0, set_remote_policy=1'
[Aug 11 08:36:28] DEBUG[4001][C-00000005]: res_rtp_asterisk.c:3222 __rtp_recvfrom: (0x55a9c10734c0) DTLS - __rtp_recvfrom rtp=0x55a9bf8e5770 - established'
[Aug 11 08:36:28] DEBUG[2132]: res_rtp_asterisk.c:2193 ast_rtp_dtls_set_configuration: (0x55a9bffb65f0) DTLS RTP setup
[Aug 11 08:36:29] DEBUG[2132]: res_rtp_asterisk.c:2193 ast_rtp_dtls_set_configuration: (0x55a9bffb65f0) DTLS RTP setup
[Aug 11 08:36:29] DEBUG[2132]: res_rtp_asterisk.c:9509 ast_rtp_activate: (0x55a9bffb65f0) DTLS - ast_rtp_activate rtp=0x55a9bf849ff0 - setup and perform DTLS'
[Aug 11 08:36:29] DEBUG[2132]: res_rtp_asterisk.c:2630 dtls_perform_setup: DTLS perform setup - connection reset
[Aug 11 08:36:29] DEBUG[2132]: res_rtp_asterisk.c:2590 dtls_perform_handshake: (0x55a9bf849ff0) DTLS perform handshake - ssl = 0x55a9bfa03100, setup = 0
[Aug 11 08:36:29] DEBUG[2132]: res_rtp_asterisk.c:765 dtls_bio_write: (0x55a9bffb65f0) DTLS - sent RTP packet to 127.0.0.1:11186 (len 000214)
[Aug 11 08:36:29] DEBUG[2132]: res_rtp_asterisk.c:2904 dtls_srtp_start_timeout_timer: (0x55a9bffb65f0) DTLS srtp - scheduled timeout timer for '999'
[Aug 11 08:36:30] DEBUG[2239]: res_rtp_asterisk.c:2843 dtls_srtp_handle_timeout: (0x55a9bffb65f0) DTLS srtp - handle timeout - rtcp=0
[Aug 11 08:36:30] DEBUG[2239]: res_rtp_asterisk.c:765 dtls_bio_write: (0x55a9bffb65f0) DTLS - sent RTP packet to 127.0.0.1:11186 (len 000214)
[Aug 11 08:36:31] DEBUG[2239]: res_rtp_asterisk.c:2843 dtls_srtp_handle_timeout: (0x55a9bffb65f0) DTLS srtp - handle timeout - rtcp=0
[Aug 11 08:36:32] DEBUG[2239]: res_rtp_asterisk.c:2843 dtls_srtp_handle_timeout: (0x55a9bffb65f0) DTLS srtp - handle timeout - rtcp=0
[Aug 11 08:36:32] DEBUG[2239]: res_rtp_asterisk.c:765 dtls_bio_write: (0x55a9bffb65f0) DTLS - sent RTP packet to 127.0.0.1:11186 (len 000214)
[Aug 11 08:36:33] DEBUG[2239]: res_rtp_asterisk.c:2843 dtls_srtp_handle_timeout: (0x55a9bffb65f0) DTLS srtp - handle timeout - rtcp=0
[…]
[Aug 11 08:36:36] DEBUG[2239]: res_rtp_asterisk.c:2843 dtls_srtp_handle_timeout: (0x55a9bffb65f0) DTLS srtp - handle timeout - rtcp=0
[Aug 11 08:36:36] DEBUG[2239]: res_rtp_asterisk.c:765 dtls_bio_write: (0x55a9bffb65f0) DTLS - sent RTP packet to 127.0.0.1:11186 (len 000214)
[Aug 11 08:36:37] DEBUG[2239]: res_rtp_asterisk.c:2843 dtls_srtp_handle_timeout: (0x55a9bffb65f0) DTLS srtp - handle timeout - rtcp=0
[…]
[Aug 11 08:36:44] DEBUG[2239]: res_rtp_asterisk.c:2843 dtls_srtp_handle_timeout: (0x55a9bffb65f0) DTLS srtp - handle timeout - rtcp=0
[Aug 11 08:36:44] DEBUG[2239]: res_rtp_asterisk.c:765 dtls_bio_write: (0x55a9bffb65f0) DTLS - sent RTP packet to 127.0.0.1:11186 (len 000214)
[Aug 11 08:36:45] DEBUG[2239]: res_rtp_asterisk.c:2843 dtls_srtp_handle_timeout: (0x55a9bffb65f0) DTLS srtp - handle timeout - rtcp=0
[…]
[Aug 11 08:37:01] DEBUG[2239]: res_rtp_asterisk.c:2843 dtls_srtp_handle_timeout: (0x55a9bffb65f0) DTLS srtp - handle timeout - rtcp=0
[Aug 11 08:37:01] DEBUG[2239]: res_rtp_asterisk.c:765 dtls_bio_write: (0x55a9bffb65f0) DTLS - sent RTP packet to 127.0.0.1:11186 (len 000214)
[Aug 11 08:37:02] DEBUG[2239]: res_rtp_asterisk.c:2843 dtls_srtp_handle_timeout: (0x55a9bffb65f0) DTLS srtp - handle timeout - rtcp=0
[…]
[Aug 11 08:37:34] DEBUG[2239]: res_rtp_asterisk.c:2843 dtls_srtp_handle_timeout: (0x55a9bffb65f0) DTLS srtp - handle timeout - rtcp=0
[Aug 11 08:37:34] DEBUG[2239]: res_rtp_asterisk.c:765 dtls_bio_write: (0x55a9bffb65f0) DTLS - sent RTP packet to 127.0.0.1:11186 (len 000214)
[Aug 11 08:37:35] DEBUG[2239]: res_rtp_asterisk.c:2843 dtls_srtp_handle_timeout: (0x55a9bffb65f0) DTLS srtp - handle timeout - rtcp=0
[…]
[Aug 11 08:38:28] DEBUG[2239]: res_rtp_asterisk.c:2843 dtls_srtp_handle_timeout: (0x55a9bffb65f0) DTLS srtp - handle timeout - rtcp=0
[Aug 11 08:38:28] DEBUG[2239]: res_rtp_asterisk.c:2926 dtls_srtp_renegotiate: (0x55a9bffb65f0) DTLS srtp - renegotiate'
[Aug 11 08:38:28] DEBUG[2239]: res_rtp_asterisk.c:2926 dtls_srtp_renegotiate: (0x55a9c10734c0) DTLS srtp - renegotiate'
[Aug 11 08:38:28] DEBUG[2239]: res_rtp_asterisk.c:765 dtls_bio_write: (0x55a9c10734c0) DTLS - sent RTP packet to 127.0.0.1:13368 (len 000041)
[Aug 11 08:38:29] DEBUG[2239]: res_rtp_asterisk.c:2843 dtls_srtp_handle_timeout: (0x55a9bffb65f0) DTLS srtp - handle timeout - rtcp=0
[…]
[Aug 11 08:38:34] DEBUG[2239]: res_rtp_asterisk.c:2843 dtls_srtp_handle_timeout: (0x55a9bffb65f0) DTLS srtp - handle timeout - rtcp=0
[Aug 11 08:38:34] DEBUG[2239]: res_rtp_asterisk.c:765 dtls_bio_write: (0x55a9bffb65f0) DTLS - sent RTP packet to 127.0.0.1:11186 (len 000214)
[Aug 11 08:38:35] DEBUG[2239]: res_rtp_asterisk.c:2843 dtls_srtp_handle_timeout: (0x55a9bffb65f0) DTLS srtp - handle timeout - rtcp=0
[…]
[Aug 11 08:38:46] DEBUG[2239]: res_rtp_asterisk.c:2843 dtls_srtp_handle_timeout: (0x55a9bffb65f0) DTLS srtp - handle timeout - rtcp=0
    -- Channel PJSIP/test1_webrtc_1-00000009 left 'simple_bridge' basic-bridge <6fd657c8-3932-4e14-875d-b32a44a781ad>
    -- Channel PJSIP/test2_webrtc_1-00000007 left 'simple_bridge' basic-bridge <6fd657c8-3932-4e14-875d-b32a44a781ad>
  == Spawn extension (from-internal-users, 456, 1) exited non-zero on 'PJSIP/test2_webrtc_1-00000007'
[Aug 11 08:38:47] DEBUG[2132]: res_rtp_asterisk.c:2915 dtls_srtp_stop_timeout_timer: (0x55a9c10734c0) DTLS srtp - stopped timeout timer'
[Aug 11 08:38:47] DEBUG[2132]: res_rtp_asterisk.c:2915 dtls_srtp_stop_timeout_timer: (0x55a9c10734c0) DTLS srtp - stopped timeout timer'
[Aug 11 08:38:47] DEBUG[2132]: res_rtp_asterisk.c:2317 ast_rtp_dtls_stop: (0x55a9c10734c0) DTLS stop
[Aug 11 08:38:47] DEBUG[2132]: res_rtp_asterisk.c:2915 dtls_srtp_stop_timeout_timer: (0x55a9c10734c0) DTLS srtp - stopped timeout timer'

I've also captured the DTLS traffic – github wont let me attach PCAPs, though. I can see the Asterisk sending an encrypted handshake to rtpengine exactly two minutes after the initial handshake. There's no second handshake between rtpengine and the WebRTC client, though. I think this validates your suspicion that the rekeying just (more or less silently) fails.

@rfuchs
Copy link
Member

rfuchs commented Aug 11, 2023

Ok that's good information. It will take some trial and error to make this work as I don't have a good way to easily reproduce this.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants