[asterisk-dev] sipsock_read: Failed to grab lock, trying again...

Sun May 13 12:52:48 MST 2007

Hello all,
  I was working on asterisk 1.2(latest) doing some tests before deployments when I saw the debug statement in the subject. I decided to look into it further and what causing it. I found out it was caused by slow cdr backend. To make sure this is the case, I changed the sql in cdr_addon_mysql.c to make it stored procedure. I called it "InsertCDR". Inside this stored proc. I slow down the query using  mysql BENCHMARK() functions ( example: DECLARE result int; SELECT BENCHMARK(10000,ENCODE('hello','goodbye')) into result; )

  This made my asterisk debug screen floaded with "...sipsock_read: Failed to grab lock, trying again..."  after I hangup/cancel my xlite phone.
  The more I increase the benchmark time, the more of this statement and the more I reduce the benchmark time, the less I get of this statement. If I remove the benchmark function all togather from the proc , there is only 1  or 2 such statement or none.

  This caused me to worry, what is going to happen when I deployed asterisk with slow backend with good amount of load?  is it going to effect other calls and  freeze asterisk?
  I don't  have good knowlege with asterisk code but what I'm afraid is that some sip messages such as ACK or 200 OK comes after after Cancel or BYE, this message is read by sipsock_read and finds this request is still associated with existing call/dialog but the channel is locked waiting for the cdr call to return, then sipsock_read  goes into infinite iteration untill the channel is unlocked.   So my concern  is that  what happens to other SIP requests?  if the thread that executes sipsock_read is only one responsible to read the SIP messages from SIP socket(5060), then we will have other SIP messages queuing up in the socket and asterisk basically freezing!
   Please let me know if this a problem or just my paranoia :)
  He is the sip debug:

   -- Executing Dial("SIP/XXX.XXX.XXX.X44-093c61e8", "SIP/4545019735174455 at XXX.XXX.XXX.X94|6316") in new stack
May 13 13:37:31 DEBUG[4391]: chan_sip.c:2083 sip_call: Outgoing Call for 4545019735174455
    -- Called 4545019735174455 at XXX.XXX.XXX.X94
May 13 13:37:31 DEBUG[4122]: chan_sip.c:1468 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1c3fc2527b9d6c3c42378df8663f739e at XXX.XXX.XXX.X45' Request 102: Found
May 13 13:37:35 DEBUG[4122]: chan_sip.c:1468 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1c3fc2527b9d6c3c42378df8663f739e at XXX.XXX.XXX.X45' Request 102: Found
May 13 13:37:35 DEBUG[4122]: chan_sip.c:3778 process_sdp: Oooh, we need to change our formats since our peer supports only 0x1 (g723) and not 0x4 (ulaw)
    -- SIP/XXX.XXX.XXX.X94-093b2df0 is making progress passing it to SIP/XXX.XXX.XXX.X44-093c61e8
May 13 13:37:36 DEBUG[4391]: chan_sip.c:2448 sip_hangup: update_call_counter(4545019735174455) - decrement call limit counter
May 13 13:37:36 DEBUG[4391]: chan_sip.c:1392 __sip_ack: Acked pending invite 102
May 13 13:37:36 DEBUG[4391]: chan_sip.c:1415 __sip_ack: Stopping retransmission on '1c3fc2527b9d6c3c42378df8663f739e at XXX.XXX.XXX.X45' of Request 102: Match Found
May 13 13:37:36 DEBUG[4391]: app_dial.c:1644 dial_exec_full: Exiting with DIALSTATUS=CANCEL.
  == Spawn extension (from-ser, 19735174455, 17) exited non-zero on 'SIP/XXX.XXX.XXX.X44-093c61e8'
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4391]: cdr_addon_mysql.c:206 mysql_log: cdr_mysql: inserting a CDR record.
May 13 13:37:36 DEBUG[4391]: cdr_addon_mysql.c:223 mysql_log: cdr_mysql: SQL command as follows: call insertCDR('2007-05-13 13:37:31','\"nour\" <40003>','40003','19735174455','from-ser', 'SIP/XXX.XXX.XXX.X44-093c61e8','SIP/XXX.XXX.XXX.X94-093b2df0','Dial','SIP/4545019735174455 at XXX.XXX.XXX.X94|6316',5,0,'NO ANSWER',3,'40003','1179081451.38','nil')
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...
May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.digium.com/pipermail/asterisk-dev/attachments/20070513/ed1e8a33/attachment.htm