Strange Audio on incoming/outgoing calls

FreePBX Providers
1

It seems all of my trunks are ok except for one.

Everytime there is a call (incoming or outgoing) that uses a particular trunk, as soon as both parties have picked up the phone, the person not using the PBX hears a Latin music playing. Always the same song. I don’t have any such music in my on hold so I know its not coming from there. And I’m really at a loss of what could be the issue because everything was working about a week ago then it suddenly stopped. Running freepbx 15, asterisk 13 in a VM. I did move the VM from one host to another a little over a week ago. The problem started about a week ago. I don’t believe that should be the cause as I’ve restored a backup from 2 weeks ago and 2 months ago and both experince the same problem interestingly.

Here is the call log for an incoming call:

969[2020-08-14 10:22:39] verb:app_dial.c: SIP/20-0000000c connected line has changed. Saving it until answer for SIP/FPLOuT-0000000a
970[2020-08-14 10:22:39] verb:app_dial.c: SIP/10-0000000b connected line has changed. Saving it until answer for SIP/FPLOuT-0000000a
971[2020-08-14 10:22:39] verb:app_dial.c: SIP/10-0000000b connected line has changed. Saving it until answer for SIP/FPLOuT-0000000a
972[2020-08-14 10:22:39] verb:app_dial.c: SIP/10-0000000b is ringing
973[2020-08-14 10:22:40] verb:app_dial.c: SIP/20-0000000c connected line has changed. Saving it until answer for SIP/FPLOuT-0000000a
974[2020-08-14 10:22:40] verb:app_dial.c: SIP/20-0000000c is ringing
975[2020-08-14 10:22:40] VERBOSE[7753][C-00000009] pbx.c: Executing [****1122@from-internal:1] TrySystem("Local/****1122@from-internal-00000000;2", "curl -X POST -d "?controller=caller&action=create&name=%22unknown%22&number=14161234567" http://10.0.0.60:1289/caller/") in new stack
976[2020-08-14 10:22:40] verb:app_dial.c: SIP/30-0000000d is ringing
977[2020-08-14 10:22:43] SECURITY[2193] res_security_log.c: SecurityEvent="ChallengeSent",EventTV="2020-08-14T10:22:43.751-0400",Severity="Informational",Service="SIP",EventVersion="1",AccountID="30",SessionID="0x7f5cb003e7b8",LocalAddress="IPV4/UDP/10.0.0.14/5060",RemoteAddress="IPV4/UDP/10.0.0.72/5060",Challenge="55de9b9b"
978[2020-08-14 10:22:43] SECURITY[2193] res_security_log.c: SecurityEvent="SuccessfulAuth",EventTV="2020-08-14T10:22:43.777-0400",Severity="Informational",Service="SIP",EventVersion="1",AccountID="30",SessionID="0x7f5cb003e7b8",LocalAddress="IPV4/UDP/10.0.0.14/5060",RemoteAddress="IPV4/UDP/10.0.0.72/5060",UsingPassword="1"
979[2020-08-14 10:22:45] SECURITY[2193] res_security_log.c: SecurityEvent="SuccessfulAuth",EventTV="2020-08-14T10:22:45.036-0400",Severity="Informational",Service="AMI",EventVersion="1",AccountID="admin",SessionID="0x7f5cb4002ba8",LocalAddress="IPV4/TCP/0.0.0.0/5038",RemoteAddress="IPV4/TCP/127.0.0.1/58688",UsingPassword="0",SessionTV="2020-08-14T10:22:45.036-0400"
980[2020-08-14 10:22:48] SECURITY[2193] res_security_log.c: SecurityEvent="SuccessfulAuth",EventTV="2020-08-14T10:22:48.705-0400",Severity="Informational",Service="AMI",EventVersion="1",AccountID="admin",SessionID="0x7f5cb00568e8",LocalAddress="IPV4/TCP/0.0.0.0/5038",RemoteAddress="IPV4/TCP/127.0.0.1/58694",UsingPassword="0",SessionTV="2020-08-14T10:22:48.705-0400"
981[2020-08-14 10:22:50] verb:app_dial.c: SIP/10-0000000b connected line has changed. Saving it until answer for SIP/FPLOuT-0000000a
982[2020-08-14 10:22:50] verb:app_dial.c: SIP/10-0000000b answered SIP/FPLOuT-0000000a
983[2020-08-14 10:22:50] verb:pbx.c: Executing [s@macro-auto-blkvm:1] Set("SIP/10-0000000b", "__MACRO_RESULT=") in new stack
984[2020-08-14 10:22:50] verb:pbx.c: Executing [s@macro-auto-blkvm:2] Set("SIP/10-0000000b", "CFIGNORE=") in new stack
985[2020-08-14 10:22:50] verb:pbx.c: Executing [s@macro-auto-blkvm:3] Set("SIP/10-0000000b", "MASTER_CHANNEL(CFIGNORE)=") in new stack
986[2020-08-14 10:22:50] verb:pbx.c: Executing [s@macro-auto-blkvm:4] Set("SIP/10-0000000b", "FORWARD_CONTEXT=from-internal") in new stack
987[2020-08-14 10:22:50] verb:pbx.c: Executing [s@macro-auto-blkvm:5] Set("SIP/10-0000000b", "MASTER_CHANNEL(FORWARD_CONTEXT)=from-internal") in new stack
988[2020-08-14 10:22:50] verb:pbx.c: Executing [s@macro-auto-blkvm:6] Macro("SIP/10-0000000b", "blkvm-clr,") in new stack
989[2020-08-14 10:22:50] verb:pbx.c: Executing [s@macro-blkvm-clr:1] Set("SIP/10-0000000b", "SHARED(BLKVM,SIP/FPLOuT-0000000a)=") in new stack
990[2020-08-14 10:22:50] verb:pbx.c: Executing [s@macro-blkvm-clr:2] Set("SIP/10-0000000b", "GOSUB_RETVAL=") in new stack
991[2020-08-14 10:22:50] verb:pbx.c: Executing [s@macro-blkvm-clr:3] MacroExit("SIP/10-0000000b", "") in new stack
992[2020-08-14 10:22:50] verb:pbx.c: Executing [s@macro-auto-blkvm:7] ExecIf("SIP/10-0000000b", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=10)") in new stack
993[2020-08-14 10:22:50] verb:pbx.c: Executing [s@macro-auto-blkvm:8] ExecIf("SIP/10-0000000b", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=UserName)") in new stack
994[2020-08-14 10:22:50] VERBOSE[7771][C-00000009] bridge_channel.c: Channel SIP/10-0000000b joined 'simple_bridge' basic-bridge <248a36fc-493d-49c1-aa8a-4b3559541c5f>
995[2020-08-14 10:22:50] verb:bridge_channel.c: Channel SIP/FPLOuT-0000000a joined 'simple_bridge' basic-bridge <248a36fc-493d-49c1-aa8a-4b3559541c5f>
996[2020-08-14 10:22:52] SECURITY[2193] res_security_log.c: SecurityEvent="SuccessfulAuth",EventTV="2020-08-14T10:22:52.029-0400",Severity="Informational",Service="AMI",EventVersion="1",AccountID="admin",SessionID="0x7f5ca4000d78",LocalAddress="IPV4/TCP/0.0.0.0/5038",RemoteAddress="IPV4/TCP/127.0.0.1/58700",UsingPassword="0",SessionTV="2020-08-14T10:22:52.029-0400"
997[2020-08-14 10:22:55] SECURITY[2193] res_security_log.c: SecurityEvent="SuccessfulAuth",EventTV="2020-08-14T10:22:55.378-0400",Severity="Informational",Service="AMI",EventVersion="1",AccountID="admin",SessionID="0x7f5ca0106338",LocalAddress="IPV4/TCP/0.0.0.0/5038",RemoteAddress="IPV4/TCP/127.0.0.1/58706",UsingPassword="0",SessionTV="2020-08-14T10:22:55.378-0400"
998[2020-08-14 10:22:58] SECURITY[2193] res_security_log.c: SecurityEvent="SuccessfulAuth",EventTV="2020-08-14T10:22:58.695-0400",Severity="Informational",Service="AMI",EventVersion="1",AccountID="admin",SessionID="0x7f5cac00fc88",LocalAddress="IPV4/TCP/0.0.0.0/5038",RemoteAddress="IPV4/TCP/127.0.0.1/58712",UsingPassword="0",SessionTV="2020-08-14T10:22:58.695-0400"
999[2020-08-14 10:22:59] VERBOSE[7771][C-00000009] bridge_channel.c: Channel SIP/10-0000000b left 'simple_bridge' basic-bridge <248a36fc-493d-49c1-aa8a-4b3559541c5f>
1000[2020-08-14 10:22:59] verb:bridge_channel.c: Channel SIP/FPLOuT-0000000a left 'simple_bridge' basic-bridge <248a36fc-493d-49c1-aa8a-4b3559541c5f>
1001[2020-08-14 10:22:59] verb:app_macro.c: Spawn extension (macro-dial, s, 24) exited non-zero on 'SIP/FPLOuT-0000000a' in macro 'dial'
1002[2020-08-14 10:22:59] verb:pbx.c: Spawn extension (ext-group, 600, 18) exited non-zero on 'SIP/FPLOuT-0000000a'
1003[2020-08-14 10:22:59] verb:pbx.c: Executing [h@ext-group:1] Macro("SIP/FPLOuT-0000000a", "hangupcall,") in new stack
1004[2020-08-14 10:22:59] verb:pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/FPLOuT-0000000a", "1?theend") in new stack
1005[2020-08-14 10:22:59] verb:pbx_builtins.c: Goto (macro-hangupcall,s,3)
1006[2020-08-14 10:22:59] verb:pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/FPLOuT-0000000a", "0?Set(CDR(recordingfile)=)") in new stack
1007[2020-08-14 10:22:59] verb:pbx.c: Executing [s@macro-hangupcall:4] NoOp("SIP/FPLOuT-0000000a", "Local/****1122@from-internal-00000000;1 montior file= /var/spool/asterisk/monitor/2020/08/14/in-19051234567-14161234567-20200814-102238-1597414958.10.wav") in new stack
1008[2020-08-14 10:22:59] verb:pbx.c: Executing [s@macro-hangupcall:5] GotoIf("SIP/FPLOuT-0000000a", "0?skipagi") in new stack
1009[2020-08-14 10:22:59] verb:pbx.c: Executing [s@macro-hangupcall:6] AGI("SIP/FPLOuT-0000000a", "attendedtransfer-rec-restart.php,Local/****1122@from-internal-00000000;1,/var/spool/asterisk/monitor/2020/08/14/in-19051234567-14161234567-20200814-102238-1597414958.10.wav") in new stack
1010[2020-08-14 10:22:59] verb:res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/attendedtransfer-rec-restart.php
1011[2020-08-14 10:23:00] SECURITY[2193] res_security_log.c: SecurityEvent="SuccessfulAuth",EventTV="2020-08-14T10:23:00.406-0400",Severity="Informational",Service="AMI",EventVersion="1",AccountID="admin",SessionID="0x7f5ca804e048",LocalAddress="IPV4/TCP/0.0.0.0/5038",RemoteAddress="IPV4/TCP/127.0.0.1/58718",UsingPassword="0",SessionTV="2020-08-14T10:23:00.406-0400"
1012[2020-08-14 10:23:00] verb:res_agi.c: <SIP/FPLOuT-0000000a>AGI Script attendedtransfer-rec-restart.php completed, returning 0
1013[2020-08-14 10:23:00] verb:pbx.c: Executing [s@macro-hangupcall:7] Hangup("SIP/FPLOuT-0000000a", "") in new stack
1014[2020-08-14 10:23:00] verb:app_macro.c: Spawn extension (macro-hangupcall, s, 7) exited non-zero on 'SIP/FPLOuT-0000000a' in macro 'hangupcall'
1015[2020-08-14 10:23:00] verb:pbx.c: Spawn extension (ext-group, h, 1) exited non-zero on 'SIP/FPLOuT-0000000a'
1016[2020-08-14 10:23:00] VERBOSE[7743][C-00000009] app_mixmonitor.c: MixMonitor close fiUserNametream (mixed)
1017[2020-08-14 10:23:00] VERBOSE[7743][C-00000009] app_mixmonitor.c: End MixMonitor Recording SIP/FPLOuT-0000000a

and the associated call event log:
Call Event Log - Search Returned 24 Events
Fri, 14 Aug 2020 10:22 CHAN_START 14161234567 14161234567 DEFAULT 19051234567 from-trunk SIP/FPLOuT-0000000a
Fri, 14 Aug 2020 10:22 APP_START 14161234567 14161234567 14161234567 19051234567 DEFAULT recordcheck sub-record-check MixMonitor SIP/FPLOuT-0000000a
Fri, 14 Aug 2020 10:22 APP_END 14161234567 14161234567 14161234567 19051234567 DEFAULT recordcheck sub-record-check MixMonitor SIP/FPLOuT-0000000a
Fri, 14 Aug 2020 10:22 CHAN_START User1 10 DEFAULT s from-internal SIP/10-0000000b
Fri, 14 Aug 2020 10:22 CHAN_START Fax 20 DEFAULT s from-internal SIP/20-0000000c
Fri, 14 Aug 2020 10:22 CHAN_START ExtraLine 30 DEFAULT s from-internal SIP/30-0000000d
Fri, 14 Aug 2020 10:22 CHAN_START DEFAULT ****1122 from-internal Local/****1122@from-internal-00000000;1
Fri, 14 Aug 2020 10:22 CHAN_START DEFAULT ****1122 from-internal Local/****1122@from-internal-00000000;2
Fri, 14 Aug 2020 10:22 ANSWER User1 10 10 DEFAULT 600 from-internal AppDial SIP/10-0000000b
Fri, 14 Aug 2020 10:22 HANGUP User2 20 20 DEFAULT 600 from-internal AppDial SIP/20-0000000c
Fri, 14 Aug 2020 10:22 CHAN_END User2 20 20 DEFAULT 600 from-internal AppDial SIP/20-0000000c
Fri, 14 Aug 2020 10:22 HANGUP ExtraLine 30 30 DEFAULT 600 from-internal AppDial SIP/30-0000000d
Fri, 14 Aug 2020 10:22 CHAN_END ExtraLine 30 30 DEFAULT 600 from-internal AppDial SIP/30-0000000d
Fri, 14 Aug 2020 10:22 HANGUP 600 DEFAULT 600 from-internal AppDial Local/****1122@from-internal-00000000;1
Fri, 14 Aug 2020 10:22 CHAN_END 600 DEFAULT 600 from-internal AppDial Local/****1122@from-internal-00000000;1
Fri, 14 Aug 2020 10:22 ANSWER unknown 14161234567 14161234567 19051234567 DEFAULT s macro-dial Dial SIP/FPLOuT-0000000a
Fri, 14 Aug 2020 10:22 BRIDGE_ENTER User1 10 10 DEFAULT s macro-dial AppDial SIP/10-0000000b
Fri, 14 Aug 2020 10:22 BRIDGE_ENTER unknown 14161234567 14161234567 19051234567 DEFAULT s macro-dial Dial SIP/FPLOuT-0000000a
Fri, 14 Aug 2020 10:22 BRIDGE_EXIT User1 10 10 DEFAULT s macro-dial AppDial SIP/10-0000000b
Fri, 14 Aug 2020 10:22 HANGUP User1 10 10 DEFAULT s macro-dial AppDial SIP/10-0000000b
Fri, 14 Aug 2020 10:22 CHAN_END User1 10 10 DEFAULT s macro-dial AppDial SIP/10-0000000b
Fri, 14 Aug 2020 10:22 BRIDGE_EXIT unknown 14161234567 14161234567 19051234567 DEFAULT s macro-dial Dial SIP/FPLOuT-0000000a
Fri, 14 Aug 2020 10:23 HANGUP unknown 14161234567 14161234567 19051234567 DEFAULT h ext-group SIP/FPLOuT-0000000a
Fri, 14 Aug 2020 10:23 CHAN_END unknown 14161234567 14161234567 19051234567 DEFAULT h ext-group SIP/FPLOuT-0000000a

Related Call Detail Records

Call Date Recording System CallerID Outbound CallerID DID App Destination Disposition Duration Userfield Account CDR Table CDR Graph
Fri, 14 Aug 2020 10:22 Call recording Call recording 1597414958.10 “unknown” <14161234567> 19051234567 Dial 600 ANSWERED 00:21
Fri, 14 Aug 2020 10:22 Call recording Call recording 1597414958.10 “unknown” <14161234567> 19051234567 Dial 600 NO ANSWER 00:10
Fri, 14 Aug 2020 10:22 Call recording Call recording 1597414958.10 “unknown” <14161234567> 19051234567 Dial 600 NO ANSWER 00:10
Fri, 14 Aug 2020 10:22 Call recording Call recording 1597414958.10 “unknown” <14161234567> 19051234567 Dial 600 NO ANSWER 00:10

Any help would be appreciated.

2

I strongly suspect that the trunking provider (or their upstream) is playing hold music when they do not receive proper audio from the PBX. The question is why has this suddenly started happening.

Some guesses:

FPL (FreePhoneLine ?) made a change so they are now fussier about codecs or packetization.

FPL changed media server addresses to ones now being blocked by your firewall.

Your router/firewall has a buggy SIP ALG and an otherwise innocuous change has caused it to malfunction.

Some debugging options:

  1. At the Asterisk command prompt, type
    sip set debug on
    and make another failing test call. Paste the Asterisk log (which will now include a SIP trace) at pastebin.freepbx.org and post the link here.
  2. If the above doesn’t show the problem, run a tcpdump capture on the PBX of a failing call and post it. This will show whether proper RTP is being sent to the correct address and port at FPL.
  3. If (2) also doesn’t show the trouble, capture traffic on the WAN interface of your router and check for proper RTP being sent to the right place.
  4. If (3) still shows no problem, you could try accessing the FPL account from another device or another account from this device.
  5. If still no luck, I see no choice other than getting help from FPL.
3

at the cli type

rtp set debug on

it will reveal the ip of the media source

1 Like
4

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