Outbound calls beeing droped when called party does conect the call

mannebk · July 18, 2017, 2:23pm

Hi Folks,

I run the FreePBX 14.0.1.1. with Asterisk 14. I did install the BETA back then.

Last week end I did changed the config to “record all cals” by modifiing the extensions via bulk hanlder to force the recording in all cases.

I did the same to my trunks. force recording.

Now I have a funny thing. We make a call to say a service hotline, or a company where we dail the operator. Now we will be conected to the person we want to talk to. When this person pics up the fone, the call is ended. Spot on. repeatably.

I have no clue where I shold start troubleshooting this one.

I didnt find any helpfull infos in google in combination with the recording setting.

would the output from a call with asterisk -Rvvvvvvvvvv be a starter?

Thanks
Cheers Manne

cynjut · July 18, 2017, 2:25pm

Start by reading through the Wiki. There’s lots of good troubleshooting info in there.

The /var/log/asterisk/full file is the most likely place to check for more info.

mannebk · July 18, 2017, 2:37pm

This is the log of the droped call.
Call started at 15:26:54
Call droped about 15:40, i have not taken a note of the time. I was in holding for being conected to the guy i wanted to talk to.

Any clues?

[2017-07-18 15:26:24] VERBOSE[18844][C-00000143] bridge_channel.c: Channel SIP/LoComVoipDE-0000025d left 'simple_bridge' basic-bridge <be3781d6-3d96-4e05-a8b6-bc118ad88f75>
[2017-07-18 15:26:24] VERBOSE[18842][C-00000143] bridge_channel.c: Channel SIP/224-0000025c left 'simple_bridge' basic-bridge <be3781d6-3d96-4e05-a8b6-bc118ad88f75>
[2017-07-18 15:26:24] VERBOSE[18842][C-00000143] res_musiconhold.c: Stopped music on hold on SIP/224-0000025c
[2017-07-18 15:26:24] VERBOSE[18842][C-00000143] app_macro.c: Spawn extension (macro-dialout-trunk, s, 23) exited non-zero on 'SIP/224-0000025c' in macro 'dialout-trunk'
[2017-07-18 15:26:24] VERBOSE[18842][C-00000143] pbx.c: Spawn extension (from-internal, 091170440044, 7) exited non-zero on 'SIP/224-0000025c'
[2017-07-18 15:26:24] VERBOSE[18842][C-00000143] pbx.c: Executing [h@from-internal:1] Macro("SIP/224-0000025c", "hangupcall") in new stack
[2017-07-18 15:26:24] VERBOSE[18842][C-00000143] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/224-0000025c", "1?theend") in new stack
[2017-07-18 15:26:24] VERBOSE[18842][C-00000143] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2017-07-18 15:26:24] VERBOSE[18842][C-00000143] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/224-0000025c", "0?Set(CDR(recordingfile)=)") in new stack
[2017-07-18 15:26:24] VERBOSE[18842][C-00000143] pbx.c: Executing [s@macro-hangupcall:4] Hangup("SIP/224-0000025c", "") in new stack
[2017-07-18 15:26:24] VERBOSE[18842][C-00000143] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/224-0000025c' in macro 'hangupcall'
[2017-07-18 15:26:24] VERBOSE[18842][C-00000143] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/224-0000025c'
[2017-07-18 15:26:24] VERBOSE[18843][C-00000143] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2017-07-18 15:26:24] VERBOSE[18843][C-00000143] app_mixmonitor.c: End MixMonitor Recording SIP/224-0000025c
[2017-07-18 15:26:54] VERBOSE[1755][C-00000148] netsock2.c: Using SIP RTP TOS bits 184
[2017-07-18 15:26:54] VERBOSE[1755][C-00000148] netsock2.c: Using SIP RTP CoS mark 5
[2017-07-18 15:26:54] VERBOSE[1657] chan_sip.c: Extension Changed 524[ext-local] new state InUse for Notify User 521
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [091170440044@from-internal:1] Macro("SIP/524-00000262", "user-callerid,LIMIT,EXTERNAL,") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/524-00000262", "TOUCH_MONITOR=1500384414.1348") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/524-00000262", "AMPUSER=524") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/524-00000262", "0?report") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/524-00000262", "1?Set(__REALCALLERIDNUM=524)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/524-00000262", "AMPUSER=524") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/524-00000262", "0?limit") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/524-00000262", "AMPUSERCIDNAME=Manne-Trumic") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("SIP/524-00000262", "0?report") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:9] Set("SIP/524-00000262", "AMPUSERCID=524") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:10] Set("SIP/524-00000262", "__DIAL_OPTIONS=Ttr") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:11] Set("SIP/524-00000262", "CALLERID(all)="Manne-Trumic" <524>") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:12] GotoIf("SIP/524-00000262", "0?limit") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:13] ExecIf("SIP/524-00000262", "1?Set(GROUP(concurrency_limit)=524)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:14] ExecIf("SIP/524-00000262", "1?Set(CHANNEL(language)=de)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:15] GotoIf("SIP/524-00000262", "1?continue") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx_builtins.c: Goto (macro-user-callerid,s,29)
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:29] Set("SIP/524-00000262", "CALLERID(number)=524") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:30] Set("SIP/524-00000262", "CALLERID(name)=Manne-Trumic") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:31] GotoIf("SIP/524-00000262", "0?cnum") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:32] Set("SIP/524-00000262", "CDR(cnam)=Manne-Trumic") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:33] Set("SIP/524-00000262", "CDR(cnum)=524") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-user-callerid:34] Set("SIP/524-00000262", "CHANNEL(language)=de") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [091170440044@from-internal:2] Gosub("SIP/524-00000262", "sub-record-check,s,1(out,091170440044,dontcare)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/524-00000262", "0?initialized") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@sub-record-check:2] Set("SIP/524-00000262", "__REC_STATUS=INITIALIZED") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@sub-record-check:3] Set("SIP/524-00000262", "NOW=1500384414") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@sub-record-check:4] Set("SIP/524-00000262", "__DAY=18") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@sub-record-check:5] Set("SIP/524-00000262", "__MONTH=07") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@sub-record-check:6] Set("SIP/524-00000262", "__YEAR=2017") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@sub-record-check:7] Set("SIP/524-00000262", "__TIMESTR=20170718-152654") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@sub-record-check:8] Set("SIP/524-00000262", "__FROMEXTEN=524") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@sub-record-check:9] Set("SIP/524-00000262", "__MON_FMT=wav") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/524-00000262", "Recordings initialized") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/524-00000262", "0?Set(ARG3=dontcare)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@sub-record-check:12] Set("SIP/524-00000262", "REC_POLICY_MODE_SAVE=") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/524-00000262", "0?Set(REC_STATUS=NO)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/524-00000262", "3?checkaction") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx_builtins.c: Goto (sub-record-check,s,17)
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/524-00000262", "1?sub-record-check,out,1") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx_builtins.c: Goto (sub-record-check,out,1)
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [out@sub-record-check:1] NoOp("SIP/524-00000262", "Outbound Recording Check from 524 to 091170440044") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [out@sub-record-check:2] Set("SIP/524-00000262", "RECMODE=force") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [out@sub-record-check:3] ExecIf("SIP/524-00000262", "0?Goto(routewins)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [out@sub-record-check:4] ExecIf("SIP/524-00000262", "0?Goto(routewins)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [out@sub-record-check:5] Gosub("SIP/524-00000262", "recordcheck,1(force,out,091170440044)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/524-00000262", "Starting recording check against force") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/524-00000262", "force") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx_builtins.c: Goto (sub-record-check,recordcheck,5)
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [recordcheck@sub-record-check:5] Set("SIP/524-00000262", "__REC_POLICY_MODE=FORCE") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [recordcheck@sub-record-check:6] GotoIf("SIP/524-00000262", "1?startrec") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx_builtins.c: Goto (sub-record-check,recordcheck,16)
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [recordcheck@sub-record-check:16] NoOp("SIP/524-00000262", "Starting recording: out, 091170440044") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [recordcheck@sub-record-check:17] Set("SIP/524-00000262", "AUDIOHOOK_INHERIT(MixMonitor)=yes") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [recordcheck@sub-record-check:18] Set("SIP/524-00000262", "__CALLFILENAME=out-091170440044-524-20170718-152654-1500384414.1348") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [recordcheck@sub-record-check:19] MixMonitor("SIP/524-00000262", "2017/07/18/out-091170440044-524-20170718-152654-1500384414.1348.wav,abi(LOCAL_MIXMON_ID),") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [recordcheck@sub-record-check:20] Set("SIP/524-00000262", "__MIXMON_ID=0x7fe0c88e9f80") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [recordcheck@sub-record-check:21] Set("SIP/524-00000262", "__RECORD_ID=SIP/524-00000262") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [recordcheck@sub-record-check:22] Set("SIP/524-00000262", "__REC_STATUS=RECORDING") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [recordcheck@sub-record-check:23] Set("SIP/524-00000262", "CDR(recordingfile)=out-091170440044-524-20170718-152654-1500384414.1348.wav") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [recordcheck@sub-record-check:24] Return("SIP/524-00000262", "") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [out@sub-record-check:6] Return("SIP/524-00000262", "") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [091170440044@from-internal:3] ExecIf("SIP/524-00000262", "0 ?Set(CDR(accountcode)=)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [091170440044@from-internal:4] Set("SIP/524-00000262", "ROUTE_CIDSAVE="Manne-Trumic" <524>") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [091170440044@from-internal:5] Set("SIP/524-00000262", "MOHCLASS=default") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [091170440044@from-internal:6] Set("SIP/524-00000262", "_NODEST=") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [091170440044@from-internal:7] Macro("SIP/524-00000262", "dialout-trunk,3,091170440044,,off") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:1] Set("SIP/524-00000262", "DIAL_TRUNK=3") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:2] GosubIf("SIP/524-00000262", "0?sub-pincheck,s,1()") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:3] GotoIf("SIP/524-00000262", "0?disabletrunk,1") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:4] Set("SIP/524-00000262", "DIAL_NUMBER=091170440044") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:5] Set("SIP/524-00000262", "DIAL_TRUNK_OPTIONS=Ttr") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:6] Set("SIP/524-00000262", "OUTBOUND_GROUP=OUT_3") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:7] GotoIf("SIP/524-00000262", "1?nomax") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx_builtins.c: Goto (macro-dialout-trunk,s,9)
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:9] GotoIf("SIP/524-00000262", "0?skipoutcid") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:10] Set("SIP/524-00000262", "DIAL_TRUNK_OPTIONS=T") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:11] Macro("SIP/524-00000262", "outbound-callerid,3") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-outbound-callerid:1] ExecIf("SIP/524-00000262", "0?Set(CALLERPRES(name-pres)=)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-outbound-callerid:2] ExecIf("SIP/524-00000262", "0?Set(CALLERPRES(num-pres)=)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-outbound-callerid:3] ExecIf("SIP/524-00000262", "0?Set(REALCALLERIDNUM=524)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-outbound-callerid:4] GotoIf("SIP/524-00000262", "1?normcid") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx_builtins.c: Goto (macro-outbound-callerid,s,7)
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-outbound-callerid:7] Set("SIP/524-00000262", "USEROUTCID=4971936042") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-outbound-callerid:8] Set("SIP/524-00000262", "EMERGENCYCID=") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-outbound-callerid:9] Set("SIP/524-00000262", "TRUNKOUTCID=4971919792960") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-outbound-callerid:10] GotoIf("SIP/524-00000262", "1?trunkcid") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx_builtins.c: Goto (macro-outbound-callerid,s,15)
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-outbound-callerid:15] ExecIf("SIP/524-00000262", "1?Set(CALLERID(all)=4971919792960)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-outbound-callerid:16] ExecIf("SIP/524-00000262", "1?Set(CALLERID(all)=4971936042)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-outbound-callerid:17] ExecIf("SIP/524-00000262", "0?Set(CALLERID(all)=)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-outbound-callerid:18] ExecIf("SIP/524-00000262", "0?Set(CALLERPRES(name-pres)=prohib_passed_screen)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-outbound-callerid:19] ExecIf("SIP/524-00000262", "0?Set(CALLERPRES(num-pres)=prohib_passed_screen)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-outbound-callerid:20] Set("SIP/524-00000262", "CDR(outbound_cnum)=4971936042") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-outbound-callerid:21] Set("SIP/524-00000262", "CDR(outbound_cnam)=") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:12] GosubIf("SIP/524-00000262", "0?sub-flp-3,s,1()") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:13] Set("SIP/524-00000262", "OUTNUM=091170440044") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:14] Set("SIP/524-00000262", "custom=SIP/LoComVoipDE") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:15] ExecIf("SIP/524-00000262", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)T)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:16] ExecIf("SIP/524-00000262", "0?Set(DIAL_TRUNK_OPTIONS=TM(confirm))") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:17] Macro("SIP/524-00000262", "dialout-trunk-predial-hook,") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/524-00000262", "") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:18] GotoIf("SIP/524-00000262", "0?bypass,1") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:19] ExecIf("SIP/524-00000262", "1?Set(CONNECTEDLINE(num,i)=091170440044)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:20] ExecIf("SIP/524-00000262", "1?Set(CONNECTEDLINE(name,i)=CID:4971936042)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:21] ExecIf("SIP/524-00000262", "0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)4971936042)") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:22] GotoIf("SIP/524-00000262", "0?customtrunk") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-dialout-trunk:23] Dial("SIP/524-00000262", "SIP/LoComVoipDE/091170440044,300,T") in new stack
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] netsock2.c: Using SIP RTP TOS bits 184
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] netsock2.c: Using SIP RTP CoS mark 5
[2017-07-18 15:26:54] VERBOSE[19989][C-00000148] app_dial.c: Called SIP/LoComVoipDE/091170440044
[2017-07-18 15:26:54] VERBOSE[19990][C-00000148] app_mixmonitor.c: Begin MixMonitor Recording SIP/524-00000262
[2017-07-18 15:26:56] VERBOSE[19989][C-00000148] app_dial.c: SIP/LoComVoipDE-00000263 is making progress passing it to SIP/524-00000262
[2017-07-18 15:26:57] VERBOSE[19989][C-00000148] app_dial.c: SIP/LoComVoipDE-00000263 answered SIP/524-00000262
[2017-07-18 15:26:57] VERBOSE[19997][C-00000148] bridge_channel.c: Channel SIP/LoComVoipDE-00000263 joined 'simple_bridge' basic-bridge <ab4977ae-73ee-45e1-9268-502fcdfd2d74>
[2017-07-18 15:26:57] VERBOSE[19989][C-00000148] bridge_channel.c: Channel SIP/524-00000262 joined 'simple_bridge' basic-bridge <ab4977ae-73ee-45e1-9268-502fcdfd2d74>
[2017-07-18 15:39:00] VERBOSE[19989][C-00000148] res_musiconhold.c: Started music on hold, class 'default', on channel 'SIP/524-00000262'
[2017-07-18 15:40:13] VERBOSE[19997][C-00000148] bridge_channel.c: Channel SIP/LoComVoipDE-00000263 left 'simple_bridge' basic-bridge <ab4977ae-73ee-45e1-9268-502fcdfd2d74>
[2017-07-18 15:40:13] VERBOSE[19989][C-00000148] bridge_channel.c: Channel SIP/524-00000262 left 'simple_bridge' basic-bridge <ab4977ae-73ee-45e1-9268-502fcdfd2d74>
[2017-07-18 15:40:13] VERBOSE[19989][C-00000148] res_musiconhold.c: Stopped music on hold on SIP/524-00000262
[2017-07-18 15:40:13] VERBOSE[19989][C-00000148] app_macro.c: Spawn extension (macro-dialout-trunk, s, 23) exited non-zero on 'SIP/524-00000262' in macro 'dialout-trunk'
[2017-07-18 15:40:13] VERBOSE[19989][C-00000148] pbx.c: Spawn extension (from-internal, 091170440044, 7) exited non-zero on 'SIP/524-00000262'
[2017-07-18 15:40:13] VERBOSE[19989][C-00000148] pbx.c: Executing [h@from-internal:1] Macro("SIP/524-00000262", "hangupcall") in new stack
[2017-07-18 15:40:13] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/524-00000262", "1?theend") in new stack
[2017-07-18 15:40:13] VERBOSE[19989][C-00000148] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2017-07-18 15:40:13] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/524-00000262", "0?Set(CDR(recordingfile)=)") in new stack
[2017-07-18 15:40:13] VERBOSE[19989][C-00000148] pbx.c: Executing [s@macro-hangupcall:4] Hangup("SIP/524-00000262", "") in new stack
[2017-07-18 15:40:13] VERBOSE[19989][C-00000148] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/524-00000262' in macro 'hangupcall'
[2017-07-18 15:40:13] VERBOSE[19989][C-00000148] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/524-00000262'
[2017-07-18 15:40:13] VERBOSE[19990][C-00000148] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2017-07-18 15:40:13] VERBOSE[19990][C-00000148] app_mixmonitor.c: End MixMonitor Recording SIP/524-00000262
[2017-07-18 15:40:13] VERBOSE[1657] chan_sip.c: Extension Changed 524[ext-local] new state Idle for Notify User 521
[2017-07-18 15:40:30] VERBOSE[1755][C-00000149] netsock2.c: Using SIP RTP TOS bits 184
[2017-07-18 15:40:30] VERBOSE[1755][C-00000149] netsock2.c: Using SIP RTP CoS mark 5
[2017-07-18 15:40:30] VERBOSE[21049][C-00000149] pbx.c: Executing [091170440044@from-internal:1] Macro("SIP/524-00000264", "user-callerid,LIMIT,EXTERNAL,") in new stack

cynjut · July 18, 2017, 2:55pm

If I’m reading this right, your local machine is killing the connection. I’m not sure why - a SIP DEBUG would probably be your next step to see why the SIP connection is dying.

mannebk · July 18, 2017, 3:47pm

cynjut, thank you so much for your help.

By googling SIP DEBUG I ended reading through an outdated wiki from freepbx
https://wiki.freepbx.org/display/SUP/Providing+Great+Debug
refering to amportal.

But from what I gained there

asterisk -Rvvvvvvvvvv from command line of the pbx machine

followed by

sip set debug peer (peer_name) (to stop: sip set debug off)

would be a good start for the debugging?

anyway, I tryed to reproduce it calling my self via the trunk in use… to no sucess.

So I need to call that company again while running asterisk -Rvvvvvvvvvv from command line. unfortunatly they are closed now…

cynjut · July 18, 2017, 5:35pm

There’s a FreePBX Wiki that talks to how to do good debugging.

I don’t use SIP DEBUG very often, but the CLI in “asterisk -vr” is ‘tab friendly’ so you can build the command up as you need it.

As I think about this, I’m wondering if your problem might not be a codec problem. Just a random thought - how is your system and how are your extensions configured?

mannebk · July 19, 2017, 7:05am

This is a level 5 debug from a droped call. I started at 8:28:06 the call to “35480”

It was answered at 08:28:59. The SIP I made this call from is 524.
debug_log_droped_call.txt.tgz (82,7 KB)

my codec settings are

ulaw
alaw
gsm
g726

cynjut · July 19, 2017, 1:38pm

I can’t download the call log (limitation of the network hardware here).

To test the codec theory, try setting your codec to the “*law” setting for your locale (Ulaw in 'murica and Alaw in All others) just to avoid the transcoding issues. It could be as simple as that.