[asterisk-users] Diagnosing call hangups

Wed Dec 21 14:57:43 CST 2011

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