SIP phone blocked after hanging up

system · August 22, 2012, 8:45pm

I am sure that this is something stupid but I can’t figure it out.
The phone system is a new 1.8.15 on CentOS.
It works OK except for 1 thing.
When you dial from a local SIP phone into another local SIP phone or to a MeetMe confernce room and hangup, the phone can not be used again for a few minutes.
If one is using an Eyebeam softphone, there is a long pause after you dial the second number and you get the Eyebeam message that the person is not available and if you use an Astra hardware phone, it displays that the “call Failed”

It appears that Asterisk sees the phone “exit non-zero” but is not willing to start a new call.

I am not sure where to look. It is probably a single bad setting but I am not sure where to look.
Any suggestions welcomed.

david55 · August 22, 2012, 9:49pm

sip set debug on.

dejanst · August 24, 2012, 7:56am

and Asterisk CLI call debugs (verbosity 3) and the output of “sip show channelstats” command

system · August 24, 2012, 2:25pm

That was very helpful advice.

If I dial and extension and hang up while it is ringing, the channel stay active for a few seconds after I hang up

192.168.3.134 2a7788d3051 0000000000 0000000000 ( 0.00%) 0.0000 0000000000 0000000000 ( 0.00%) 0.0000
192.168.3.107 ODM2NWJkYjE 0000000000 0000000000 ( 0.00%) 0.0000 0000000000 0000000000 ( 0.00%) 0.0000

Another symptom of the problem is:
After dialing an extension(105) from 102 and hanging up on 102 while the other phone is ringing, the SIP phone itself seems to lock up and can not make calls.

The line from the Asterisk consol that mentions 32000 ms seems to correspond to the time for which the phone is stuck.
[Aug 24 10:10:52] VERBOSE[23848] chan_sip.c: Scheduling destruction of SIP dialog ‘91b87b1e14dc7b0d54f423442e3ae6d8@192.168.3.134’ in 32000 ms (Method: REGISTER)

This seems to print out on the consol regularly while the phones are idle.
Before I replaced the old Asterisk with the new one, the phones all worked so I am pretty sure that I screwed up something or missed a configuration item.

Eyebeam reports this in its log

Asterisk consol:
With SIP debugging on, it is really hard to get the logs to synchronize and the following log may include different tests but the syptoms are the same.
<------------>
[Aug 24 10:10:52] VERBOSE[23848] chan_sip.c: Scheduling destruction of SIP dialog ‘91b87b1e14dc7b0d54f423442e3ae6d8@192.168.3.134’ in 32000 ms (Method: REGISTER)
[Aug 24 10:10:52] VERBOSE[23848] chan_sip.c:
<— SIP read from UDP:192.168.3.134:5060 —>
REGISTER sip:192.168.3.10:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.134;branch=z9hG4bK3472510f9
Max-Forwards: 70
Content-Length: 0
To: 105 sip:105@192.168.3.10:5060
From: 105 sip:105@192.168.3.10:5060;tag=a2d857b97241793
Call-ID: 91b87b1e14dc7b0d54f423442e3ae6d8@192.168.3.134
CSeq: 976021689 REGISTER
Contact: 105 sip:105@192.168.3.134
Allow-Events: talk,hold,conference
Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO
Authorization:Digest response=“f2d415ca5d2290a234fc43a9f8d9e4cd”,username=“105”,realm=“asterisk”,nonce=“25e6c863”,algorithm=MD5,uri="sip:192.168.3.10:5060"
User-Agent: Aastra 9133i/1.4.0.1048 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26

<------------->
[Aug 24 10:10:52] VERBOSE[23848] chan_sip.c: — (13 headers 0 lines) —
[Aug 24 10:10:52] VERBOSE[23848] chan_sip.c: Sending to 192.168.3.134:5060 (NAT)
[Aug 24 10:10:52] VERBOSE[23848] chan_sip.c:
<— Transmitting (NAT) to 192.168.3.134:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.3.134;branch=z9hG4bK3472510f9;received=192.168.3.134;rport=5060
From: 105 sip:105@192.168.3.10:5060;tag=a2d857b97241793
To: 105 sip:105@192.168.3.10:5060;tag=as6975e31a
Call-ID: 91b87b1e14dc7b0d54f423442e3ae6d8@192.168.3.134
CSeq: 976021689 REGISTER
Server: Asterisk PBX 1.8.15.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Expires: 120
Contact: sip:105@192.168.3.134;expires=120
Date: Fri, 24 Aug 2012 14:10:52 GMT
Content-Length: 0

<------------>
[Aug 24 10:10:52] VERBOSE[23848] chan_sip.c: Scheduling destruction of SIP dialog ‘4cbbeea44c933c47455091421084797b@192.168.3.10:5060’ in 32000 ms (Method: NOTIFY)
[Aug 24 10:10:52] VERBOSE[23848] chan_sip.c: Reliably Transmitting (NAT) to 192.168.3.134:5060:
NOTIFY sip:105@192.168.3.134 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.10:5060;branch=z9hG4bK14b24f5a;rport
Max-Forwards: 70
From: “asterisk” sip:asterisk@192.168.3.10;tag=as1961539b
To: sip:105@192.168.3.134
Contact: sip:asterisk@192.168.3.10:5060
Call-ID: 4cbbeea44c933c47455091421084797b@192.168.3.10:5060
CSeq: 102 NOTIFY
User-Agent: Asterisk PBX 1.8.15.0
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 88

Messages-Waiting: yes
Message-Account: sip:*97@192.168.3.10
Voice-Message: 1/0 (0/0)

[Aug 24 10:10:52] VERBOSE[23848] chan_sip.c: Scheduling destruction of SIP dialog ‘91b87b1e14dc7b0d54f423442e3ae6d8@192.168.3.134’ in 32000 ms (Method: REGISTER)
[Aug 24 10:10:53] VERBOSE[23848] chan_sip.c:
<— SIP read from UDP:192.168.3.134:5060 —>
SIP/2.0 200 OK
Call-ID: 4cbbeea44c933c47455091421084797b@192.168.3.10:5060
CSeq: 102 NOTIFY
From: “asterisk” sip:asterisk@192.168.3.10;tag=as1961539b
To: sip:105@192.168.3.134;tag=dcbf564d452afdb
Via: SIP/2.0/UDP 192.168.3.10:5060;branch=z9hG4bK14b24f5a;rport
Content-Length: 0
Contact: sip:105@192.168.3.134
Supported: replaces
User-Agent: Aastra 9133i/1.4.0.1048 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26

<------------->
[Aug 24 10:10:53] VERBOSE[23848] chan_sip.c: — (10 headers 0 lines) —
[Aug 24 10:10:53] VERBOSE[23848] chan_sip.c: Really destroying SIP dialog ‘4cbbeea44c933c47455091421084797b@192.168.3.10:5060’ Method: NOTIFY
[Aug 24 10:10:56] VERBOSE[23848] chan_sip.c: Retransmitting #6 (NAT) to 192.168.3.107:17782:
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 192.168.3.107:17782;branch=z9hG4bK-d8754z-d4638e73f2097359-1—d8754z-;received=192.168.3.107;rport=17782
From: "Ron Wheeler"sip:102@192.168.3.10:5060;tag=f31a0673
To: "105"sip:105@192.168.3.10:5060;tag=as321ed57b
Call-ID: OTdjZTAyNmNkMDNjYmY3ODNhYTA2YjI5YjA1ODM1YTk.
CSeq: 2 INVITE
Server: Asterisk PBX 1.8.15.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

[Aug 24 10:11:00] VERBOSE[23848] chan_sip.c: Retransmitting #7 (NAT) to 192.168.3.107:17782:
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 192.168.3.107:17782;branch=z9hG4bK-d8754z-d4638e73f2097359-1—d8754z-;received=192.168.3.107;rport=17782
From: "Ron Wheeler"sip:102@192.168.3.10:5060;tag=f31a0673
To: "105"sip:105@192.168.3.10:5060;tag=as321ed57b
Call-ID: OTdjZTAyNmNkMDNjYmY3ODNhYTA2YjI5YjA1ODM1YTk.
CSeq: 2 INVITE
Server: Asterisk PBX 1.8.15.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

[Aug 24 10:11:04] VERBOSE[23848] chan_sip.c: Retransmitting #8 (NAT) to 192.168.3.107:17782:
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 192.168.3.107:17782;branch=z9hG4bK-d8754z-d4638e73f2097359-1—d8754z-;received=192.168.3.107;rport=17782
From: "Ron Wheeler"sip:102@192.168.3.10:5060;tag=f31a0673
To: "105"sip:105@192.168.3.10:5060;tag=as321ed57b
Call-ID: OTdjZTAyNmNkMDNjYmY3ODNhYTA2YjI5YjA1ODM1YTk.
CSeq: 2 INVITE
Server: Asterisk PBX 1.8.15.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

david55 · August 24, 2012, 2:41pm

You’ve got multiple Request Terminated responses, but not the INVITE that was cancelled, not the cancels. I would assume that Asterisk is not receiving any responses to the cancels, but the trace is incomplete.

The 32 seconds is the time after which a SIP UAC gives up when the UAS fails to respond to repeated attempts to make a request.

system · September 5, 2012, 3:11pm

Any reason why Eyebeam is not responding?
How do I reduce this timeout to 5 seconds.
We are on a LAN.
I think that this is the Eyebeam log from the end of the locked up period but timing is hard to track and it is hard to understand the messages.

[12-09-05]10:45:58.521 | Debug | RESIP:TRANSPORT | “Looked up source for destination: [ V4 192.168.3.10:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:25764 UDP target domain=unspecified connectionId=0 ] connectionId=0 ] -> [ V4 192.168.3.107:0 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:25764 UDP target domain=unspecified connectionId=0 ] connectionId=0 ] sent-by=192.168.3.10 sent-port=5060” |
[12-09-05]10:45:58.521 | Debug | RESIP:TRANSPORT | "Transmitting to [ V4 192.168.3.10:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:25764 UDP target domain=unspecified connectionId=0 ] connectionId=0 ] tlsDomain= via [ V4 192.168.3.107:25764 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:25764 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]

SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.3.10:5060;branch=z9hG4bK5346f5c0;rport=5060
Contact: sip:102@192.168.3.107:25764
To: sip:102@192.168.3.107:25764;tag=6f7a8f3b
From: "“asterisk”"sip:asterisk@192.168.3.10;tag=as2cf6b260
Call-ID: ODEwZWNkNjFmNWVkN2RkNTNlZjgzZTYzMGFhMDNmNmI.
CSeq: 102 NOTIFY
User-Agent: eyeBeam release 1105z stamp 59030
Content-Length: 0

" |
[12-09-05]10:45:58.521 | Debug | RESIP:TRANSPORT | “Adding message to tx buffer to: [ V4 192.168.3.10:5060 UDP target domain=unspecified received on: Transport: [ V4 0.0.0.0:25764 UDP target domain=unspecified connectionId=0 ] connectionId=0 ]” |

david55 · September 5, 2012, 3:21pm

The timeout is part of the SIP specification. You eliminate it by fixing the underlying problem.

The trace you provided is not useful. You need to look at the trace from Asterisk and work out which packet is getting retransmitted.

system · September 5, 2012, 8:31pm

Thanks for your patience
I reran the test with sip debugging on.
I think that I have captured the matching dialogue from both sides. The timestamping is very weak on the Asterisk side.

I created the problem by dialling one of our conference rooms and going through the Meetme process until I was in and then hanging up. The Eyebeam is then unable to make a call (tried extension 105) for a while (3200 ms sounds about right).

Both logs

**********a s t e r i s k

<------------->

<— SIP read from UDP:192.168.3.107:25764 —>
BYE sip:6300@192.168.3.10:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.107:25764;branch=z9hG4bK-d8754z-a8795133e3542242-1—d8754z-;rport
Max-Forwards: 70
Contact: sip:102@192.168.3.107:25764
To: "6300"sip:6300@192.168.3.10:5060;tag=as74a42826
From: "Ron Wheeler"sip:102@192.168.3.10:5060;tag=041d4319
Call-ID: NjMxNGIyMzExZGZkZGRlZDY3MzI0YmE1YTVmZDcxOWM.
CSeq: 3 BYE
User-Agent: eyeBeam release 1105z stamp 59030
Authorization: Digest username=“102”,realm=“asterisk”,nonce=“07586622”,uri=“sip:6300@192.168.3.10:5060”,response=“f78f63ee96fd754aa332a0c56c7e5d52”,algorithm=MD5
Reason: SIP;description="User Hung Up"
Content-Length: 0

<------------->
— (12 headers 0 lines) —
Sending to 192.168.3.107:25764 (NAT)
Scheduling destruction of SIP dialog ‘NjMxNGIyMzExZGZkZGRlZDY3MzI0YmE1YTVmZDcxOWM.’ in 32000 ms (Method: BYE)

<— Transmitting (NAT) to 192.168.3.107:25764 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.3.107:25764;branch=z9hG4bK-d8754z-a8795133e3542242-1—d8754z-;received=192.168.3.107;rport=25764
From: "Ron Wheeler"sip:102@192.168.3.10:5060;tag=041d4319
To: "6300"sip:6300@192.168.3.10:5060;tag=as74a42826
Call-ID: NjMxNGIyMzExZGZkZGRlZDY3MzI0YmE1YTVmZDcxOWM.
CSeq: 3 BYE
Server: Asterisk PBX 1.8.15.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

<------------>
– Stopped music on hold on SIP/102-00000009
– Hungup ‘DAHDI/pseudo-842728396’
– Hungup ‘DAHDI/pseudo-312433482’
== Spawn extension (DLPN_DialPlan1, 6300, 2) exited non-zero on ‘SIP/102-00000009’
– Executing [h@DLPN_DialPlan1:1] Hangup(“SIP/102-00000009”, “”) in new stack
== Spawn extension (DLPN_DialPlan1, h, 1) exited non-zero on ‘SIP/102-00000009’

<— SIP read from UDP:192.168.3.107:25764 —>
INVITE sip:105@192.168.3.10:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.107:25764;branch=z9hG4bK-d8754z-87755d6c96144e5c-1—d8754z-;rport
Max-Forwards: 70
Contact: sip:102@192.168.3.107:25764
To: "105"sip:105@192.168.3.10:5060
From: "Ron Wheeler"sip:102@192.168.3.10:5060;tag=be36e433
Call-ID: OTZlYmRmNjE5ZTI3NTVlZjU4NGViZmY4ZGJkYmU4MmU.
CSeq: 1 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
Content-Type: application/sdp
User-Agent: eyeBeam release 1105z stamp 59030
Content-Length: 287

v=0
o=- 5 2 IN IP4 192.168.3.107
s=CounterPath eyeBeam 1.5
c=IN IP4 192.168.3.107
t=0 0
m=audio 61148 RTP/AVP 0 8 18 101
a=alt:1 1 : XaxIn4Qf t5XoGeo9 192.168.3.107 61148
a=fmtp:18 annexb=yes
a=fmtp:101 0-15
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=sendrecv
<------------->
— (12 headers 12 lines) —
Sending to 192.168.3.107:25764 (NAT)
Using INVITE request as basis request - OTZlYmRmNjE5ZTI3NTVlZjU4NGViZmY4ZGJkYmU4MmU.
Found peer ‘102’ for ‘102’ from 192.168.3.107:25764

<— Reliably Transmitting (NAT) to 192.168.3.107:25764 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.3.107:25764;branch=z9hG4bK-d8754z-87755d6c96144e5c-1—d8754z-;received=192.168.3.107;rport=25764
From: "Ron Wheeler"sip:102@192.168.3.10:5060;tag=be36e433
To: "105"sip:105@192.168.3.10:5060;tag=as17c0478b
Call-ID: OTZlYmRmNjE5ZTI3NTVlZjU4NGViZmY4ZGJkYmU4MmU.
CSeq: 1 INVITE
Server: Asterisk PBX 1.8.15.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce="1c725c35"
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog ‘OTZlYmRmNjE5ZTI3NTVlZjU4NGViZmY4ZGJkYmU4MmU.’ in 32000 ms (Method: INVITE)

<— SIP read from UDP:192.168.3.107:25764 —>
ACK sip:105@192.168.3.10:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.3.107:25764;branch=z9hG4bK-d8754z-87755d6c96144e5c-1—d8754z-;rport
To: "105"sip:105@192.168.3.10:5060;tag=as17c0478b
From: "Ron Wheeler"sip:102@192.168.3.10:5060;tag=be36e433
Call-ID: OTZlYmRmNjE5ZTI3NTVlZjU4NGViZmY4ZGJkYmU4MmU.
CSeq: 1 ACK
Content-Length: 0

<------------->
— (7 headers 0 lines) —

E Y E B E A M
[12-09-05]16:12:26.935 | Debug | RESIP:TRANSACTION | "Send to TU: TU: DialogUsageManager size=0

SIP/2.0 408 Request Timeout
Via: SIP/2.0/UDP 192.168.3.107:25764;branch=z9hG4bK-d8754z-0f7dda4353185f62-1—d8754z-;rport
To: "“Ron Wheeler”"sip:102@192.168.3.10:5060;tag=as31d1364f
From: "“Ron Wheeler”"sip:102@192.168.3.10:5060;tag=ae109c48
Call-ID: YTlkMGI3ZTk3YWI5ODA1OTgzODc0NTEzODg5YTMzOTg.
CSeq: 142 SUBSCRIBE
Content-Length: 0

SIP/2.0 408 Request Timeout
Via: SIP/2.0/UDP 192.168.3.107:25764;branch=z9hG4bK-d8754z-0f7dda4353185f62-1—d8754z-;rport
To: "“Ron Wheeler”"sip:102@192.168.3.10:5060;tag=as31d1364f
From: "“Ron Wheeler”"sip:102@192.168.3.10:5060;tag=ae109c48
Call-ID: YTlkMGI3ZTk3YWI5ODA1OTgzODc0NTEzODg5YTMzOTg.
CSeq: 142 SUBSCRIBE
Content-Length: 0

david55 · September 5, 2012, 9:22pm

If you set the right options and use the log files, rather than the console, Asterisk will timestamp to 1ms resolution.

408 is often used as fake response when there wasn’t actually any response at all. Certainly your trace doesn’t show any 408 being sent by Asterisk. On the Asterisk side it shows a caller making a call without authorisation (this is normal), but then not following it up with the same call with authorisation (which is abnormal, if the caller has been configured with any credentials at all).

I don’t see the INVITE or the ACK being transmitted in your eyebeam trace.

As the ACK doesn’t have any user agent information, but the INVITE does, I suspect it is being faked by a router, which is actually eating the 401 response. The lack of a server on the 408 suggests that it is being faked - probably by Eyebeam, but possibly by whatever is faking the ACK.