[asterisk-dev] BAD BAD BAD reproducible case

[Steve Davies]

I have a reproducible case of the chan_sip BAD BAD BAD message, and
thought that people here might be interested to see if they can
reproduce it themselves. This is in asterisk 1.2.13:

    -- Executing Dial("SIP/snom320-096d92d8", "Zap/G1/101||") in new stack
Dec  1 17:14:28 NOTICE[29123]: app_dial.c:1076 dial_exec_full: Unable
to create channel of type 'Zap' (cause 34 - Circuit/channel
congestion)
  == Everyone is busy/congested at this time (1:0/1/0)
    -- Executing Goto("SIP/snom320-096d92d8", "5") in new stack
    -- Goto (trunk,8101,5)
    -- Executing Busy("SIP/snom320-096d92d8", "") in new stack
  == Spawn extension (trunk, 8101, 5) exited non-zero on 'SIP/snom320-096d92d8'
Dec  1 17:14:28 WARNING[24592]: channel.c:840 channel_find_locked:
Avoided initial deadlock for '0x959d430', 10 retries!
Dec  1 17:14:28 ERROR[24602]: chan_sip.c:11666 sipsock_read: We could
NOT get the channel lock for SIP/snom320-096d92d8!
Dec  1 17:14:28 ERROR[24602]: chan_sip.c:11667 sipsock_read: SIP
MESSAGE JUST IGNORED: ACK
Dec  1 17:14:28 ERROR[24602]: chan_sip.c:11668 sipsock_read: BAD! BAD! BAD!

A snip of the SIP debug for that phone shows that it is the ACK for
the "486 Busy" that is causing the problem:

Transmitting (no NAT) to 10.0.0.180:2051:
SIP/2.0 486 Busy Here
Via: SIP/2.0/UDP
10.0.0.180:2051;branch=z9hG4bK-wnyb6hwkcg5v;rport;received=10.0.0.180
From: "Fred" <sip:snom320 at pabx.phone.domain.co.uk>;tag=o9nm6uuwfk
To: <sip:8101 at pabx.phone.domain.co.uk;user=phone>;tag=as129f9b80
Call-ID: 3c563f466b6c-miqzkdl99wou at snom320-000413243DB0
CSeq: 2 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Content-Length: 0
X-Asterisk-HangupCause: Circuit/channel congestion


---
  == Spawn extension (trunk, 8101, 5) exited non-zero on 'SIP/snom320-096d92d8'
Dec  1 17:16:50 WARNING[24592]: channel.c:840 channel_find_locked:
Avoided initial deadlock for '0x959d430', 10 retries!

<-- SIP read from 10.0.0.180:2051:
ACK sip:8101 at pabx.phone.domain.co.uk;user=phone SIP/2.0
Via: SIP/2.0/UDP 10.0.0.180:2051;branch=z9hG4bK-wnyb6hwkcg5v;rport
From: "Fred" <sip:snom320 at pabx.phone.domain.co.uk>;tag=o9nm6uuwfk
To: <sip:8101 at pabx.phone.domain.co.uk;user=phone>;tag=as129f9b80
Call-ID: 3c563f466b6c-miqzkdl99wou at snom320-000413243DB0
CSeq: 2 ACK
Max-Forwards: 70
Contact: <sip:snom320 at 10.0.0.180:2051;line=r8a9j9qd>;flow-id=1
Content-Length: 0


--- (9 headers 0 lines) ---
Dec  1 17:16:50 ERROR[24602]: chan_sip.c:11666 sipsock_read: We could
NOT get the channel lock for SIP/snom320-096d92d8!
Dec  1 17:16:50 ERROR[24602]: chan_sip.c:11667 sipsock_read: SIP
MESSAGE JUST IGNORED: ACK
Dec  1 17:16:50 ERROR[24602]: chan_sip.c:11668 sipsock_read: BAD! BAD! BAD!


Like I say, perhaps this will help someone knock another un-necessary
alert on the head :)

Regards,
Steve