A (maybe) strange asterisk issue

Segg

Segg

Executive Member
Joined
Feb 25, 2012
Messages
5,452
Reaction score
2,848
Location
FAOR
Hello Everyone

I've got a strange issue I'm having with a new Asterisk (FreePBX) build I'm working on, basically I've managed to sort out hangup detection from the Telkom PSTN, but if a caller hangs up after the IVR has transferred the call to an extension, the extension keeps ringing until it enters voicemail.

I'm pretty certain that the hangup detection on dahdi is working because if you pick up the extension whilst it is still ringing you can hear the busy tone from Telkom, and asterisk proceeds to terminate the connection between the extension and the trunk almost immediately.

Voicemail terminates the call after the busy tone has sounded as well.

The extensions SIP accounts are configured as generic PJSIP devices, and I'm using these phones

I have 4 PSTN lines with hunting facilities

A call will be picked up by the IVR before promoting the user to enter an extension, it will time out after 5 seconds after which it will transfer the call to reception, it will do the same if an incorrect extension is entered.

Now, I'm wanting to enable the Follow Me feature, and email voicemail but I'm holding back on this last step until I can sort this out, so I don't flood the employee's inbox's, and rack up an astronomical phone bill transferring calls to cell phones

Any suggestions will be greatly appreciated :D
 
Segg said:
I'm pretty certain that the hangup detection on dahdi is working because if you pick up the extension whilst it is still ringing you can hear the busy tone from Telkom, and asterisk proceeds to terminate the connection between the extension and the trunk almost immediately.
Click to expand...

I suspect what is more likely here is that Asterisk doesn't know the call is hung up because you are hearing the Telkom tone. What probably happens then is the call drops because Asterisk tries to bridge the call when you pick up and then discovers the caller is gone.

Set this on the CLI
core set debug 9
core set verbose 9
Click to expand...
And check your logs during a call.

Also as a test get someone internal on SIP to call into the IVR and see if you have the same problem.
 
Last edited:
Clarotech said:
I suspect what is more likely here is that Asterisk doesn't know the call is hung up because you are hearing the Telkom tone. What probably happens then is the call drops because Asterisk tries to bridge the call when you pick up and then discovers the caller is gone.

Set this on the CLI

And check your logs during a call.

Also as a test get someone internal on SIP to call into the IVR and see if you have the same problem.
Click to expand...

Thanks, I'll give this a try in the morning :)
 
So here are my logs, for some reason the CLI commands didn't take affect last time

Code: 
[2015-07-20 13:09:35] VERBOSE[9503][C-00000006] app_dial.c: Called PJSIP/1014/sip:[email protected]:5060
[2015-07-20 13:09:35] VERBOSE[9503][C-00000006] app_dial.c: PJSIP/1014-00000007 is ringing
[2015-07-20 13:09:37] VERBOSE[9503][C-00000006] app_dial.c: PJSIP/1014-00000007 answered DAHDI/4-1
[2015-07-20 13:09:37] VERBOSE[9503][C-00000006] bridge_channel.c: Channel DAHDI/4-1 joined 'simple_bridge' basic-bridge <5cd34db7-2702-4b96-9af0-cc053551bc0d>
[2015-07-20 13:09:37] VERBOSE[9525][C-00000006] bridge_channel.c: Channel PJSIP/1014-00000007 joined 'simple_bridge' basic-bridge <5cd34db7-2702-4b96-9af0-cc053551bc0d>
[2015-07-20 13:09:44] VERBOSE[9503][C-00000006] bridge_channel.c: Channel DAHDI/4-1 left 'simple_bridge' basic-bridge <5cd34db7-2702-4b96-9af0-cc053551bc0d>
[2015-07-20 13:09:44] VERBOSE[9525][C-00000006] bridge_channel.c: Channel PJSIP/1014-00000007 left 'simple_bridge' basic-bridge <5cd34db7-2702-4b96-9af0-cc053551bc0d>
[2015-07-20 13:09:44] VERBOSE[9503][C-00000006] app_macro.c: Spawn extension (macro-dial-one, s, 44) exited non-zero on 'DAHDI/4-1' in macro 'dial-one'
[2015-07-20 13:09:44] VERBOSE[9503][C-00000006] app_macro.c: Spawn extension (macro-exten-vm, s, 16) exited non-zero on 'DAHDI/4-1' in macro 'exten-vm'
[2015-07-20 13:09:44] VERBOSE[9503][C-00000006] pbx.c: Spawn extension (ext-local, 1014, 2) exited non-zero on 'DAHDI/4-1'
[2015-07-20 13:09:44] VERBOSE[9503][C-00000006] pbx.c: Executing [h@ext-local:1] Macro("DAHDI/4-1", "hangupcall,") in new stack
[2015-07-20 13:09:44] VERBOSE[9503][C-00000006] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("DAHDI/4-1", "1?theend") in new stack
[2015-07-20 13:09:44] VERBOSE[9503][C-00000006] pbx.c: Goto (macro-hangupcall,s,3)
[2015-07-20 13:09:44] VERBOSE[9503][C-00000006] pbx.c: Executing [s@macro-hangupcall:3] Hangup("DAHDI/4-1", "") in new stack
[2015-07-20 13:09:44] VERBOSE[9503][C-00000006] app_macro.c: Spawn extension (macro-hangupcall, s, 3) exited non-zero on 'DAHDI/4-1' in macro 'hangupcall'
[2015-07-20 13:09:44] VERBOSE[9503][C-00000006] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'DAHDI/4-1'
[2015-07-20 13:09:44] VERBOSE[9503][C-00000006] sig_analog.c: Hanging up on 'DAHDI/4-1'
[2015-07-20 13:09:44] VERBOSE[9503][C-00000006] chan_dahdi.c: Hungup 'DAHDI/4-1'

This is what happens if you pick up the SIP phone after hanging up the cell phone
 
And here is what happens if I just let it ring

Code: 
[2015-07-20 13:19:42] VERBOSE[10316][C-00000007] app_dial.c: Called PJSIP/1014/sip:[email protected]:5060
[2015-07-20 13:19:42] VERBOSE[10316][C-00000007] app_dial.c: PJSIP/1014-00000008 is ringing
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] app_dial.c: Nobody picked up in 45000 ms
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-dial-one:45] ExecIf("DAHDI/4-1", "0?MacroExit()") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-dial-one:46] ExecIf("DAHDI/4-1", "0?Set(DIALSTATUS=)") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-dial-one:47] GosubIf("DAHDI/4-1", "0?s-NOANSWER,1()") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-dial-one:48] MacroExit("DAHDI/4-1", "") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-exten-vm:17] Set("DAHDI/4-1", "SV_DIALSTATUS=NOANSWER") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-exten-vm:18] GosubIf("DAHDI/4-1", "0?docfu,1()") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-exten-vm:19] GosubIf("DAHDI/4-1", "0?docfb,1()") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-exten-vm:20] Set("DAHDI/4-1", "DIALSTATUS=NOANSWER") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-exten-vm:21] ExecIf("DAHDI/4-1", "0?MacroExit()") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-exten-vm:22] GotoIf("DAHDI/4-1", "0?s-NOANSWER,1") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-exten-vm:23] Macro("DAHDI/4-1", "vm,1014,NOANSWER,") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-vm:1] Macro("DAHDI/4-1", "user-callerid,SKIPTTL") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-user-callerid:1] Set("DAHDI/4-1", "TOUCH_MONITOR=1437391168.106") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-user-callerid:2] Set("DAHDI/4-1", "AMPUSER=") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("DAHDI/4-1", "0?report") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("DAHDI/4-1", "1?Set(REALCALLERIDNUM=)") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-user-callerid:5] Set("DAHDI/4-1", "AMPUSER=") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("DAHDI/4-1", "0?limit") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-user-callerid:7] Set("DAHDI/4-1", "AMPUSERCIDNAME=") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("DAHDI/4-1", "1?report") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Goto (macro-user-callerid,s,16)
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-user-callerid:16] GotoIf("DAHDI/4-1", "1?continue") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Goto (macro-user-callerid,s,30)
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-user-callerid:30] Set("DAHDI/4-1", "CALLERID(number)=") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-user-callerid:31] Set("DAHDI/4-1", "CALLERID(name)=") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-user-callerid:32] Set("DAHDI/4-1", "CDR(cnum)=") in new stack
[2015-07-20 13:20:27] WARNING[8136] func_cdr.c: CDR requires a value (CDR(variable)=value)
)[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-user-callerid:33] Set("DAHDI/4-1", "CDR(cnam)=") in new stack
[2015-07-20 13:20:27] WARNING[8136] func_cdr.c: CDR requires a value (CDR(variable)=value)
)[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-user-callerid:34] Set("DAHDI/4-1", "CHANNEL(language)=en") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-vm:2] Set("DAHDI/4-1", "VMGAIN=") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-vm:3] Macro("DAHDI/4-1", "blkvm-check,") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-blkvm-check:1] Set("DAHDI/4-1", "GOSUB_RETVAL=") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-blkvm-check:2] ExecIf("DAHDI/4-1", "0?Set(GOSUB_RETVAL=TRUE)") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-blkvm-check:3] MacroExit("DAHDI/4-1", "") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-vm:4] GotoIf("DAHDI/4-1", "1?vmx,1") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Goto (macro-vm,vmx,1)
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [vmx@macro-vm:1] Set("DAHDI/4-1", "MEXTEN=1014") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [vmx@macro-vm:2] Set("DAHDI/4-1", "MMODE=NOANSWER") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [vmx@macro-vm:3] Set("DAHDI/4-1", "RETVM=") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [vmx@macro-vm:4] Set("DAHDI/4-1", "MODE=unavail") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [vmx@macro-vm:5] Macro("DAHDI/4-1", "get-vmcontext,1014") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-get-vmcontext:1] Set("DAHDI/4-1", "VMCONTEXT=default") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-get-vmcontext:2] GotoIf("DAHDI/4-1", "0?200:300") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Goto (macro-get-vmcontext,s,300)
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-get-vmcontext:300] NoOp("DAHDI/4-1", "") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [vmx@macro-vm:6] Set("DAHDI/4-1", "MODE=unavail") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [vmx@macro-vm:7] NoOp("DAHDI/4-1", "MODE IS: unavail") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [vmx@macro-vm:8] GotoIf("DAHDI/4-1", "1?chknomsg") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Goto (macro-vm,vmx,10)
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [vmx@macro-vm:10] GotoIf("DAHDI/4-1", "0?s-NOANSWER,1") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [vmx@macro-vm:11] GotoIf("DAHDI/4-1", "1?notdirect") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Goto (macro-vm,vmx,13)
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [vmx@macro-vm:13] NoOp("DAHDI/4-1", "Checking if ext 1014 is enabled: ") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [vmx@macro-vm:14] GotoIf("DAHDI/4-1", "1?s-NOANSWER,1") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Goto (macro-vm,s-NOANSWER,1)
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s-NOANSWER@macro-vm:1] Macro("DAHDI/4-1", "get-vmcontext,1014") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-get-vmcontext:1] Set("DAHDI/4-1", "VMCONTEXT=default") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-get-vmcontext:2] GotoIf("DAHDI/4-1", "0?200:300") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Goto (macro-get-vmcontext,s,300)
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s@macro-get-vmcontext:300] NoOp("DAHDI/4-1", "") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] pbx.c: Executing [s-NOANSWER@macro-vm:2] VoiceMail("DAHDI/4-1", "1014@default,u") in new stack
[2015-07-20 13:20:27] VERBOSE[10316][C-00000007] file.c: <DAHDI/4-1> Playing 'vm-theperson.ulaw' (language 'en')
[2015-07-20 13:20:29] VERBOSE[10316][C-00000007] file.c: <DAHDI/4-1> Playing 'digits/1.ulaw' (language 'en')
[2015-07-20 13:20:29] VERBOSE[10316][C-00000007] file.c: <DAHDI/4-1> Playing 'digits/0.ulaw' (language 'en')
[2015-07-20 13:20:30] VERBOSE[10316][C-00000007] file.c: <DAHDI/4-1> Playing 'digits/1.ulaw' (language 'en')
[2015-07-20 13:20:31] VERBOSE[10316][C-00000007] file.c: <DAHDI/4-1> Playing 'digits/4.ulaw' (language 'en')
[2015-07-20 13:20:31] VERBOSE[10316][C-00000007] file.c: <DAHDI/4-1> Playing 'vm-isunavail.ulaw' (language 'en')
[2015-07-20 13:20:32] VERBOSE[10316][C-00000007] file.c: <DAHDI/4-1> Playing 'vm-intro.ulaw' (language 'en')
[2015-07-20 13:20:38] VERBOSE[10316][C-00000007] file.c: <DAHDI/4-1> Playing 'beep.ulaw' (language 'en')
[2015-07-20 13:20:38] VERBOSE[10316][C-00000007] app_voicemail.c: Recording the message
[2015-07-20 13:20:38] VERBOSE[10316][C-00000007] app.c: x=0, open writing: /var/spool/asterisk/voicemail/default/1014/tmp/jqNa4c format: wav, 0x7fe1ec015b88
 
Code: 
[2015-07-20 13:09:35] VERBOSE[9503][C-00000006] app_dial.c: Called PJSIP/1014/sip:[email protected]:5060
[2015-07-20 13:09:35] VERBOSE[9503][C-00000006] app_dial.c: PJSIP/1014-00000007 is ringing
[2015-07-20 13:09:37] VERBOSE[9503][C-00000006] app_dial.c: PJSIP/1014-00000007 answered DAHDI/4-1
[2015-07-20 13:09:37] VERBOSE[9503][C-00000006] bridge_channel.c: Channel DAHDI/4-1 joined 'simple_bridge' basic-bridge <5cd34db7-2702-4b96-9af0-cc053551bc0d>
[2015-07-20 13:09:37] VERBOSE[9525][C-00000006] bridge_channel.c: Channel PJSIP/1014-00000007 joined 'simple_bridge' basic-bridge <5cd34db7-2702-4b96-9af0-cc053551bc0d>
[2015-07-20 13:09:44] VERBOSE[9503][C-00000006] bridge_channel.c: Channel DAHDI/4-1 left 'simple_bridge' basic-bridge <5cd34db7-2702-4b96-9af0-cc053551bc0d>
[2015-07-20 13:09:44] VERBOSE[9525][C-00000006] bridge_channel.c: Channel PJSIP/1014-00000007 left 'simple_bridge' basic-bridge <5cd34db7-2702-4b96-9af0-cc053551bc0d>

Still doesn't look like full verbose/debug logs.

So at what time did you hang-up (exactly)? Logs show that at 13:09:37 1014 answered and the call was bridged. At 13:09:44 the caller hangs-up.
 
Clarotech said:
Code: 
[2015-07-20 13:09:35] VERBOSE[9503][C-00000006] app_dial.c: Called PJSIP/1014/sip:[email protected]:5060
[2015-07-20 13:09:35] VERBOSE[9503][C-00000006] app_dial.c: PJSIP/1014-00000007 is ringing
[2015-07-20 13:09:37] VERBOSE[9503][C-00000006] app_dial.c: PJSIP/1014-00000007 answered DAHDI/4-1
[2015-07-20 13:09:37] VERBOSE[9503][C-00000006] bridge_channel.c: Channel DAHDI/4-1 joined 'simple_bridge' basic-bridge <5cd34db7-2702-4b96-9af0-cc053551bc0d>
[2015-07-20 13:09:37] VERBOSE[9525][C-00000006] bridge_channel.c: Channel PJSIP/1014-00000007 joined 'simple_bridge' basic-bridge <5cd34db7-2702-4b96-9af0-cc053551bc0d>
[2015-07-20 13:09:44] VERBOSE[9503][C-00000006] bridge_channel.c: Channel DAHDI/4-1 left 'simple_bridge' basic-bridge <5cd34db7-2702-4b96-9af0-cc053551bc0d>
[2015-07-20 13:09:44] VERBOSE[9525][C-00000006] bridge_channel.c: Channel PJSIP/1014-00000007 left 'simple_bridge' basic-bridge <5cd34db7-2702-4b96-9af0-cc053551bc0d>

Still doesn't look like full verbose/debug logs.

So at what time did you hang-up (exactly)? Logs show that at 13:09:37 1014 answered and the call was bridged. At 13:09:44 the caller hangs-up.
Click to expand...

I'll post the full logs in a few minutes :)

In this case I had already hung up the cell phone (directly after the IVR) and picked up the extension, it played the Telkom busy tones before hanging up the Telkom line, then proceeded to play it's own busy tone, then hung up the extension
 
You must log in or register to reply here.
Back
Top
Sign up to the MyBroadband newsletter
X