<div>Hello all,</div> <div>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; )</div> <div> </div> <div>This made my asterisk debug screen floaded with "...sipsock_read: Failed to grab lock, trying again..." after I hangup/cancel my xlite phone.</div> <div>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.<BR></div> <div>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?</div> <div>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!</div>
<div> Please let me know if this a problem or just my paranoia :)</div> <div>He is the sip debug:</div> <div> </div> <div> </div> <div> -- Executing Dial("SIP/XXX.XXX.XXX.X44-093c61e8", "<A href="mailto:SIP/4545019735174455@XXX.XXX.XXX.X94|6316">SIP/4545019735174455@XXX.XXX.XXX.X94|6316</A>") in new stack<BR>May 13 13:37:31 DEBUG[4391]: chan_sip.c:2083 sip_call: Outgoing Call for 4545019735174455<BR> -- Called <A href="mailto:4545019735174455@XXX.XXX.XXX.X94">4545019735174455@XXX.XXX.XXX.X94</A><BR>May 13 13:37:31 DEBUG[4122]: chan_sip.c:1468 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on <A href="mailto:'1c3fc2527b9d6c3c42378df8663f739e@XXX.XXX.XXX.X45'">'1c3fc2527b9d6c3c42378df8663f739e@XXX.XXX.XXX.X45'</A> Request 102: Found<BR>May 13 13:37:35 DEBUG[4122]: chan_sip.c:1468 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on <A
href="mailto:'1c3fc2527b9d6c3c42378df8663f739e@XXX.XXX.XXX.X45'">'1c3fc2527b9d6c3c42378df8663f739e@XXX.XXX.XXX.X45'</A> Request 102: Found<BR>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)<BR> -- SIP/XXX.XXX.XXX.X94-093b2df0 is making progress passing it to SIP/XXX.XXX.XXX.X44-093c61e8<BR>May 13 13:37:36 DEBUG[4391]: chan_sip.c:2448 sip_hangup: update_call_counter(4545019735174455) - decrement call limit counter<BR>May 13 13:37:36 DEBUG[4391]: chan_sip.c:1392 __sip_ack: Acked pending invite 102<BR>May 13 13:37:36 DEBUG[4391]: chan_sip.c:1415 __sip_ack: Stopping retransmission on <A href="mailto:'1c3fc2527b9d6c3c42378df8663f739e@XXX.XXX.XXX.X45'">'1c3fc2527b9d6c3c42378df8663f739e@XXX.XXX.XXX.X45'</A> of Request 102: Match Found<BR>May 13 13:37:36 DEBUG[4391]: app_dial.c:1644 dial_exec_full: Exiting with DIALSTATUS=CANCEL.<BR> == Spawn extension
(from-ser, 19735174455, 17) exited non-zero on 'SIP/XXX.XXX.XXX.X44-093c61e8'<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4391]: cdr_addon_mysql.c:206 mysql_log: cdr_mysql: inserting a CDR record.<BR>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@XXX.XXX.XXX.X94|6316',5,0,'NO ANSWER',3,'40003','1179081451.38','nil')<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476
sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]:
chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36
DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR>May 13 13:37:36 DEBUG[4122]: chan_sip.c:11476 sipsock_read: Failed to grab lock, trying again...<BR></div> <div> </div>