Choppy audio with DSP warnings

duncannz · February 7, 2024, 2:33am

Hi there,

We have started experiencing intermittent choppy audio such as the below recordings:

The choppiness is only heard when someone is talking (or hold music is playing in the case of the second recording), and generally resolves itself within ~20 seconds (as heard towards the end of the first recording).

The only clue we have so far is the following message logged repeatedly around the same time:

WARNING[44793]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames

This is the pjsip.conf:

[global]
use_callerid_contact=yes
user_agent=VXT cpaas-worker

;============= Transport
[transport]
type=transport
protocol=tcp
bind=0.0.0.0:<env>INBOUND_SIP_PORT</env>
external_media_address=<env>EXTERNAL_IPv4</env>

;============= Web RTC

[webrtc_client]
type=aor
max_contacts=100000

[webrtc_client]
type=endpoint
allow=!all,opus,ulaw,alaw,h264
aors=webrtc_client
context=webrtc-client
dtls_auto_generate_cert=yes
identify_by=header
max_audio_streams=16
max_video_streams=16
rtp_symmetric=yes
; RTP timeout to ensure clients hang up if they lose connection
rtp_timeout=30
rtp_timeout_hold=30
webrtc=yes
rewrite_contact=yes
force_rport=yes

[webrtc_client]
type=identify
endpoint=webrtc_client
match_header=X-Vxt-Invite-Source: app

codecs.conf:

[opus]
type=opus
fec=true
packet_loss=10

Please let me know if any other config files are relevant.

To start with I would like to understand what may be calling ast_dsp_silence_noise_with_energy in the first place, and whether this is likely a cause or another symptom of the issue leading to choppy audio.

Edit to add: The Asterisk version is 20.3.0, and this issue appears to have been introduced by upgrading from 20.0.0. However I haven’t found any change so far that appear relevant in any of the 20.x changelogs.

Many thanks in advance

jcolp · February 7, 2024, 9:56am

There is insufficient information here. You would need to show an actual SIP trace, as well as the Asterisk console log of a call flow to show what is being used - or describe what is being done in more detail.

duncannz · February 7, 2024, 10:00pm

Hi jcolp,

Thank you for your post. Here is a SIP trace of the call from the first link:

proto:TCP 2024-01-29T04:54:27.69Z  127.0.0.1:47740 ---> 127.0.0.1:6001

INVITE sip:response@cpaas-worker-asi.invalid SIP/2.0
Max-Forwards: 69
To: <sip:response@cpaas-worker-asi.invalid>
From: <sip:webrtc_client@cpaas-worker-asi.invalid>;tag=rotk3i0e3afhvbl
Call-ID: 01HN9S36K9JN09F846H7C5X2RG
CSeq: 3928 INVITE
Supported: outbound
User-Agent: VXT SIP
X-Vxt-Invite-Source: app
[Other custom headers redacted]
Allow: ACK,BYE,CANCEL,INFO,INVITE,MESSAGE,NOTIFY,OPTIONS,REFER,UPDATE
Via: SIP/2.0/tcp 785u68ojm0.invalid;branch=vxtSip06c1g16faf2ltma
Contact: <sip:va9e5sjskq@785u68ojm0.invalid;transport=tcp>
Content-Type: application/sdp
Content-Length: 1989

v=0
o=- 3528094481641471396 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=extmap-allow-mixed
a=msid-semantic: WMS
m=audio 50839 UDP/TLS/RTP/SAVPF 111 63 9 0 8 13 110 126
c=IN IP4 192.168.0.102
a=rtcp:9 IN IP4 0.0.0.0
a=candidate:1800010069 1 udp 2122129151 192.168.0.102 50839 typ host generation 0 network-id 1 network-cost 10
a=candidate:3772799020 1 udp 2122262783 2001:8003:34c1:8400:78e3:8816:a14a:2077 50840 typ host generation 0 network-id 2 network-cost 10
a=candidate:617511769 1 udp 2122197247 2001:8003:34c1:8400:3bd:515d:db12:97f2 50841 typ host generation 0 network-id 3 network-cost 10
a=candidate:361110477 1 tcp 1518149375 192.168.0.102 9 typ host tcptype active generation 0 network-id 1 network-cost 10
a=candidate:2653928116 1 tcp 1518283007 2001:8003:34c1:8400:78e3:8816:a14a:2077 9 typ host tcptype active generation 0 network-id 2 network-cost 10
a=candidate:1510054337 1 tcp 1518217471 2001:8003:34c1:8400:3bd:515d:db12:97f2 9 typ host tcptype active generation 0 network-id 3 network-cost 10
a=ice-ufrag:JFx0
a=ice-pwd:YwRkH6xgYfTyEHqwT+rS/XBY
a=ice-options:trickle
a=fingerprint:sha-256 EB:0F:24:64:32:72:3B:98:18:54:28:3B:13:A1:D1:48:12:FE:A1:77:5A:9C:02:12:67:F4:89:BC:D8:65:73:96
a=setup:actpass
a=mid:0
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=sendrecv
a=msid:- 22c28263-08e3-4bd5-ad49-feff6c7cfbaa
a=rtcp-mux
a=rtpmap:111 opus/48000/2
a=rtcp-fb:111 transport-cc
a=fmtp:111 minptime=10;useinbandfec=1
a=rtpmap:63 red/48000/2
a=fmtp:63 111/111
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:126 telephone-event/8000
a=ssrc:2627945518 cname:MtWV/s2tNHNGpkF2
a=ssrc:2627945518 msid:- 22c28263-08e3-4bd5-ad49-feff6c7cfbaa

proto:TCP 2024-01-29T04:54:27.690706Z  127.0.0.1:6001 ---> 127.0.0.1:47740

SIP/2.0 100 Trying
Via: SIP/2.0/TCP 785u68ojm0.invalid;rport=47740;received=127.0.0.1;branch=vxtSip06c1g16faf2ltma
Call-ID: 01HN9S36K9JN09F846H7C5X2RG
From: <sip:webrtc_client@cpaas-worker-asi.invalid>;tag=rotk3i0e3afhvbl
To: <sip:response@cpaas-worker-asi.invalid>
CSeq: 3928 INVITE
Server: VXT cpaas-worker
Content-Length:  0


proto:TCP 2024-01-29T04:54:27.715725Z  127.0.0.1:6001 ---> 127.0.0.1:47740

SIP/2.0 200 OK
Via: SIP/2.0/TCP 785u68ojm0.invalid;rport=47740;received=127.0.0.1;branch=vxtSip06c1g16faf2ltma
Call-ID: 01HN9S36K9JN09F846H7C5X2RG
From: <sip:webrtc_client@cpaas-worker-asi.invalid>;tag=rotk3i0e3afhvbl
To: <sip:response@cpaas-worker-asi.invalid>;tag=5f551ca3-5bdb-45a3-a355-5a0f94b1fee0
CSeq: 3928 INVITE
Server: VXT cpaas-worker
Contact: <sip:127.0.0.1:6001;transport=TCP>
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Supported: 100rel, timer, replaces, norefersub
Content-Type: application/sdp
Content-Length:   938

v=0
o=- 138509732 4 IN IP4 127.0.0.1
s=Asterisk
c=IN IP4 127.0.0.1
t=0 0
a=msid-semantic:WMS *
a=group:BUNDLE 0
m=audio 11620 UDP/TLS/RTP/SAVPF 111 0 8 126
a=connection:new
a=setup:active
a=fingerprint:SHA-256 8E:DD:22:99:47:C0:7F:91:03:AD:DC:AA:9E:9F:F9:52:A8:14:43:47:0E:BE:68:DD:A1:E5:60:FF:F0:2A:C6:DE
a=ice-ufrag:4fca7a781ce964a84a1c486624dbce94
a=ice-pwd:0bf010a257a9af44452fe78741376276
a=candidate:H22746872 1 UDP 2130706431 34.116.104.114 11620 typ host
a=candidate:H531c7707 1 UDP 2130706431 2600:1900:40b0:efbd:0:6c:: 11620 typ host
a=rtpmap:111 opus/48000/2
a=fmtp:111 useinbandfec=1
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:126 telephone-event/8000
a=fmtp:126 0-16
a=ptime:20
a=maxptime:20
a=sendrecv
a=rtcp-mux
a=ssrc:580540386 cname:8b361562-35b3-4e79-ab19-651bcd40fda1
a=msid:57b12397-00f0-4a45-82e9-b5a741f751d7 20d45a36-faa0-4f3a-8fe9-7786b7532475
a=rtcp-fb:* transport-cc
a=mid:0

proto:TCP 2024-01-29T04:54:27.723Z  127.0.0.1:47740 ---> 127.0.0.1:6001

ACK sip:127.0.0.1:6001;transport=TCP SIP/2.0
Max-Forwards: 69
To: <sip:response@cpaas-worker-asi.invalid>;tag=5f551ca3-5bdb-45a3-a355-5a0f94b1fee0
From: <sip:webrtc_client@cpaas-worker-asi.invalid>;tag=rotk3i0e3afhvbl
Call-ID: 01HN9S36K9JN09F846H7C5X2RG
CSeq: 3928 ACK
Supported: outbound
User-Agent: VXT SIP
Via: SIP/2.0/tcp 785u68ojm0.invalid;branch=vxtSip2m4o797e6511q5e
Content-Length: 0


proto:UDP 2024-01-29T04:54:29.455371Z  2001:8003:34c1:8400:78e3:8816:a14a:2077:50840 ---> 2600:1900:40b0:efbd:0:6c:::11620

{"ssrc":3915492869,"type":200,"report_count":0,"sender_information":{"ntp_timestamp_sec":"1706504069","ntp_timestamp_usec":"229559","rtp_timestamp":793632188,"packets":65,"octets":2190},"report_blocks":[]}
proto:UDP 2024-01-29T04:54:30.595828Z  2001:8003:34c1:8400:78e3:8816:a14a:2077:50840 ---> 2600:1900:40b0:efbd:0:6c:::11620

{"ssrc":580540386,"type":201,"report_count":1,"sender_information":null,"report_blocks":[{"source_ssrc":580540386,"fraction_lost":0,"packets_lost":0,"highest_seq_no":16107,"ia_jitter":34,"lsr":"0","dlsr":0}]}
proto:UDP 2024-01-29T04:54:31.970601Z  2001:8003:34c1:8400:78e3:8816:a14a:2077:50840 ---> 2600:1900:40b0:efbd:0:6c:::11620

{"ssrc":3915492871,"type":200,"report_count":0,"sender_information":{"ntp_timestamp_sec":"1706504071","ntp_timestamp_usec":"744589","rtp_timestamp":793752860,"packets":191,"octets":8529},"report_blocks":[]}
proto:UDP 2024-01-29T04:54:33.049872Z  2600:1900:40b0:efbd:0:6c:::11620 ---> 2001:8003:34c1:8400:78e3:8816:a14a:2077:50840

{"ssrc":580540386,"type":200,"report_count":1,"sender_information":{"ntp_timestamp_sec":"1706504073","ntp_timestamp_usec":"49769","rtp_timestamp":240000,"packets":250,"octets":27326},"report_blocks":[{"source_ssrc":2627945518,"fraction_lost":0,"packets_lost":0,"highest_seq_no":6231,"ia_jitter":17,"lsr":"2919743133","dlsr":70713}]}
proto:UDP 2024-01-29T04:54:35.093962Z  2001:8003:34c1:8400:78e3:8816:a14a:2077:50840 ---> 2600:1900:40b0:efbd:0:6c:::11620

{"ssrc":3915492874,"type":200,"report_count":0,"sender_information":{"ntp_timestamp_sec":"1706504074","ntp_timestamp_usec":"867958","rtp_timestamp":793902812,"packets":347,"octets":16579},"report_blocks":[]}
proto:UDP 2024-01-29T04:54:36.609485Z  2001:8003:34c1:8400:78e3:8816:a14a:2077:50840 ---> 2600:1900:40b0:efbd:0:6c:::11620

{"ssrc":580540386,"type":201,"report_count":1,"sender_information":null,"report_blocks":[{"source_ssrc":580540386,"fraction_lost":0,"packets_lost":0,"highest_seq_no":16408,"ia_jitter":25,"lsr":"2919828669","dlsr":232163}]}
proto:UDP 2024-01-29T04:54:38.050196Z  2600:1900:40b0:efbd:0:6c:::11620 ---> 2001:8003:34c1:8400:78e3:8816:a14a:2077:50840

{"ssrc":580540386,"type":200,"report_count":1,"sender_information":{"ntp_timestamp_sec":"1706504078","ntp_timestamp_usec":"50107","rtp_timestamp":480000,"packets":500,"octets":56255},"report_blocks":[{"source_ssrc":2627945518,"fraction_lost":0,"packets_lost":0,"highest_seq_no":6481,"ia_jitter":23,"lsr":"2919947826","dlsr":193724}]}
proto:UDP 2024-01-29T04:54:38.688566Z  2001:8003:34c1:8400:78e3:8816:a14a:2077:50840 ---> 2600:1900:40b0:efbd:0:6c:::11620

{"ssrc":3915492878,"type":200,"report_count":0,"sender_information":{"ntp_timestamp_sec":"1706504078","ntp_timestamp_usec":"462504","rtp_timestamp":794075372,"packets":527,"octets":26781},"report_blocks":[]}
proto:UDP 2024-01-29T04:54:42.141342Z  2001:8003:34c1:8400:78e3:8816:a14a:2077:50840 ---> 2600:1900:40b0:efbd:0:6c:::11620

{"ssrc":580540386,"type":201,"report_count":1,"sender_information":null,"report_blocks":[{"source_ssrc":580540386,"fraction_lost":0,"packets_lost":0,"highest_seq_no":16684,"ia_jitter":33,"lsr":"2920156371","dlsr":266943}]}
proto:UDP 2024-01-29T04:54:42.276601Z  2001:8003:34c1:8400:78e3:8816:a14a:2077:50840 ---> 2600:1900:40b0:efbd:0:6c:::11620

{"ssrc":3915492882,"type":200,"report_count":0,"sender_information":{"ntp_timestamp_sec":"1706504082","ntp_timestamp_usec":"49459","rtp_timestamp":794247548,"packets":706,"octets":37725},"report_blocks":[]}
proto:UDP 2024-01-29T04:54:43.05016Z  2600:1900:40b0:efbd:0:6c:::11620 ---> 2001:8003:34c1:8400:78e3:8816:a14a:2077:50840

{"ssrc":580540386,"type":200,"report_count":1,"sender_information":{"ntp_timestamp_sec":"1706504083","ntp_timestamp_usec":"50049","rtp_timestamp":720000,"packets":750,"octets":85812},"report_blocks":[{"source_ssrc":2627945518,"fraction_lost":0,"packets_lost":0,"highest_seq_no":6731,"ia_jitter":28,"lsr":"2920418473","dlsr":50659}]}
proto:UDP 2024-01-29T04:54:44.954424Z  2001:8003:34c1:8400:78e3:8816:a14a:2077:50840 ---> 2600:1900:40b0:efbd:0:6c:::11620

{"ssrc":3915492884,"type":200,"report_count":0,"sender_information":{"ntp_timestamp_sec":"1706504084","ntp_timestamp_usec":"727967","rtp_timestamp":794376092,"packets":840,"octets":44661},"report_blocks":[]}
proto:UDP 2024-01-29T04:54:48.049832Z  2600:1900:40b0:efbd:0:6c:::11620 ---> 2001:8003:34c1:8400:78e3:8816:a14a:2077:50840

{"ssrc":580540386,"type":200,"report_count":1,"sender_information":{"ntp_timestamp_sec":"1706504088","ntp_timestamp_usec":"49704","rtp_timestamp":960000,"packets":1000,"octets":112473},"report_blocks":[{"source_ssrc":2627945518,"fraction_lost":0,"packets_lost":0,"highest_seq_no":6981,"ia_jitter":18,"lsr":"2920594012","dlsr":202833}]}
proto:UDP 2024-01-29T04:54:48.312232Z  2001:8003:34c1:8400:78e3:8816:a14a:2077:50840 ---> 2600:1900:40b0:efbd:0:6c:::11620

{"ssrc":580540386,"type":201,"report_count":1,"sender_information":null,"report_blocks":[{"source_ssrc":580540386,"fraction_lost":0,"packets_lost":0,"highest_seq_no":16993,"ia_jitter":20,"lsr":"2920811705","dlsr":16020}]}
proto:UDP 2024-01-29T04:54:52.09508Z  2001:8003:34c1:8400:78e3:8816:a14a:2077:50840 ---> 2600:1900:40b0:efbd:0:6c:::11620

{"ssrc":3915492891,"type":200,"report_count":0,"sender_information":{"ntp_timestamp_sec":"1706504091","ntp_timestamp_usec":"869025","rtp_timestamp":794718908,"packets":1197,"octets":65633},"report_blocks":[]}
proto:UDP 2024-01-29T04:54:53.050008Z  2600:1900:40b0:efbd:0:6c:::11620 ---> 2001:8003:34c1:8400:78e3:8816:a14a:2077:50840

{"ssrc":580540386,"type":200,"report_count":1,"sender_information":{"ntp_timestamp_sec":"1706504093","ntp_timestamp_usec":"49875","rtp_timestamp":1200000,"packets":1250,"octets":143234},"report_blocks":[{"source_ssrc":2627945518,"fraction_lost":0,"packets_lost":0,"highest_seq_no":7231,"ia_jitter":17,"lsr":"2921062008","dlsr":62521}]}
proto:UDP 2024-01-29T04:54:54.937352Z  2001:8003:34c1:8400:78e3:8816:a14a:2077:50840 ---> 2600:1900:40b0:efbd:0:6c:::11620

{"ssrc":580540386,"type":201,"report_count":1,"sender_information":null,"report_blocks":[{"source_ssrc":580540386,"fraction_lost":0,"packets_lost":0,"highest_seq_no":17324,"ia_jitter":28,"lsr":"2921139396","dlsr":122614}]}
proto:UDP 2024-01-29T04:54:55.99716Z  2001:8003:34c1:8400:78e3:8816:a14a:2077:50840 ---> 2600:1900:40b0:efbd:0:6c:::11620

{"ssrc":3915492895,"type":200,"report_count":0,"sender_information":{"ntp_timestamp_sec":"1706504095","ntp_timestamp_usec":"769992","rtp_timestamp":794906108,"packets":1392,"octets":76797},"report_blocks":[]}
proto:UDP 2024-01-29T04:54:58.04982Z  2600:1900:40b0:efbd:0:6c:::11620 ---> 2001:8003:34c1:8400:78e3:8816:a14a:2077:50840

{"ssrc":580540386,"type":200,"report_count":1,"sender_information":{"ntp_timestamp_sec":"1706504098","ntp_timestamp_usec":"49730","rtp_timestamp":1440000,"packets":1500,"octets":171963},"report_blocks":[{"source_ssrc":2627945518,"fraction_lost":0,"packets_lost":0,"highest_seq_no":7481,"ia_jitter":22,"lsr":"2921317662","dlsr":134479}]}
proto:UDP 2024-01-29T04:54:59.249988Z  2001:8003:34c1:8400:78e3:8816:a14a:2077:50840 ---> 2600:1900:40b0:efbd:0:6c:::11620

{"ssrc":3915492899,"type":200,"report_count":0,"sender_information":{"ntp_timestamp_sec":"1706504099","ntp_timestamp_usec":"24049","rtp_timestamp":795062348,"packets":1555,"octets":85453},"report_blocks":[]}
proto:UDP 2024-01-29T04:54:59.891747Z  2001:8003:34c1:8400:78e3:8816:a14a:2077:50840 ---> 2600:1900:40b0:efbd:0:6c:::11620

{"ssrc":580540386,"type":201,"report_count":1,"sender_information":null,"report_blocks":[{"source_ssrc":580540386,"fraction_lost":0,"packets_lost":0,"highest_seq_no":17572,"ia_jitter":34,"lsr":"2921467067","dlsr":119564}]}
proto:UDP 2024-01-29T04:55:02.575312Z  2001:8003:34c1:8400:78e3:8816:a14a:2077:50840 ---> 2600:1900:40b0:efbd:0:6c:::11620

{"ssrc":3915492902,"type":200,"report_count":0,"sender_information":{"ntp_timestamp_sec":"1706504102","ntp_timestamp_usec":"349512","rtp_timestamp":795221948,"packets":1721,"octets":95517},"report_blocks":[]}
proto:UDP 2024-01-29T04:55:02.813355Z  2001:8003:34c1:8400:78e3:8816:a14a:2077:50840 ---> 2600:1900:40b0:efbd:0:6c:::11620

{"ssrc":580540386,"type":201,"report_count":1,"sender_information":null,"report_blocks":[{"source_ssrc":580540386,"fraction_lost":0,"packets_lost":0,"highest_seq_no":17718,"ia_jitter":20,"lsr":"2921467067","dlsr":311015}]}
proto:UDP 2024-01-29T04:55:03.049751Z  2600:1900:40b0:efbd:0:6c:::11620 ---> 2001:8003:34c1:8400:78e3:8816:a14a:2077:50840

{"ssrc":580540386,"type":200,"report_count":1,"sender_information":{"ntp_timestamp_sec":"1706504103","ntp_timestamp_usec":"49639","rtp_timestamp":1680000,"packets":1750,"octets":201514},"report_blocks":[{"source_ssrc":2627945518,"fraction_lost":0,"packets_lost":0,"highest_seq_no":7731,"ia_jitter":23,"lsr":"2921748857","dlsr":31064}]}
proto:UDP 2024-01-29T04:55:04.960117Z  2001:8003:34c1:8400:78e3:8816:a14a:2077:50840 ---> 2600:1900:40b0:efbd:0:6c:::11620

{"ssrc":2177499142,"type":201,"report_count":0,"sender_information":null,"report_blocks":[]}
proto:TCP 2024-01-29T04:55:05.594507Z  127.0.0.1:6001 ---> 127.0.0.1:47740

BYE sip:va9e5sjskq@127.0.0.1:47740;transport=TCP SIP/2.0
Via: SIP/2.0/TCP 127.0.0.1:6001;rport;branch=z9hG4bKPj8330a0b5-eabf-4a6e-b387-ec8b203e0ee4;alias
From: <sip:response@cpaas-worker-asi.invalid>;tag=5f551ca3-5bdb-45a3-a355-5a0f94b1fee0
To: <sip:webrtc_client@cpaas-worker-asi.invalid>;tag=rotk3i0e3afhvbl
Call-ID: 01HN9S36K9JN09F846H7C5X2RG
CSeq: 11595 BYE
Reason: Q.850;cause=16
Max-Forwards: 70
User-Agent: VXT cpaas-worker
Content-Length:  0


proto:TCP 2024-01-29T04:55:05.597Z  127.0.0.1:47740 ---> 127.0.0.1:6001

SIP/2.0 200 OK
Via: SIP/2.0/TCP 127.0.0.1:6001;rport;branch=z9hG4bKPj8330a0b5-eabf-4a6e-b387-ec8b203e0ee4;alias
From: <sip:response@cpaas-worker-asi.invalid>;tag=5f551ca3-5bdb-45a3-a355-5a0f94b1fee0
To: <sip:webrtc_client@cpaas-worker-asi.invalid>;tag=rotk3i0e3afhvbl
Call-ID: 01HN9S36K9JN09F846H7C5X2RG
CSeq: 11595 BYE
Supported: outbound
User-Agent: VXT SIP
Content-Length: 0

It is hard for us to gather the exact Asterisk logs for the call, since we have multiple calls running simultaneously, but these are our entire logs for the same time period:

[2024-01-29 04:55:08] WARNING[354988][C-00000f09]: mp3/interface.c:218 decodeMP3: Junk at the beginning of frame 49443304
[2024-01-29 04:55:08] WARNING[354988][C-00000f09]: db.c:346 ast_db_put: Family and key length must be less than 253 bytes
[2024-01-29 04:54:56] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[72 omitted]
[2024-01-29 04:54:49] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:49] WARNING[354925][C-00000f11]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay -13144020, threshold 1000, new offset 13144020
[2024-01-29 04:54:49] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:49] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:49] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:49] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:49] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:49] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:48] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:48] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:48] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:48] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:48] WARNING[354897][C-00000f10]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay 12764, threshold 1000, new offset -12764
[2024-01-29 04:54:48] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:48] NOTICE[1558]: res_pjsip_sdp_rtp.c:146 rtp_check_timeout: Disconnecting channel 'PJSIP/webrtc_client-0000155d' for lack of audio RTP activity in 30 seconds
[2024-01-29 04:54:48] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[152 omitted]
[2024-01-29 04:54:33] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:33] NOTICE[1559]: res_hep.c:477 hep_queue_cb: Unable to send packet: Address Family mismatch between source/destination
[2024-01-29 04:54:33] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:32] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:32] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:32] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:32] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:32] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:32] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:32] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:32] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:32] NOTICE[1559]: res_hep.c:477 hep_queue_cb: Unable to send packet: Address Family mismatch between source/destination
[2024-01-29 04:54:32] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:32] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:31] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:31] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:31] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:31] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:31] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:31] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:31] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:31] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:31] NOTICE[1559]: res_hep.c:477 hep_queue_cb: Unable to send packet: Address Family mismatch between source/destination
[2024-01-29 04:54:31] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:31] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:30] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:30] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:30] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:30] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:30] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:30] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:30] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:30] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:30] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:30] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:29] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:29] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:29] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:29] WARNING[355585][C-00000f11]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay -66044717, threshold 1000, new offset 66044717
[2024-01-29 04:54:29] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:29] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:29] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:29] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:29] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:29] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:29] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:28] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:28] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:28] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:28] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:28] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:28] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:28] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:28] WARNING[355560][C-00000f10]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay -16532243, threshold 1000, new offset 16532243
[2024-01-29 04:54:28] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:28] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:28] WARNING[355549][C-00000f0f]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay 2841, threshold 1000, new offset -2841
[2024-01-29 04:54:27] WARNING[354848]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-01-29 04:54:27] NOTICE[1559]: res_hep.c:477 hep_queue_cb: Unable to send packet: Address Family mismatch between source/destination
[2024-01-29 04:54:26] NOTICE[1559]: res_hep.c:477 hep_queue_cb: Unable to send packet: Address Family mismatch between source/destination
[2024-01-29 04:54:25] WARNING[354842][C-00000f0f]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay -58224675, threshold 1000, new offset 58224675
[2024-01-29 04:54:21] NOTICE[1559]: res_hep.c:477 hep_queue_cb: Unable to send packet: Address Family mismatch between source/destination
[2024-01-29 04:54:21] WARNING[354802][C-00000f0e]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay -18310692, threshold 1000, new offset 18310692
[2024-01-29 04:54:21] WARNING[354767][C-00000f0d]: chan_iax2.c:1237 jb_warning_output: Resyncing the jb. last_delay 0, this delay 5526, threshold 1000, new offset -5526

jcolp · February 8, 2024, 9:57am

I was hoping for verbose logs to show what is actually going on to give an idea of everything involved.

duncannz · February 13, 2024, 1:04am

The links in my first post expired but I don’t seem to be able to edit them any more, so here are the recordings uploaded separately:

I have enabled verbose logging using -vvvvvv in our production environment (and also upgraded to Asterisk 20.6.0 for good measure), and we have had further reports of the issue in production since then.

The verbose logs don’t seem to have any identifier that would allow us to narrow them down to a specific call, so with multiple ongoing calls I’m not sure how to provide the complete logs for a specific call. The only logs around the ast_dsp_silence_noise_with_energy logs appear unlikely to be useful:

[many omitted]
[2024-02-13 00:00:39] WARNING[167868]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-02-13 00:00:39] WARNING[167720]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-02-13 00:00:39] WARNING[167868]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-02-13 00:00:39] WARNING[167720]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-02-13 00:00:39] WARNING[167868]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
> 0x7f4d243ac3d0 -- Strict RTP learning after ICE completion
> 0x7f4d243ac3d0 -- Strict RTP learning after remote address set to: [redacted]
[2024-02-13 00:00:39] WARNING[167720]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-02-13 00:00:39] WARNING[167868]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
> 0x7f4d243ac3d0 -- Strict RTP switching to RTP target address [redacted] as source
[2024-02-13 00:00:39] WARNING[167720]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-02-13 00:00:39] WARNING[167962][C-00000850]: chan_iax2.c:1280 jb_warning_output: Resyncing the jb. last_delay 0, this delay -62155937, threshold 1000, new offset 62155937
[2024-02-13 00:00:39] WARNING[167868]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-02-13 00:00:39] WARNING[167720]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-02-13 00:00:39] WARNING[167868]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
> 0x7f4d5c38d040 -- Strict RTP learning complete - Locking on source address [redacted]
[2024-02-13 00:00:39] WARNING[167720]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-02-13 00:00:39] WARNING[167868]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-02-13 00:00:39] WARNING[167720]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-02-13 00:00:39] WARNING[167868]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[2024-02-13 00:00:39] WARNING[167720]: dsp.c:1469 ast_dsp_silence_noise_with_energy: Can only calculate silence on signed-linear, alaw or ulaw frames :(
[many omitted]

Are there any other ways I could gather logs that would be useful for this issue?

Thanks for your help so far!

jcolp · February 13, 2024, 12:34pm

The C- identifier in logging relates to a call, which can be used to isolate things some. That’s the only thing that comes to mind. Someone else may have a suggestion on it.

duncannz · February 17, 2024, 8:42am

Unfortunately I don’t have anything further on the logging front, but I do have a new example of channel recordings that has some very interesting behaviour.

The top channel is a WebRTC endpoint using Opus and sounds perfect.

The bottom channel is a PSTN endpoint that I believe is using alaw (that’s the first rtpmap line in the answerer’s SDP). It has an extremely distorted version of the top channel “bleeding” into it. Additionally, when the party on the bottom channel is actually speaking, it cuts in and out.

Even though the top channel sounds perfect in the recording, both parties report experiencing an audio quality issue.

Zoomed version of left segment:

Zoomed version of right segment:

If anyone has any ideas as to what could cause this it would be much appreciated.

david551 · February 17, 2024, 12:33pm

How were these obtained.

You appear to be getting bursts of the top channel (as though it were multiplied by a low duty cycle square wave, rather than an traditional form of distortion.

I can’t think of any way that Asterisk would do this.

duncannz · February 17, 2024, 11:33pm

These were obtained by setting up a snoop channel (spy: in) on each channel and recording that. We have this logic anyway (recording each channel as well as the bridge) in order to support transcription with speaker identification.

Yes I agree - even when the party in the bottom channel is actually speaking, it is as though their audio is being multiplied by a square wave.

Analysing more closely, I found something interesting: we are always dealing with cycles of 20 ms. When the top channel is bleeding in, this is 5ms on, 15ms off; when the bottom channel is actually speaking it is either 15ms on, 5ms off or sometimes 10ms on, 10ms off (but this may be an anomaly because in other parts of the recording it is consistently 15ms on, 5ms off, and it kind of makes sense that it would be the inverse of the pattern for audio bleeding in).

I’m at a loss as to what could cause something like this. I do know that each RTP packet represents 20 ms so it’s interesting that each cycle is 20 ms, but I don’t know what else to do with that information.

Any further inspiration of things to think about is helpful!

Thanks very much again

duncannz · February 17, 2024, 11:58pm

It’s also worth noting that this issue is a bit different to what I was talking about in the original post. However, I suspect they are strongly related.

I just had a look at the channel recordings for the recording I was talking about in the original post, and in that case the top channel (WebRTC endpoint) also sounds perfect, while the bottom channel (PSTN endpoint) sounds distorted.

However the distortion is a bit different, it appears to be an intense amplification that occurs with a pattern of either 20ms amplified, 80ms normal, or 40ms amplified, 60ms normal. I couldn’t see evidence in those examples of audio bleeding in from the other channel.

Again this seems to be related to the 20ms duration of a single RTP packet.

From example 1 from original post (person talking)

The issue then corrected itself and everything was perfect after 25s:

Note that this was a test call in which the same person was speaking into both ends of the call, so this is not an example of audio bleeding in from the other channel (when that happens, there is virtually no delay).

From example 2 from original post (hold music)

duncannz · February 18, 2024, 12:09am

I have one more example that is slightly different again. In this case there is no audio bleeding in from the other channel, but the distortion on the bottom channel is 15ms on, 5ms off, like we saw when there was audio bleeding in from the other channel.

Again, the top channel sounds perfect in the recording, however both parties report an audio quality issue. Perhaps this means that both audio input and output is mangled for the other party, so the way their output is mangled isn’t captured by the recording.

duncannz · February 18, 2024, 9:46pm

I have tried disabling Opus, so that all legs of the call are just using ulaw or alaw, to see if that made any difference or would give us any additional information. So far, it does not seem to have made a difference, as we have had the following call since then.

This is the issue where there are extreme spikes, which sound like knocking. Again it looks like it turns on and off in multiples of 20ms (labels shown are every 20ms). It resolves itself at the 35 second mark.

Just hoping the additional information may be useful, if anyone has any clues as to where to look to diagnose an issue like this please let me know.

duncannz · February 19, 2024, 10:35pm

We have finally been able to run RTP debug logging during an affected call, and identified the issue.

The issue is that both Asterisk and our provider’s media server appear to switch codecs when they receive a packet using a different codec from the other side. Because this is happening on both ends, some calls get into an infinite loop of switching codecs.

As a temporary/interim measure, we have changed our allowed codec list to only PCMA, so that there is no room for confusion. This has successfully resolved the extreme audio quality issues described in this post. The ast_dsp_silence_noise_with_energy log described in the original post was also a symptom of the same problem, we aren’t seeing it any more.

However, going forward, we would still want to use the preferred codec indicated by our provider for a given call where possible. I have opened a separate topic asking for advice on the best way to implement this while still avoiding the infinite codec switching issue: Infinite codec switching

Hopefully this can help someone else experiencing similar issues in the future

system · March 20, 2024, 10:36pm

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