[Asterisk-Dev] SIP freeze in HEAD using SIP Realtime

Tue Aug 23 05:47:41 MST 2005

Currently running HEAD with a build date of today 8-23.  Also
experienced this under 8-17 and 8-12 Head builds.

7 Peers loaded in the peer table, 6 users loaded in the sip table. 
Running realtime with two db tables, sipusers and sippeers, mysql as the
driver.

SIP just hangs after some random period of time, it could be hours,
could be minutes.  A sip reload always fixes the problem.  Upon
reloading SIP I do get a bunch of stale nonce messages and sip traffic
begins to flow again, until if freezes up at some point.

Here is a CLI output from the 8-23 head version just after a sip reload
command when the channel appears hung.  verbose and debug are 6+.  IP
addresses have been change to protect the innocent.

-Chris

localhost*CLI> sip reload
Destroying call '3966caeb-fdc16f79 at 192.168.10.36'

<-- SIP read from 10.1.0.2:5060:
SIP/2.0 200 OK
To: <sip:2609 at 10.1.0.2:5060>;tag=dddfb283e7a7ecc1i1
From: "asterisk" <sip:asterisk at 10.0.0.2>;tag=as17313c2e
Call-ID: 4be18d217148bc4313b00e6663a1398f at 10.0.0.2
CSeq: 102 OPTIONS
Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK68003bb7
Server: Sipura/SPA841-0.9.1
Content-Length: 0
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER

--- (9 headers 0 lines)---
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:8522 handle_response_peerpoke:
Peer '2609' is
now TOO LAGGED! (282567ms / 2000ms)
Destroying call '77c7af57-65bceec5-9ed3360c at 192.168.254.1'
Destroying call 'c079831d-e1b3e55b-fda02f8a at 192.168.254.1'
11 headers, 0 lines
Reliably Transmitting (no NAT) to 10.3.0.1:29299:
OPTIONS sip:5006 at 192.168.1.10:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK5fffddb5
From: "asterisk" <sip:asterisk at 10.0.0.2>;tag=as5c1ace70
To: <sip:5006 at 192.168.1.10:5060>
Contact: <sip:asterisk at 10.0.0.2>
Call-ID: 4bd414811730ff6044f135662dcff58c at 10.0.0.2
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX
Date: Tue, 23 Aug 2005 15:37:36 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY
Content-Length: 0

---
11 headers, 0 lines
Reliably Transmitting (no NAT) to 10.3.54.137:5060:
OPTIONS sip:10.3.54.137 SIP/2.0
Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK7001972a
From: "asterisk" <sip:asterisk at 10.0.0.2>;tag=as1483b03f
To: <sip:10.3.54.137>
Contact: <sip:asterisk at 10.0.0.2>
Call-ID: 614ade9b123954b379b9208013dc0aa4 at 10.0.0.2
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX
Date: Tue, 23 Aug 2005 15:37:36 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY
Content-Length: 0

---
11 headers, 0 lines
Reliably Transmitting (no NAT) to 10.1.0.2:5060:
OPTIONS sip:2608 at 10.1.0.2:5060 SIP/2.0
Via: SIP/2.0/UDP 10.0.0.2:5060;branch=z9hG4bK31099e08
From: "asterisk" <sip:asterisk at 10.0.0.2>;tag=as5a274c17
To: <sip:2608 at 10.1.0.2:5060>
Contact: <sip:asterisk at 10.0.0.2>
Call-ID: 61d48793272e7f644e70d07c325d8e6a at 10.0.0.2
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX
Date: Tue, 23 Aug 2005 15:37:36 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY
Content-Length: 0

---
 Reloading SIP
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:10085 sip_poke_peer: Still have
a call...
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5003 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5003 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5003 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5003 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5003 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5003 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5001 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5001 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5001 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5001 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5003 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5001 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5003 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5002 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5002 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5002 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5001 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5002 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5003 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5001 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5002 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5003 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5001 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5002 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5001 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5002 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5001 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5002 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5002 at 192.168.254.11>'
Aug 23 08:37:36 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from '<sip:5002 at 192.168.254.11>'
localhost*CLI> sip reload
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:8522 handle_response_peerpoke:
Peer 'telica' is now TOO LAGGED! (29296ms / 500ms)
 Reloading SIP
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from 'Sipura2000 <sip:5004 at 192.168.254.11>'
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from 'Sipura2000 <sip:5004 at 192.168.254.11>'
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from 'Sipura2000 <sip:5004 at 192.168.254.11>'
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from 'Sipura2000 <sip:5004 at 192.168.254.11>'
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from 'Sipura2000-2 <sip:5005 at 192.168.254.11>'
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from 'Sipura2000 <sip:5004 at 192.168.254.11>'
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from 'Sipura2000-2 <sip:5005 at 192.168.254.11>'
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from 'Sipura2000-2 <sip:5005 at 192.168.254.11>'
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from 'Sipura2000 <sip:5004 at 192.168.254.11>'
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from 'Sipura2000-2 <sip:5005 at 192.168.254.11>'
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from 'Sipura2000 <sip:5004 at 192.168.254.11>'
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from 'Sipura2000-2 <sip:5005 at 192.168.254.11>'
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from 'Sipura2000 <sip:5004 at 192.168.254.11>'
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from 'Sipura2000-2 <sip:5005 at 192.168.254.11>'
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from 'Sipura2000 <sip:5004 at 192.168.254.11>'
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:8516 handle_response_peerpoke:
Peer 'telica' is now REACHABLE! (338ms / 500ms)
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from 'Sipura2000 <sip:5004 at 192.168.254.11>'
Aug 23 08:38:05 NOTICE[2996]: chan_sip.c:5668 check_auth: stale nonce
received from 'Sipura2000-2 <sip:5005 at 192.168.254.11>'
    -- Registered SIP '5003' at 192.168.254.1 port 5060 expires 60
    -- Saved useragent "PolycomSoundPointIP-SPIP_500-UA/1.5.2.0054" for
peer 5003
    -- Registered SIP '5004' at 192.168.254.16 port 5060 expires 300
    -- Saved useragent "Sipura/SPA2000-2.0.10(c)" for peer 5004
    -- Registered SIP '5005' at 192.168.254.16 port 5060 expires 300
    -- Saved useragent "Sipura/SPA2000-2.0.10(c)" for peer 5005
    -- Registered SIP '5002' at 192.168.254.1 port 5060 expires 60
    -- Saved useragent "PolycomSoundPointIP-SPIP_500-UA/1.5.2.0054" for
peer 5002
Aug 23 08:38:17 WARNING[2996]: chan_sip.c:1055 retrans_pkt: Maximum
retries exceeded on call bf1d1d9d-c7a6b237 at localhost for seqno 101
(Non-critical Response)
Aug 23 08:38:17 WARNING[2996]: chan_sip.c:1055 retrans_pkt: Maximum
retries exceeded on call bf1d1d9d-c7a6b237 at localhost for seqno 101
(Critical Response)
    -- Registered SIP '5001' at 192.168.254.1 port 5060 expires 60
    -- Saved useragent "PolycomSoundPointIP-SPIP_500-UA/1.5.2.0054" for
peer 5001