Dropped call - extension becomes unreachable

Asterisk Asterisk Support
1

This system has been randomly dropping calls and I finally captured something in the logs that might be a clue.

It is Asterisk 1.6.2.16 and FreePBX 2.7.x

Based on the messages below can anyone tell what the cause might be?

[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1002[ext-local] new state InUse for Notify User 1012
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1002[ext-local] new state InUse for Notify User 1010
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1002[ext-local] new state InUse for Notify User 1007
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1002[ext-local] new state InUse for Notify User 1000
[Aug 11 08:11:36] VERBOSE[29466] app_dial.c: – SIP/1002-00000465 answered DAHDI/1-1
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1002[ext-local] new state InUse for Notify User 1004
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1002[ext-local] new state InUse for Notify User 1008
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1016[ext-local] new state Idle for Notify User 1008
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1016[ext-local] new state Idle for Notify User 1002
[Aug 11 08:11:36] VERBOSE[29466] pbx.c: – Executing [s@macro-auto-blkvm:1] Set(“SIP/1002-00000465”, “__MACRO_RESULT=”) in new stack
[Aug 11 08:11:36] VERBOSE[29466] pbx.c: – Executing [s@macro-auto-blkvm:2] NoOp(“SIP/1002-00000465”, “Deleting: BLKVM/7005/DAHDI/1-1 TRUE”) in new stack
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1012[ext-local] new state Idle for Notify User 1008
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1012[ext-local] new state Idle for Notify User 1002
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1010[ext-local] new state Idle for Notify User 1008
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1010[ext-local] new state Idle for Notify User 1002
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1008[ext-local] new state Idle for Notify User 1010
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1008[ext-local] new state Idle for Notify User 1007
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1008[ext-local] new state Idle for Notify User 1000
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1008[ext-local] new state Idle for Notify User 1004
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1008[ext-local] new state Idle for Notify User 1002
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1004[ext-local] new state Idle for Notify User 1008
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1004[ext-local] new state Idle for Notify User 1002
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1000[ext-local] new state Idle for Notify User 1012
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1000[ext-local] new state Idle for Notify User 1008
[Aug 11 08:11:36] VERBOSE[27720] chan_sip.c: == Extension Changed 1000[ext-local] new state Idle for Notify User 1002
[Aug 11 08:14:06] NOTICE[27734] chan_sip.c: Peer ‘1002’ is now UNREACHABLE! Last qualify: 26
[Aug 11 08:14:08] NOTICE[27734] chan_sip.c: Peer ‘1003’ is now UNREACHABLE! Last qualify: 31
[Aug 11 08:14:09] NOTICE[27734] chan_sip.c: Disconnecting call ‘SIP/1002-00000465’ for lack of RTP activity in 31 seconds
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: – Executing [h@macro-dial:1] Macro(“DAHDI/1-1”, “hangupcall”) in new stack
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: – Executing [s@macro-hangupcall:1] GotoIf(“DAHDI/1-1”, “1?skiprg”) in new stack
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: – Goto (macro-hangupcall,s,4)
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: – Executing [s@macro-hangupcall:4] GotoIf(“DAHDI/1-1”, “0?skipblkvm”) in new stack
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: – Executing [s@macro-hangupcall:5] NoOp(“DAHDI/1-1”, “Cleaning Up Block VM Flag: BLKVM/7005/DAHDI/1-1”) in new stack
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: – Executing [s@macro-hangupcall:6] NoOp(“DAHDI/1-1”, "Deleting: BLKVM/7005/DAHDI/1-1 ") in new stack
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: – Executing [s@macro-hangupcall:7] GotoIf(“DAHDI/1-1”, “1?theend”) in new stack
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: – Goto (macro-hangupcall,s,9)
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: – Executing [s@macro-hangupcall:9] Hangup(“DAHDI/1-1”, “”) in new stack
[Aug 11 08:14:09] VERBOSE[29466] app_macro.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on ‘DAHDI/1-1’ in macro ‘hangupcall’
[Aug 11 08:14:09] VERBOSE[29466] features.c: == Spawn extension (macro-dial, h, 1) exited non-zero on ‘DAHDI/1-1’
[Aug 11 08:14:09] VERBOSE[27720] chan_sip.c: == Extension Changed 1002[ext-local] new state Unavailable for Notify User 1012
[Aug 11 08:14:09] VERBOSE[27720] chan_sip.c: == Extension Changed 1002[ext-local] new state Unavailable for Notify User 1010
[Aug 11 08:14:09] VERBOSE[27720] chan_sip.c: == Extension Changed 1002[ext-local] new state Unavailable for Notify User 1007
[Aug 11 08:14:09] VERBOSE[27720] chan_sip.c: == Extension Changed 1002[ext-local] new state Unavailable for Notify User 1000
[Aug 11 08:14:09] VERBOSE[27720] chan_sip.c: == Extension Changed 1002[ext-local] new state Unavailable for Notify User 1004
[Aug 11 08:14:09] VERBOSE[27720] chan_sip.c: == Extension Changed 1002[ext-local] new state Unavailable for Notify User 1008
[Aug 11 08:14:09] VERBOSE[29466] app_macro.c: == Spawn extension (macro-dial, s, 7) exited non-zero on ‘DAHDI/1-1’ in macro ‘dial’
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: == Spawn extension (ext-group, 7005, 14) exited non-zero on ‘DAHDI/1-1’
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: – Executing [h@ext-group:1] Macro(“DAHDI/1-1”, “hangupcall,”) in new stack
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: – Executing [s@macro-hangupcall:1] GotoIf(“DAHDI/1-1”, “1?skiprg”) in new stack
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: – Goto (macro-hangupcall,s,4)
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: – Executing [s@macro-hangupcall:4] GotoIf(“DAHDI/1-1”, “0?skipblkvm”) in new stack
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: – Executing [s@macro-hangupcall:5] NoOp(“DAHDI/1-1”, “Cleaning Up Block VM Flag: BLKVM/7005/DAHDI/1-1”) in new stack
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: – Executing [s@macro-hangupcall:6] NoOp(“DAHDI/1-1”, "Deleting: BLKVM/7005/DAHDI/1-1 ") in new stack
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: – Executing [s@macro-hangupcall:7] GotoIf(“DAHDI/1-1”, “1?theend”) in new stack
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: – Goto (macro-hangupcall,s,9)
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: – Executing [s@macro-hangupcall:9] Hangup(“DAHDI/1-1”, “”) in new stack
[Aug 11 08:14:09] VERBOSE[29466] app_macro.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on ‘DAHDI/1-1’ in macro ‘hangupcall’
[Aug 11 08:14:09] VERBOSE[29466] pbx.c: == Spawn extension (ext-group, h, 1) exited non-zero on ‘DAHDI/1-1’
[Aug 11 08:14:09] VERBOSE[29466] chan_dahdi.c: – Hungup ‘DAHDI/1-1’
[Aug 11 08:14:30] NOTICE[27734] chan_sip.c: Peer ‘1002’ is now Reachable. (29ms / 2000ms)
[Aug 11 08:14:30] VERBOSE[27720] chan_sip.c: == Extension Changed 1002[ext-local] new state Idle for Notify User 1012
[Aug 11 08:14:30] VERBOSE[27720] chan_sip.c: == Extension Changed 1002[ext-local] new state Idle for Notify User 1010
[Aug 11 08:14:30] VERBOSE[27720] chan_sip.c: == Extension Changed 1002[ext-local] new state Idle for Notify User 1007
[Aug 11 08:14:30] VERBOSE[27720] chan_sip.c: == Extension Changed 1002[ext-local] new state Idle for Notify User 1000
[Aug 11 08:14:30] VERBOSE[27720] chan_sip.c: == Extension Changed 1002[ext-local] new state Idle for Notify User 1004
[Aug 11 08:14:30] VERBOSE[27720] chan_sip.c: == Extension Changed 1002[ext-local] new state Idle for Notify User 1008

2

You have qualify enabled and you are losing so many packets that the device is marked down. I would expect broken speech, as well, unless there is something about the other end that means it is OK for speech but loses OPTIONS requests.

3

Losing packets? Does that mean the network connection is bad?

Do I need to disable “qualify”? If so how?

4

overloaded

qualify=no
assuming that you don’t need it for other reasons.

5

I’m sure you’ve already thought about this, but if it’s a network connection issue you might want to try a good old ping test from your asterisk server to your device that is dropping.

ping 10.0.10.151 (assuming your device that is dropping is 10.0.10.151). That would give you a good idea if you are dropping network packets or there is latency on the network.

6

Thanks so much for the input. There are only 2 people on the network with PCs at any given time and 7 phones so I would have never had a clue that the the network could be the problem.

I will definitely try the ping test and start digging.

7

The other thing that causes permormance problems on Asterisk is using virtual machines.

8

There are no VMs on the network and the PBX is running on a vanilla Ubuntu 10.4 server,… But thanks for the heads up.