Inbound calls dropped on 1 extension and 1 trunk

[Derrick32]

Hey all,
Firstly PBX in a Flash Version 1.4 is what Im running at the moment. I have a user who has his own phone line from vitelity with a trunk setup to ring direct to his extension. Whenever he answers calls on this line the call doesnt connect. Other trunks are functioning fine with IVR's on same server. I pulled the log from when this was happening, he is extension 2001 in the logs.


[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- Executing [s@macro-exten-vm:8] Macro("SIP/#######-#######", "record-enable|2001|IN") in new stack
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- Executing [s@macro-record-enable:1] GotoIf("SIP/#######-#######", "1?check") in new stack
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- Goto (macro-record-enable,s,4)
[2010-05-26 17:13:58] DEBUG[11552] app_macro.c: Executed application: GotoIf
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- Executing [s@macro-record-enable:4] AGI("SIP/#######-#######", "recordingcheck|20100526-171358|1274919238.4862") in new stack
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: recordingcheck|20100526-171358|1274919238.4862: Inbound recording not enabled
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- AGI Script recordingcheck completed, returning 0
[2010-05-26 17:13:58] DEBUG[11552] app_macro.c: Executed application: AGI
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- Executing [s@macro-record-enable:5] MacroExit("SIP/#######-#######", "") in new stack
[2010-05-26 17:13:58] DEBUG[11552] app_macro.c: Executed application: Macro
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- Executing [s@macro-exten-vm:9] Macro("SIP/#######-#######", "dial|15|tr|2001") in new stack
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- Executing [s@macro-dial:1] GotoIf("SIP/#######-#######", "1?dial") in new stack
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- Goto (macro-dial,s,3)
[2010-05-26 17:13:58] DEBUG[11552] app_macro.c: Executed application: GotoIf
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- Executing [s@macro-dial:3] AGI("SIP/#######-#######", "dialparties.agi") in new stack
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: dialparties.agi: Starting New Dialparties.agi
[2010-05-26 17:13:58] VERBOSE[11555] logger.c: == Parsing '/etc/asterisk/manager.conf': [2010-05-26 17:13:58] VERBOSE[11555] logger.c: Found
[2010-05-26 17:13:58] VERBOSE[11555] logger.c: == Parsing '/etc/asterisk/manager_additional.conf': [2010-05-26 17:13:58] VERBOSE[11555] logger.c: Found
[2010-05-26 17:13:58] VERBOSE[11555] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': [2010-05-26 17:13:58] VERBOSE[11555] logger.c: Found
[2010-05-26 17:13:58] VERBOSE[11555] logger.c: == Manager 'admin' logged on from 127.0.0.1
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: dialparties.agi: Caller ID name is 'Bill Elswick3103728624' number is '3103728624'
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: dialparties.agi: USE_CONFIRMATION: 'FALSE'
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: dialparties.agi: RINGGROUP_INDEX: ''
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: dialparties.agi: Methodology of ring is 'none'
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- dialparties.agi: Added extension 2001 to extension map
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: > dialparties.agi: Extension 2001 has call screening off
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- dialparties.agi: Extension 2001 cf is disabled
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- dialparties.agi: Extension 2001 do not disturb is disabled
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: > dialparties.agi: extnum 2001 has: cw: 1; hascfb: 0 [] hascfu: 0 []
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: dialparties.agi: ExtensionState: 0
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- dialparties.agi: dbset CALLTRACE/2001 to 3103728624
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- dialparties.agi: Filtered ARG3: 2001
[2010-05-26 17:13:58] VERBOSE[11555] logger.c: == Manager 'admin' logged off from 127.0.0.1
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- AGI Script dialparties.agi completed, returning 0
[2010-05-26 17:13:58] DEBUG[11552] app_macro.c: Executed application: AGI
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- Executing [s@macro-dial:7] Dial("SIP/#######-#######", "SIP/2001|15|tr") in new stack
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- Called 2001
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- SIP/2001-0923db10 is ringing
[2010-05-26 17:14:07] VERBOSE[11552] logger.c: -- SIP/2001-0923db10 answered SIP/#######-#######
[2010-05-26 17:14:18] VERBOSE[11552] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on 'SIP/#######-#######' in macro 'dial'
[2010-05-26 17:14:18] VERBOSE[11552] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on 'SIP/#######-#######' in macro 'exten-vm'
[2010-05-26 17:14:18] VERBOSE[11552] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on 'SIP/#######-#######'
[2010-05-26 17:14:18] VERBOSE[11552] logger.c: -- Executing [h@macro-dial:1] Macro("SIP/#######-#######", "hangupcall") in new stack
[2010-05-26 17:14:18] VERBOSE[11552] logger.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/#######-#######", "1?skiprg") in new stack
[2010-05-26 17:14:18] VERBOSE[11552] logger.c: -- Goto (macro-hangupcall,s,4)
[2010-05-26 17:14:18] DEBUG[11552] app_macro.c: Executed application: GotoIf
[2010-05-26 17:14:18] VERBOSE[11552] logger.c: -- Executing [s@macro-hangupcall:4] GotoIf("SIP/#######-#######", "1?skipblkvm") in new stack
[2010-05-26 17:14:18] VERBOSE[11552] logger.c: -- Goto (macro-hangupcall,s,7)
[2010-05-26 17:14:18] DEBUG[11552] app_macro.c: Executed application: GotoIf
[2010-05-26 17:14:18] VERBOSE[11552] logger.c: -- Executing [s@macro-hangupcall:7] GotoIf("SIP/#######-#######", "1?theend") in new stack
[2010-05-26 17:14:18] VERBOSE[11552] logger.c: -- Goto (macro-hangupcall,s,9)
[2010-05-26 17:14:18] DEBUG[11552] app_macro.c: Executed application: GotoIf
[2010-05-26 17:14:18] VERBOSE[11552] logger.c: -- Executing [s@macro-hangupcall:9] Hangup("SIP/#######-#######", "") in new stack

He's an important user in the company, and i need to resolve this immediately. Ill be putting a call into Vitelity to see if there has been any outages, as well as check his trunk config. ANY help would be hugely appreciated!

Thanks,

Derrick

 

[Derrick32]

Can someone explain this behavior?

Why are these phones becoming unreachable so often??

2010-05-26 14:50:34] NOTICE[4132] chan_sip.c: Peer '2004' is now Reachable. (99ms / 2000ms)
[2010-05-26 14:53:32] NOTICE[4132] chan_sip.c: Peer '2001' is now UNREACHABLE! Last qualify: 41
[2010-05-26 14:53:59] VERBOSE[4132] logger.c: -- Registered SIP '2001' at 123.456.7.22 port 55205 expires 120
[2010-05-26 14:53:59] NOTICE[4132] chan_sip.c: Peer '2001' is now Reachable. (99ms / 2000ms)
[2010-05-26 15:00:39] NOTICE[4132] chan_sip.c: Peer '2004' is now UNREACHABLE! Last qualify: 40
[2010-05-26 15:01:05] VERBOSE[4132] logger.c: -- Registered SIP '2004' at 123.456.7.22 port 63486 expires 120
[2010-05-26 15:01:05] NOTICE[4132] chan_sip.c: Peer '2004' is now Reachable. (98ms / 2000ms)
[2010-05-26 15:20:04] NOTICE[4132] chan_sip.c: Peer '2001' is now UNREACHABLE! Last qualify: 41
[2010-05-26 15:20:16] VERBOSE[4132] logger.c: -- Registered SIP '2001' at 123.456.7.22 port 61839 expires 120
[2010-05-26 15:20:16] NOTICE[4132] chan_sip.c: Peer '2001' is now Reachable. (98ms / 2000ms)
[2010-05-26 15:22:23] NOTICE[4132] chan_sip.c: Peer '2000' is now UNREACHABLE! Last qualify: 44
[2010-05-26 15:22:56] VERBOSE[4132] logger.c: -- Registered SIP '2000' at 123.456.7.2 port 58394 expires 120
[2010-05-26 15:22:56] NOTICE[4132] chan_sip.c: Peer '2000' is now Reachable. (106ms / 2000ms)
[2010-05-26 15:28:00] NOTICE[4132] chan_sip.c: Peer '2000' is now UNREACHABLE! Last qualify: 37
[2010-05-26 15:28:11] VERBOSE[4132] logger.c: -- Registered SIP '2000' at 123.456.7.22 port 60620 expires 120
[2010-05-26 15:28:11] NOTICE[4132] chan_sip.c: Peer '2000' is now Reachable. (110ms / 2000ms)
[2010-05-26 15:46:00] NOTICE[4132] chan_sip.c: Peer '2003' is now UNREACHABLE! Last qualify: 45
[2010-05-26 15:46:20] VERBOSE[4132] logger.c: -- Registered SIP '2003' at 123.456.7.7 port 63610 expires 120
[2010-05-26 15:46:20] NOTICE[4132] chan_sip.c: Peer '2003' is now Reachable. (109ms / 2000ms)
[2010-05-26 15:57:10] VERBOSE[4132] logger.c: -- Registered SIP '2004' at 123.456.7.22 port 57416 expires 120
[2010-05-26 16:01:17] NOTICE[4132] chan_sip.c: Peer '2000' is now UNREACHABLE! Last qualify: 37
[2010-05-26 16:01:29] VERBOSE[4132] logger.c: -- Registered SIP '2000' at 123.456.7.2 port 56422 expires 120
[2010-05-26 16:01:29] NOTICE[4132] chan_sip.c: Peer '2000' is now Reachable. (113ms / 2000ms)
[2010-05-26 16:14:23] NOTICE[4132] chan_sip.c: Peer '2007' is now UNREACHABLE! Last qualify: 41
[2010-05-26 16:14:23] NOTICE[4132] chan_sip.c: Peer '2001' is now UNREACHABLE! Last qualify: 41
[2010-05-26 16:14:36] VERBOSE[4132] logger.c: -- Registered SIP '2001' at 123.456.7.7 port 63194 expires 120
[2010-05-26 16:14:36] NOTICE[4132] chan_sip.c: Peer '2001' is now Reachable. (98ms / 2000ms)
[2010-05-26 16:14:40] VERBOSE[4132] logger.c: -- Registered SIP '2007' at 123.456.7.22 port 50833 expires 120
[2010-05-26 16:14:40] NOTICE[4132] chan_sip.c: Peer '2007' is now Reachable. (99ms / 2000ms)
[2010-05-26 16:26:57] NOTICE[4132] chan_sip.c: Peer '2005' is now UNREACHABLE! Last qualify: 87
[2010-05-26 16:27:32] VERBOSE[4132] logger.c: -- Registered SIP '2005' at 123.456.7.7 port 64099 expires 120
[2010-05-26 16:27:32] NOTICE[4132] chan_sip.c: Peer '2005' is now Reachable. (104ms / 2000ms)
[2010-05-26 16:30:16] NOTICE[4132] chan_sip.c: Peer '2004' is now UNREACHABLE! Last qualify: 41

 

[jroper]

Hi

I would suspect network issues.

With qualify set, the phone will deregister if the ping time goes over 2000 ms

Qualify can be set to a higher value you changing qualify=yes to qualify = 4000 (for instance) to see if there is a network issue.

As a quick and easy test, run

mtr 123.456.7.22

for a period of time, and check packet loss and ping times.

Joe

 

[Bitnetix]

[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- Called 2001
[2010-05-26 17:13:58] VERBOSE[11552] logger.c: -- SIP/2001-0923db10 is ringing
[2010-05-26 17:14:07] VERBOSE[11552] logger.c: -- SIP/2001-0923db10 answered SIP/#######-#######

The call is connecting, it's saying so right there. I suspect the phone is not configured correctly, or that your network isn't quite right as Joe suggests, since you've got a lot of reregisters. I'm guessing that the phone is never fully registered and reachable at any given moment, so the call doesn't actually get transferred to the phone.

Does the phone ring in real life? I ask because it was less than a second between when Asterisk said that the extension was ringing and when it was answered. That's a pretty good response time for picking up a phone if you're involved in ANYthing other than waiting for the phone to ring.