[asterisk-users] Diagnosing call hangups

[Tobias Steen]

If you are running version 1.8 or newer you can enable CEL (Channel Event Logging) to get a better view of the channel events.

A common issue for terminating calls is high packet loss, you can measure the network with some kind of probe.

Also, don’t forget the guides here:
http://www.voiptroubleshooter.com/diagnosis/index.html


/ Tobias


-----Original Message-----
From: Jeff LaCoursiere [mailto:jeff at sunfone.com] 
Sent: den 21 december 2011 21:58
To: asterisk-users at lists.digium.com
Subject: [asterisk-users] Diagnosing call hangups


Hi,

I have customers complaining of random call hangups, and I am trying to determine in each case what happened to the call.  I normally run a customer's PBX with verbose set to 3 and debug off, and looking at each case in the "full" log (default full in logger.conf) I don't see anything special between the call being answered and the call terminating - the log lines look exactly the same whether the local side hung up on purpose, the remote side hung up on purpose, or something unknown happened and the call simply terminates (FreePBX dialplan in
place):

Examples from our lab today:

[Dec 21 14:17:31] VERBOSE[12854] logger.c:     -- SIP/astnorth-00000f70
answered SIP/100-00000f6f

LOCAL SIDE HUNGUP

[Dec 21 14:17:37] VERBOSE[12854] logger.c:     -- Executing
[h at macro-dialout-trunk:1] Macro("SIP/100-00000f6f", "hangupcall|") in new stack

------

[Dec 21 14:14:44] VERBOSE[12764] logger.c:     -- SIP/astnorth-00000f6c
answered SIP/100-00000f6b

REMOTE SIDE HUNGUP

[Dec 21 14:14:56] VERBOSE[12764] logger.c:     -- Executing
[h at macro-dialout-trunk:1] Macro("SIP/100-00000f6b", "hangupcall|") in new stack

-----

An example from the customer site:

[Dec 19 13:24:04] VERBOSE[13794] logger.c:     -- SIP/sunfone-000052ad
answered SIP/239-000052ac
[Dec 19 13:24:04] VERBOSE[13794] logger.c:     -- Packet2Packet bridging
SIP/239-000052ac and SIP/sunfone-000052ad

UNKNOWN EVENT

[Dec 19 13:24:11] VERBOSE[13794] logger.c:     -- Executing
[h at macro-dialout-trunk:1] Macro("SIP/239-000052ac", "hangupcall|") in new stack

------------------------------------

So in our lab I turned up verbose to 100 and debug to 100 and made some tests with a local SIP phone calling out to a cell via our upstream
provider:

[Dec 21 14:19:56] VERBOSE[12912] logger.c:     -- SIP/astnorth-00000f72
answered SIP/100-00000f71
[Dec 21 14:19:56] DEBUG[12912] devicestate.c: Notification of state change to be queued on device/channel SIP/100 [Dec 21 14:19:56] DEBUG[12912] chan_sip.c: SIP answering channel:
SIP/100-00000f71
[Dec 21 14:19:56] DEBUG[12912] rtp.c: Setting the marker bit due to a source update [Dec 21 14:19:56] DEBUG[12912] chan_sip.c: Setting framing from config on incoming call [Dec 21 14:19:56] DEBUG[12912] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Dec 21 14:19:56] DEBUG[12912] chan_sip.c: ** Our prefcodec: 0x0
(nothing)
[Dec 21 14:19:56] DEBUG[12912] chan_sip.c: -- Done with adding codecs to SDP [Dec 21 14:19:56] DEBUG[12912] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Dec 21 14:19:56] DEBUG[12912] res_features.c: Removing dialed interfaces datastore on SIP/100-00000f71 since we're bridging [Dec 21 14:19:56] DEBUG[12912] res_features.c: Removing dialed interfaces datastore on SIP/astnorth-00000f72 since we're bridging [Dec 21 14:19:56] DEBUG[12912] rtp.c: Setting the marker bit due to a source update [Dec 21 14:19:56] DEBUG[12912] rtp.c: Setting the marker bit due to a source update [Dec 21 14:19:56] DEBUG[12912] rtp.c: Got RTCP report of 64 bytes

REMOTE SIDE HUNGUP

[Dec 21 14:20:01] DEBUG[12912] rtp.c: Got RTCP report of 64 bytes [Dec 21 14:20:03] DEBUG[12912] channel.c: Didn't get a frame from
channel: SIP/astnorth-00000f72
[Dec 21 14:20:03] DEBUG[12912] rtp.c: Setting the marker bit due to a source update [Dec 21 14:20:03] DEBUG[12912] channel.c: Bridge stops bridging channels
SIP/100-00000f71 and SIP/astnorth-00000f72 [Dec 21 14:20:03] DEBUG[12912] pbx.c: Launching 'Macro'
[Dec 21 14:20:03] VERBOSE[12912] logger.c:     -- Executing
[h at macro-dialout-trunk:1] Macro("SIP/100-00000f71", "hangupcall|") in new stack

----

[Dec 21 14:25:12] VERBOSE[13081] logger.c:     -- SIP/astnorth-00000f74
answered SIP/100-00000f73
[Dec 21 14:25:12] DEBUG[13081] devicestate.c: Notification of state change to be queued on device/channel SIP/100 [Dec 21 14:25:12] DEBUG[13081] chan_sip.c: SIP answering channel:
SIP/100-00000f73
[Dec 21 14:25:12] DEBUG[13081] rtp.c: Setting the marker bit due to a source update [Dec 21 14:25:12] DEBUG[13081] chan_sip.c: Setting framing from config on incoming call [Dec 21 14:25:12] DEBUG[13081] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [Dec 21 14:25:12] DEBUG[13081] chan_sip.c: ** Our prefcodec: 0x0
(nothing)
[Dec 21 14:25:12] DEBUG[13081] chan_sip.c: -- Done with adding codecs to SDP [Dec 21 14:25:12] DEBUG[13081] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [Dec 21 14:25:12] DEBUG[13081] res_features.c: Removing dialed interfaces datastore on SIP/100-00000f73 since we're bridging [Dec 21 14:25:12] DEBUG[13081] res_features.c: Removing dialed interfaces datastore on SIP/astnorth-00000f74 since we're bridging [Dec 21 14:25:12] DEBUG[13081] rtp.c: Setting the marker bit due to a source update [Dec 21 14:25:12] DEBUG[13081] rtp.c: Setting the marker bit due to a source update [Dec 21 14:25:16] DEBUG[13081] rtp.c: Got RTCP report of 64 bytes

LOCAL SIDE HUNG UP

[Dec 21 14:25:21] DEBUG[13081] rtp.c: Got RTCP report of 64 bytes [Dec 21 14:25:21] DEBUG[13081] channel.c: Didn't get a frame from
channel: SIP/100-00000f73
[Dec 21 14:25:21] DEBUG[13081] rtp.c: Setting the marker bit due to a source update [Dec 21 14:25:21] DEBUG[13081] channel.c: Bridge stops bridging channels
SIP/100-00000f73 and SIP/astnorth-00000f74 [Dec 21 14:25:21] DEBUG[13081] pbx.c: Launching 'Macro'
[Dec 21 14:25:21] VERBOSE[13081] logger.c:     -- Executing
[h at macro-dialout-trunk:1] Macro("SIP/100-00000f73", "hangupcall|") in new stack

-------------------------


After all of that, the question:

The difference seems to be which side reports "Didn't get a frame from channel:".  If the hangup was local, it is the local channel.  If the hangup was remote, it is the remote channel.  I guess that makes sense, but is there something returned from either "Dial" or "Answer" that would allow me to log which side hungup without having to enable debug and plow through a gazillion log lines to find the answer?

How do others debug random hangups for customers?

Thanks!

Jeff LaCoursiere
SunFone