TLS/STRP Encryption: Couldn’t negotiate stream 0:audio-0:audio:sendrecv (nothing)

I’m trying to make use of encryption on my FreePBX version 16 instance. Currently when I try to have the client device (in this example linphone, but is not limited to just this), try to register registration is OK and Reachable. However whenever any call, (external, internal, inbound outbound) comes in, I get this weird error: “Couldn’t negotiate stream 0:audio-0:sendrecv (nothing)” which causes no audio to be heard by either party.

This has to be something wrong with the media encryption settings, but I’ve looked everywhere searched all over the internet as well. There just seems to be no obvious answer to this problem.

I enabled pcap logging and have included an example call (that only lasts 3 seconds), to show what I am seeing.

[2022-01-17 18:45:22] VERBOSE[30138] res_pjsip_logger.c: <— Transmitting SIP response (1128 bytes) to TLS:xxx.my.ip.xxx:49954 —>
18216SIP/2.0 200 OK
18217Via: SIP/2.0/TLS xxx.device.private.ip:49954;rport=49954;received=xxx.my.ip.xxx;branch=z9hG4bK.f4n4S7naa
18218Call-ID: ~TbO7OO4V~
18219From: sip:[email protected];tag=A6fozptXy
18220To: sip:[email protected];tag=a6920a58-48fd-46ef-a777-a8ec1398521f
18221CSeq: 21 INVITE
18222Server: FPBX-16.0.10.43(18.6.0)
18223Contact: sip:xxx.ip.ip.xxx:7223;transport=TLS
18224Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE
18225Supported: 100rel, timer, replaces, norefersub
18226Content-Type: application/sdp
18227Content-Length: 518
18228
18229v=0
18230o=- 1727 1966 IN IP4 xxx.ip.ip.xxx
18231s=Asterisk
18232c=IN IP4 xxx.ip.ip.xxx
18233t=0 0
18234m=audio 11230 RTP/SAVP 0 8 3 9 96 98 97 99 104
18235a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:4MKItbXPRNz/Uyu+UfJbLE7ucjQ/v2BkObPEwUcL
18236a=rtpmap:0 PCMU/8000
18237a=rtpmap:8 PCMA/8000
18238a=rtpmap:3 GSM/8000
18239a=rtpmap:9 G722/8000
18240a=rtpmap:96 opus/48000/2
18241a=fmtp:96 useinbandfec=1
18242a=rtpmap:98 speex/8000
18243a=rtpmap:97 speex/16000
18244a=rtpmap:99 speex/32000
18245a=rtpmap:104 telephone-event/8000
18246a=fmtp:104 0-16
18247a=ptime:20
18248a=maxptime:20
18249a=sendrecv
18250
18251[2022-01-17 18:45:26] VERBOSE[30138] res_pjsip_logger.c: <— Transmitting SIP response (1128 bytes) to TLS:xxx.my.ip.xxx:49954 —>
18252SIP/2.0 200 OK
18253Via: SIP/2.0/TLS xxx.device.private.ip:49954;rport=49954;received=xxx.my.ip.xxx;branch=z9hG4bK.f4n4S7naa
18254Call-ID: ~TbO7OO4V~
18255From: sip:[email protected];tag=A6fozptXy
18256To: sip:[email protected];tag=a6920a58-48fd-46ef-a777-a8ec1398521f
18257CSeq: 21 INVITE
18258Server: FPBX-16.0.10.43(18.6.0)
18259Contact: sip:xxx.ip.ip.xxx:7223;transport=TLS
18260Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE
18261Supported: 100rel, timer, replaces, norefersub
18262Content-Type: application/sdp
18263Content-Length: 518
18264
18265v=0
18266o=- 1727 1966 IN IP4 xxx.ip.ip.xxx
18267s=Asterisk
18268c=IN IP4 xxx.ip.ip.xxx
18269t=0 0
18270m=audio 11230 RTP/SAVP 0 8 3 9 96 98 97 99 104
18271a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:4MKItbXPRNz/Uyu+UfJbLE7ucjQ/v2BkObPEwUcL
18272a=rtpmap:0 PCMU/8000
18273a=rtpmap:8 PCMA/8000
18274a=rtpmap:3 GSM/8000
18275a=rtpmap:9 G722/8000
18276a=rtpmap:96 opus/48000/2
18277a=fmtp:96 useinbandfec=1
18278a=rtpmap:98 speex/8000
18279a=rtpmap:97 speex/16000
18280a=rtpmap:99 speex/32000
18281a=rtpmap:104 telephone-event/8000
18282a=fmtp:104 0-16
18283a=ptime:20
18284a=maxptime:20
18285a=sendrecv
18286
18287[2022-01-17 18:45:29] NOTICE[30184] res_pjsip_sdp_rtp.c: Disconnecting channel ‘PJSIP/3000-00000007’ for lack of audio RTP activity in 31 seconds
18288[2022-01-17 18:45:29] VERBOSE[10340][C-00000008] app.c: User hung up
18289[2022-01-17 18:45:29] VERBOSE[10340][C-00000008] app_voicemail.c: Recording was 0 seconds long but needs to be at least 1 - abandoning
18290[2022-01-17 18:45:29] VERBOSE[10340][C-00000008] app_macro.c: Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on ‘PJSIP/3000-00000007’ in macro ‘vm’
18291[2022-01-17 18:45:29] VERBOSE[10340][C-00000008] app_macro.c: Spawn extension (macro-exten-vm, s, 25) exited non-zero on ‘PJSIP/3000-00000007’ in macro ‘exten-vm’
18292[2022-01-17 18:45:29] VERBOSE[10340][C-00000008] pbx.c: Spawn extension (ext-local, 3001, 3) exited non-zero on ‘PJSIP/3000-00000007’
18293[2022-01-17 18:45:29] VERBOSE[10340][C-00000008] pbx.c: Executing [h@ext-local:1] Macro(“PJSIP/3000-00000007”, “hangupcall,”) in new stack
18294[2022-01-17 18:45:29] VERBOSE[10340][C-00000008] pbx.c: Executing [s@macro-hangupcall:1] GotoIf(“PJSIP/3000-00000007”, “1?theend”) in new stack
18295[2022-01-17 18:45:29] VERBOSE[10340][C-00000008] pbx_builtins.c: Goto (macro-hangupcall,s,3)
18296[2022-01-17 18:45:29] VERBOSE[10340][C-00000008] pbx.c: Executing [s@macro-hangupcall:3] ExecIf(“PJSIP/3000-00000007”, “0?Set(CDR(recordingfile)=)”) in new stack
18297[2022-01-17 18:45:29] VERBOSE[10340][C-00000008] pbx.c: Executing [s@macro-hangupcall:4] NoOp(“PJSIP/3000-00000007”, " montior file= ") in new stack
18298[2022-01-17 18:45:29] VERBOSE[10340][C-00000008] pbx.c: Executing [s@macro-hangupcall:5] GotoIf(“PJSIP/3000-00000007”, “1?skipagi”) in new stack
18299[2022-01-17 18:45:29] VERBOSE[10340][C-00000008] pbx_builtins.c: Goto (macro-hangupcall,s,7)
18300[2022-01-17 18:45:29] VERBOSE[10340][C-00000008] pbx.c: Executing [s@macro-hangupcall:7] Hangup(“PJSIP/3000-00000007”, “”) in new stack
18301[2022-01-17 18:45:29] VERBOSE[10340][C-00000008] app_macro.c: Spawn extension (macro-hangupcall, s, 7) exited non-zero on ‘PJSIP/3000-00000007’ in macro ‘hangupcall’
18302[2022-01-17 18:45:29] VERBOSE[10340][C-00000008] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on ‘PJSIP/3000-00000007’
18303[2022-01-17 18:45:30] VERBOSE[30138] res_pjsip_logger.c: <— Transmitting SIP response (1128 bytes) to TLS:xxx.my.ip.xxx:49954 —>
18304SIP/2.0 200 OK
18305Via: SIP/2.0/TLS xxx.device.private.ip:49954;rport=49954;received=xxx.my.ip.xxx;branch=z9hG4bK.f4n4S7naa
18306Call-ID: ~TbO7OO4V~
18307From: sip:[email protected];tag=A6fozptXy
18308To: sip:[email protected];tag=a6920a58-48fd-46ef-a777-a8ec1398521f
18309CSeq: 21 INVITE
18310Server: FPBX-16.0.10.43(18.6.0)
18311Contact: sip:xxx.ip.ip.xxx:7223;transport=TLS
18312Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE
18313Supported: 100rel, timer, replaces, norefersub
18314Content-Type: application/sdp
18315Content-Length: 518
18316
18317v=0
18318o=- 1727 1966 IN IP4 xxx.ip.ip.xxx
18319s=Asterisk
18320c=IN IP4 xxx.ip.ip.xxx
18321t=0 0
18322m=audio 11230 RTP/SAVP 0 8 3 9 96 98 97 99 104
18323a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:4MKItbXPRNz/Uyu+UfJbLE7ucjQ/v2BkObPEwUcL
18324a=rtpmap:0 PCMU/8000
18325a=rtpmap:8 PCMA/8000
18326a=rtpmap:3 GSM/8000
18327a=rtpmap:9 G722/8000
18328a=rtpmap:96 opus/48000/2
18329a=fmtp:96 useinbandfec=1
18330a=rtpmap:98 speex/8000
18331a=rtpmap:97 speex/16000
18332a=rtpmap:99 speex/32000
18333a=rtpmap:104 telephone-event/8000
18334a=fmtp:104 0-16
18335a=ptime:20
18336a=maxptime:20
18337a=sendrecv
18338
18339[2022-01-17 18:45:31] VERBOSE[30138] res_pjsip_logger.c: <— Transmitting SIP request (435 bytes) to TLS:xxx.my.ip.xxx:49954 —>
18340BYE sip:[email protected]:49954;transport=TLS SIP/2.0
18341Via: SIP/2.0/TLS xxx.ip.ip.xxx:7223;rport;branch=z9hG4bKPj38f44e69-f030-4c27-a7dd-6df86e521cdc;alias
18342From: sip:[email protected];tag=a6920a58-48fd-46ef-a777-a8ec1398521f
18343To: sip:[email protected];tag=A6fozptXy
18344Call-ID: ~TbO7OO4V~
18345CSeq: 28394 BYE
18346Max-Forwards: 70
18347User-Agent: FPBX-16.0.10.43(18.6.0)
18348Content-Length: 0
18349
18350
18351[2022-01-17 18:45:31] VERBOSE[30138] res_pjsip_logger.c: <— Received SIP response (487 bytes) from TLS:xxx.my.ip.xxx:49954 —>
18352SIP/2.0 200 Ok
18353Via: SIP/2.0/TLS xxx.ip.ip.xxx:7223;received=3.140.142.241;rport;branch=z9hG4bKPj38f44e69-f030-4c27-a7dd-6df86e521cdc;alias
18354From: sip:[email protected];tag=a6920a58-48fd-46ef-a777-a8ec1398521f
18355To: sip:[email protected];tag=A6fozptXy
18356Call-ID: ~TbO7OO4V~
18357CSeq: 28394 BYE
18358User-Agent: Linphone Desktop/4.3.0 (Ubuntu 20.04.3 LTS, Qt 5.12.5) LinphoneCore/5.0.39
18359Supported: replaces, outbound, gruu
18360Content-Length: 0

From my basic understanding, there should be nothing here that suggests any such audio problems. Irregardless I am receiving no audio. For example the message that says “the person at extension xxxx is unavailable” doesn’t produce any audio either, thus it just is a 3 second or so delay before it starts to accept a silent voicemail.

More than anything, I would like to know how to diagnose the problem and get encryption working. However a quick answer pointing to the solution is acceptable.

Moreover what would be the critical disadvantage of having a public pbx/uc system without encryption. Thanks

This is an incomplete log. It appears that the OK was retransmitted because it never got an ACK back, which is strange because the peer appeared to be able to send OK to the BYE.

Because it is incomplete, I can’t tell if the OK was for the original INVITE or for a re-INVITE.

The message in the subject looks like it has been re-keyed, as I doubt that the sixth character is really a T. Did it even come from Asterisk? OK. A search shows it comes from Asterisk but the message is an incomplete message, starting at “Couldn’t”. The missing bit at the beginning may say it was in the handle_incoming_sdp function, but your log does not go back far enough to include the incoming SDP.

1 Like

The TLS/SRTP Encryption: part of the subject was added by me, that is what is causing the problem I believe. The other part is the actual error message. This is very concerning to me because the log I provided is complete as for as the traces go… There was and is no reINVITE it just proceeds as seen (which is baffling to me as well). The “handle_incoming_sdp function” call is never shown in logs… Maybe it isn’t being called and causes the problem? I’m really not sure how I would diagnose this but maybe the registration isn’t using sdp by some miracle?!? I’ll keep looking and will send additional logs as I find them. Thank you for the reply I really appreciate it.

Well looking through the log files you will not see any weird problems or anything like that in this case because it isn’t a problem with the codecs or encryption for that matter!

In fact it was actually SIP ALG, SIP ALG was being employed by my router when I was using one protocol over the other! So when I tried to do encryption on the other protocol, it would do its dirty work and mess everything up silently. :man_facepalming:.

Thank you to the 55 people who viewed this (some of which definitely looked into the problem) I really appreciate the time you spent in looking into this problem.
As for the other people who were looking for answers to the same exact problem. Please check your codecs, Then check for SIP ALG and disable if possible or use different protocol (again if possible). Finally check your certificates and if that fails maybe further logs will show the problem.

+1 to @david55 for replying and helping me keep on track (it really helped me to look where I wasn’t looking knowing your input). Thanks

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.