Outbound call dials but then immediately hangs up. Intermittantly

mmac · November 30, 2011, 3:17pm

When I make an outbound call, my phone shows the call being made, but then it immediately reports the call hung up. This happens about 25% of the time I make an outbound call. I’ve tried it with 3 different softphones and a Polycom 501 with the same results.

It is intermittant, but I have the asterisk log (below) for when it did happen. I’ve changed the actual phone numbers, but you should be able to tell that they are phone numbers. I’m testing the system, so I’m the only one on it. I do have it configured to dial 7 to go out on the dahdi trunk that I want.

Here are my versions:

FreePBX Distro: 1.87.29.55
FreePBX: 2.9.0.7
Asterisk: 1.8.7.1
Dahdi: 2.5.0.1
Kernal: 2.6.18_194.17.1.el5

Here is the log:

[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [717025556666@from-internal:1] Macro("SIP/350-000000ac", "user-callerid,LIMIT,") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/350-000000ac", "AMPUSER=350") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/350-000000ac", "0?report") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/350-000000ac", "1?Set(REALCALLERIDNUM=350)") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-user-callerid:4] Set("SIP/350-000000ac", "AMPUSER=350") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/350-000000ac", "AMPUSERCIDNAME=Michael") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/350-000000ac", "0?report") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/350-000000ac", "AMPUSERCID=350") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-user-callerid:8] Set("SIP/350-000000ac", "CALLERID(all)="Michael" <350>") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-user-callerid:9] GotoIf("SIP/350-000000ac", "0?limit") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-user-callerid:10] ExecIf("SIP/350-000000ac", "1?Set(GROUP(concurrency_limit)=350)") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-user-callerid:11] GosubIf("SIP/350-000000ac", "7?sub-ccss,s,1(from-internal,717025556666)") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@sub-ccss:1] ExecIf("SIP/350-000000ac", "0?Return()") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@sub-ccss:2] Set("SIP/350-000000ac", "CCSS_SETUP=TRUE") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@sub-ccss:3] GosubIf("SIP/350-000000ac", "0?monitor_config,1(from-internal,717025556666):monitor_default,1(from-internal,717025556666)") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [monitor_default@sub-ccss:1] GotoIf("SIP/350-000000ac", "0?is_exten") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [monitor_default@sub-ccss:2] StackPop("SIP/350-000000ac", "") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [monitor_default@sub-ccss:3] Return("SIP/350-000000ac", "FALSE") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-user-callerid:12] ExecIf("SIP/350-000000ac", "0?Set(CHANNEL(language)=)") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-user-callerid:13] GotoIf("SIP/350-000000ac", "1?continue") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Goto (macro-user-callerid,s,26)
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-user-callerid:26] Set("SIP/350-000000ac", "CALLERID(number)=350") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-user-callerid:27] Set("SIP/350-000000ac", "CALLERID(name)=Michael") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-user-callerid:28] Set("SIP/350-000000ac", "CHANNEL(language)=en") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [717025556666@from-internal:2] Set("SIP/350-000000ac", "MOHCLASS=default") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [717025556666@from-internal:3] ExecIf("SIP/350-000000ac", "0?Set(TRUNKCIDOVERRIDE=8662223333)") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [717025556666@from-internal:4] Set("SIP/350-000000ac", "_NODEST=") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [717025556666@from-internal:5] Macro("SIP/350-000000ac", "record-enable,350,OUT,") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-record-enable:1] GotoIf("SIP/350-000000ac", "1?check") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Goto (macro-record-enable,s,4)
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-record-enable:4] ExecIf("SIP/350-000000ac", "0?MacroExit()") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-record-enable:5] GotoIf("SIP/350-000000ac", "0?Group:OUT") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Goto (macro-record-enable,s,14)
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-record-enable:14] GotoIf("SIP/350-000000ac", "0?IN") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-record-enable:15] ExecIf("SIP/350-000000ac", "1?MacroExit()") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [717025556666@from-internal:6] Macro("SIP/350-000000ac", "dialout-trunk,2,17025556666,") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/350-000000ac", "DIAL_TRUNK=2") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/350-000000ac", "0?sub-pincheck,s,1") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/350-000000ac", "0?disabletrunk,1") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/350-000000ac", "DIAL_NUMBER=17025556666") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:5] Set("SIP/350-000000ac", "DIAL_TRUNK_OPTIONS=tr") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:6] Set("SIP/350-000000ac", "OUTBOUND_GROUP=OUT_2") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/350-000000ac", "0?nomax") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:8] GotoIf("SIP/350-000000ac", "0?chanfull") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/350-000000ac", "0?skipoutcid") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:10] Set("SIP/350-000000ac", "DIAL_TRUNK_OPTIONS=") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:11] Macro("SIP/350-000000ac", "outbound-callerid,2") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/350-000000ac", "0?Set(CALLERPRES()=)") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/350-000000ac", "0?Set(REALCALLERIDNUM=350)") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/350-000000ac", "1?normcid") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Goto (macro-outbound-callerid,s,6)
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-outbound-callerid:6] Set("SIP/350-000000ac", "USEROUTCID=8662223333") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-outbound-callerid:7] Set("SIP/350-000000ac", "EMERGENCYCID=") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-outbound-callerid:8] Set("SIP/350-000000ac", "TRUNKOUTCID=8662223333") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/350-000000ac", "1?trunkcid") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Goto (macro-outbound-callerid,s,12)
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-outbound-callerid:12] ExecIf("SIP/350-000000ac", "1?Set(CALLERID(all)=8662223333)") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-outbound-callerid:13] ExecIf("SIP/350-000000ac", "1?Set(CALLERID(all)=8662223333)") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/350-000000ac", "0?Set(CALLERID(all)=)") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/350-000000ac", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/350-000000ac", "0?sub-flp-2,s,1") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/350-000000ac", "OUTNUM=17025556666") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/350-000000ac", "custom=DAHDI/g1") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/350-000000ac", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default))") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/350-000000ac", "0?Set(DIAL_TRUNK_OPTIONS=M(confirm))") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:17] Macro("SIP/350-000000ac", "dialout-trunk-predial-hook,") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/350-000000ac", "") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/350-000000ac", "0?bypass,1") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:19] GotoIf("SIP/350-000000ac", "0?customtrunk") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] pbx.c: -- Executing [s@macro-dialout-trunk:20] Dial("SIP/350-000000ac", "DAHDI/g1/17025556666,300,") in new stack
[2011-11-30 07:53:30] VERBOSE[3879] app_dial.c: -- Called DAHDI/g1/17025556666
[2011-11-30 07:53:31] VERBOSE[3879] app_dial.c: -- DAHDI/1-1 answered SIP/350-000000ac
[2011-11-30 07:53:31] VERBOSE[3879] pbx.c: -- Executing [h@macro-dialout-trunk:1] Macro("SIP/350-000000ac", "hangupcall,") in new stack
[2011-11-30 07:53:31] VERBOSE[3879] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/350-000000ac", "1?theend") in new stack
[2011-11-30 07:53:31] VERBOSE[3879] pbx.c: -- Goto (macro-hangupcall,s,3)
[2011-11-30 07:53:31] VERBOSE[3879] pbx.c: -- Executing [s@macro-hangupcall:3] Hangup("SIP/350-000000ac", "") in new stack
[2011-11-30 07:53:31] VERBOSE[3879] app_macro.c: == Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'SIP/350-000000ac' in macro 'hangupcall'
[2011-11-30 07:53:31] VERBOSE[3879] features.c: == Spawn extension (macro-dialout-trunk, h, 1) exited non-zero on 'SIP/350-000000ac'
[2011-11-30 07:53:31] VERBOSE[3879] sig_analog.c: -- Hanging up on 'DAHDI/1-1'
[2011-11-30 07:53:31] VERBOSE[3879] chan_dahdi.c: -- Hungup 'DAHDI/1-1'
[2011-11-30 07:53:31] VERBOSE[3879] app_macro.c: == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on 'SIP/350-000000ac' in macro 'dialout-trunk'
[2011-11-30 07:53:31] VERBOSE[3879] pbx.c: == Spawn extension (from-internal, 717025556666, 6) exited non-zero on 'SIP/350-000000ac'

The only difference (that I can tell) between when it hangs up and doesn’t hang up is the “hangupcall” execute after the DAHDI/1-1 answered line. If it would help, I’ll be glad to post the log from a successful outbound call.

Just wondering if anyone else had experienced this problem or can tell what’s causing it.

Thanks for your help!

-Michael

mmac · December 3, 2011, 8:37pm

Just allowing myself a single bump.

SkykingOH · December 3, 2011, 11:22pm

There is really nothing in the log that tells us anything other than some event called the hangup macro.

Please use pastebin.ca and provide a link for long logs.

Turn verbosity up to 64 and debug to 64 ‘core set debug on’ and pull the log from the /var/log/asterisk/full file. Maybe something at that debug level will tell you what happened.

If these are copper lines you may need to put a volt/ohm meter across the line and see if the voltage is crossing 18v or the polarity reverse signal is received from telco. Your meter will momentarily switch from negative to positive when the wink is received. You can do it with a digital meter but they are slow to respond. This is why telco guys carry traditional analog multimeters still.

mmac · December 7, 2011, 9:31pm

As always, thanks SkyKing for your input.

It was on a T1 that needed 250 ms delay before sending digits. I just popped in a “w” on the trunk dial rules to have it delay, and it seems to be good to go!

Thanks,

-Michael

SkykingOH · December 7, 2011, 11:13pm

I have seen analog lines need a dial delay, never a PRI.

Glad you got it working.