[Home]

Summary:ASTERISK-12415: could NOT get the channel lock
Reporter:pj (pj)Labels:
Date Opened:2008-07-20 07:13:44Date Closed:2009-02-16 14:40:59.000-0600
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) coredebug.txt
( 1) gdb.txt
( 2) ReqTermResend.pcap
( 3) ReqTermResend.png
( 4) sipdump-r141949.pcap
( 5) sipdump-r141949.png
Description:Asterisk SVN-trunk-r132312
I have lot of this error messages on CLI,
It seems, that it can be related to ilbc codec, because it happens mainly when try to call echotest from xlite/eyebeam softphone with ilbc.
When I tried same situation with gsm, it doesn't happened (or only sporadically).


[Jul 20 14:13:17] ERROR[5827]: chan_sip.c:18837 handle_request_do: We could NOT get the channel lock for SIP/324-083ae4e0!
[Jul 20 14:13:17] ERROR[5827]: chan_sip.c:18838 handle_request_do: SIP transaction failed: YzcyMGFkMTgyNGNiMTRlMGFhNThkNTBkYjU0Y2FmMGY.
[Jul 20 14:13:18] ERROR[5827]: chan_sip.c:18837 handle_request_do: We could NOT get the channel lock for SIP/324-083ae4e0!
[Jul 20 14:13:18] ERROR[5827]: chan_sip.c:18838 handle_request_do: SIP transaction failed: YzcyMGFkMTgyNGNiMTRlMGFhNThkNTBkYjU0Y2FmMGY.


****** ADDITIONAL INFORMATION ******

ipbx*CLI> sip show history YzcyMGFkMTgyNGNiMTRlMGFhNThkNTBkYjU0Y2FmMGY.
ipbx*CLI>
 * SIP Call
1. Rx              INVITE / 1 INVITE / sip:959@ipbx.i.cz
2. AuthChal        Auth challenge sent for  - nc 0
3. TxRespRel       SIP/2.0 / 1 INVITE - 401 Unauthorized
4. SchedDestroy    14720 ms
5. Rx              ACK / 1 ACK / sip:959@ipbx.i.cz
6. Rx              INVITE / 2 INVITE / sip:959@ipbx.i.cz
7. CancelDestroy
8. Invite          New call: YzcyMGFkMTgyNGNiMTRlMGFhNThkNTBkYjU0Y2FmMGY.
9. AuthOK          Auth challenge succesful for 324
10. NewChan         Channel SIP/324-083ae4e0 - from YzcyMGFkMTgyNGNiMTRlMGFhNThkNTB
11. TxResp          SIP/2.0 / 2 INVITE - 100 Trying
12. TxRespRel       SIP/2.0 / 2 INVITE - 200 OK
13. Rx              ACK / 2 ACK / sip:959@193.179.38.20
14. LockFail        Owner lock failed, transaction failed.
15. ReTx            460 SIP/2.0 200 OK
16. Rx              ACK / 2 ACK / sip:959@193.179.38.20
17. LockFail        Owner lock failed, transaction failed.
18. ReTx            920 SIP/2.0 200 OK
19. Rx              ACK / 2 ACK / sip:959@193.179.38.20
Comments:By: pj (pj) 2008-07-20 07:17:46

some notice, probably unrelated to this issue:
'core show translation' shows always '0' in ilbc column
By: pj (pj) 2008-07-31 12:58:42

Should I do some more debugging to help with identificion of source this issue?
currently using trunk-r134650, but problem still persist
and more, some users complain about first two seconds of audio lost after sip2sip bridging, as reported ASTERISK-1263708


By: pj (pj) 2008-08-01 05:03:39

today asterisk crashed, I don't know, if it can be related to this bugreport, gdb from coredump attached.
By: Dennis DeDonatis (dennisd) 2008-08-20 09:54:40

I just started running Asterisk SVN-trunk-r138887M and I'm seeing the same thing.

The debug log shows:  Failed to grab owner channel lock, trying again, in addition to the exact same lock errors above.

In trunk's chan_sip.c the line:

copy_socket_data(&p->socket, &req->socket);

was in 1.6.0beta9:

p->socket = req->socket;

I tried to change it to that and Asterisk won't start.

This is in chan_sip.c's handle_request_do.

I get this whenever any SIP call passes through Asterisk.  It seems to actually WORK ok (only tested 1 call at a time) and better than 1.6.0beta9 was for me.
By: pj (pj) 2008-08-22 06:41:48

every time, "could NOT get the channel lock" error (reported here) happen,
asterisk generates SIP 200/OK retransmissions as more detailed reported in ASTERISK-1320287
please add relationship with tiket ASTERISK-1320287
By: Chris Maciejewski (chris-mac) 2008-09-04 09:17:02

I just found out this error ("We could NOT get the channel lock for SIP...") and SIP 200/OK retransmissions depends on how fast "200/OK" is ACKed by UA. If ACK is send to quickly error occurs, if there is a bit of delay everything is fine.

I was doing my tests with QuteCom phone which is ACKing * OK after 0.0006-0.0007 seconds - 10 errors out of 10 calls. See http://wima.co.uk/sip/2008-09-04_14-45-16-QuteCom-10-tests_index.html - Frame 12 and all other OK/ACK frames (TimeFromPreviousSipFrame value)

The other phone was Twinkle which is ACKing * OK after around 0.6644 seconds - 0 errors out of 10 calls. See http://wima.co.uk/sip/2008-09-04_14-49-32-Twinkle-10-tests_index.html - Frame 12 and all other OK/ACK frames (TimeFromPreviousSipFrame value)

Hope that will help resolving this issue.

Regards,
Chris
By: Mark Hulber (hulber) 2008-09-06 08:10:16

I'm seeing what might be related on 1.6rc4:

[Sep  6 09:13:06] ERROR[2931]: chan_sip.c:18560 handle_request_do: We could NOT get the channel lock for SIP/193.111.201.114-1347a6f0!
[Sep  6 09:13:06] ERROR[2931]: chan_sip.c:18561 handle_request_do: SIP transaction failed: 32655c3446effe8642c5d91119935c87@193.111.201.114
   -- SIP/sip.gradwell.net-13478da0 answered SIP/sipura2_2-1346c020
   -- Packet2Packet bridging SIP/sipura2_2-1346c020 and SIP/sip.gradwell.net-13478da0

The call did go out and since I was calling a number that was routed from external to the same asterisk it was also answered and received.

I see on another call it's on the inbound call that this error is occurring.

   -- Executing [s@default:4] Answer("SIP/213.166.5.133-1348dea0", "") in new stack
[Sep  6 09:36:12] ERROR[2931]: chan_sip.c:18560 handle_request_do: We could NOT get the channel lock for SIP/213.166.5.133-1348dea0!
[Sep  6 09:36:12] ERROR[2931]: chan_sip.c:18561 handle_request_do: SIP transaction failed: 9AAC0AFE-7B4F11DD-81ABEFB9-710EBE4B@213.166.5.133


By: Digium Subversion (svnbot) 2008-09-08 20:38:35

Repository: asterisk
Revision: 141949

U   trunk/main/channel.c

------------------------------------------------------------------------
r141949 | russell | 2008-09-08 20:38:31 -0500 (Mon, 08 Sep 2008) | 9 lines

Modify ast_answer() to not hold the channel lock while calling ast_safe_sleep()
or when calling ast_waitfor().  These are inappropriate times to hold the channel
lock.  This is what has caused "could not get the channel lock" messages from
chan_sip and has likely caused a negative impact on performance results of SIP
in Asterisk 1.6.  Thanks to file for pointing out this section of code.

(closes issue ASTERISK-12564)
(closes issue ASTERISK-12415)

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

http://svn.digium.com/view/asterisk?view=rev&revision=141949
By: pj (pj) 2008-09-09 06:02:25

reopening issue, because "could NOT get the channel lock" and SIP/OK resend issues still continues (perhaps not so often).
sending relevant packed dump and graph analysis showing this issue,

sipdump-r141949.pcap
sipdump-r141949.png


By: Mark Hulber (hulber) 2008-09-09 06:24:53

I coded the changes to ast_answer in channel.c and for my case (as noted above) I have not seen the issue which was previously always repeatable.
By: Chris Maciejewski (chris-mac) 2008-09-09 07:13:14

I can confirm my problem is now solved with changes in r141949
By: pj (pj) 2008-09-09 08:11:10

can't be source of my continuing problems, that I use debugs flags?
DONT_OPTIMIZE DEBUG_THREADS LOADABLE_MODULES DEBUG_CHANNEL_LOCKS MALLOC_DEBUG
By: pj (pj) 2008-09-10 06:49:48

not only SIP/OK is retransmitted, but also "Request Terminated" messages (as reaction to SIP CANCEL) are retransmitted many times after "could NOT get the channel lock" appears on asterisk console.
look at attached packet dump ReqTermResend.pcap and graph analysis ReqTermResend.png


[Sep 10 13:43:44]     -- Executing [_ZXX@from-bill:36] Playback("SIP/ipbx-gw-08480c88", "vlastni/nedostupny,noanswer") in new stack
[Sep 10 13:43:44]     -- <SIP/ipbx-gw-08480c88> Playing 'vlastni/nedostupny.slin' (language 'cz')
[Sep 10 13:43:49] ERROR[22631]: chan_sip.c:19202 handle_request_do: We could NOT get the channel lock for SIP/ipbx-gw-08480c88!
[Sep 10 13:43:49] ERROR[22631]: chan_sip.c:19203 handle_request_do: SIP transaction failed: 4b06b4a7576129ba7e8a925d2384be3c@192.168.40.4
[Sep 10 13:43:49]   == Spawn extension (from-bill, _ZXX, 36) exited non-zero on 'SIP/ipbx-gw-08480c88'
[Sep 10 13:43:59] WARNING[22631]: chan_sip.c:2991 retrans_pkt: Maximum retries exceeded on transmission 4b06b4a7576129ba7e8a925d2384be3c@192.168.40.4 for seqno 103 (Critical Response) -- See doc/sip-retransmit.txt.


By: pj (pj) 2008-09-15 06:30:35

it seems, that this issue appears mostly in cases, when hangup channel, what was not answered (see Playback,noanswer).
By: Whit Thiele (sirwhit) 2008-10-27 12:55:42

Is this patch going to be applied to the 1.4 svn branch?
By: pj (pj) 2009-01-29 07:28:02.000-0600

It seems, that this issue doesn't longer appear in latest trunk (Asterisk SVN-trunk-r170794)
I haven't any "could NOT get the channel lock" messages about two weeks ago.
But please keep this bugreport open for some time, I will report again, if it's realy resolved after some longer time. thanks
By: pj (pj) 2009-02-12 15:28:23.000-0600

It's long time ago, when "could NOT get the channel lock" message had appear in my asterisk messages. It seems, that Revision 167700 into trunk was crucial for resolving this long standing issue. If you agree with my opinion about this commit, this bugreport can be closed. thanks!
By: Mark Michelson (mmichelson) 2009-02-16 14:40:58.000-0600

It appears that other fixes have also fixed this. Since pj has given the go-ahead to close this, that's what I'm doing.