[asterisk-bugs] [Asterisk 0018554]: SIP channel tried to release unowned mutex in handle_incoming()

[Asterisk Bug Tracker]

A NOTE has been added to this issue. 
====================================================================== 
https://issues.asterisk.org/view.php?id=18554 
====================================================================== 
Reported By:                kkm
Assigned To:                
====================================================================== 
Project:                    Asterisk
Issue ID:                   18554
Category:                   Channels/chan_sip/General
Reproducibility:            unable to reproduce
Severity:                   minor
Priority:                   normal
Status:                     acknowledged
Asterisk Version:           1.8.1.1 
JIRA:                       SWP-2827 
Regression:                 No 
Reviewboard Link:            
SVN Branch (only for SVN checkouts, not tarball releases): N/A 
SVN Revision (number only!):  
Request Review:              
====================================================================== 
Date Submitted:             2010-12-29 20:32 CST
Last Modified:              2011-01-13 20:30 CST
====================================================================== 
Summary:                    SIP channel tried to release unowned mutex in
handle_incoming()
Description: 
Still testing 1.8 pre-production, suddenly received this

[2010-12-29 18:00:34.191] ERROR[17610]: lock.c:384
__ast_pthread_mutex_unlock: chan_sip.c line 23562 (handle_incoming): mutex
'owner' freed more times than we've locked!
[2010-12-29 18:00:34.191] ERROR[17610]: lock.c:416
__ast_pthread_mutex_unlock: chan_sip.c line 23562 (handle_incoming): Error
releasing mutex: Operation not permitted

Unfortunately, not much debugging information available. That was one of a
kind error. The following AEL code has been executed with errors appearing
between 2 trace lines:

    &trace(Entering queue - ${QUEUE_STATS}); //<- after this
    &answer-nocdr-maybe();
    Queue(${CUSTAPPRAW},ct,,,${QUETIME},,,on-queue-answer);
. . . 

macro on-queue-answer() {
  &trace(Answering in $[${CDR(duration)}-${CDR(billsec)}]s on ${CHANNEL});
//<- before this
}

The call had been answered in the macro

macro answer-nocdr-maybe() {
  if("${CHANNEL(state)}" == "Ring") {
    Answer(0,nocdr);
    Wait(0.5);
    Ringing();
    Wait(1);
  }
}
======================================================================
Relationships       ID      Summary
----------------------------------------------------------------------
related to          0018403 [patch] Deadlock on SIP blind transfer ...
====================================================================== 

---------------------------------------------------------------------- 
 (0130476) MKemner (reporter) - 2011-01-13 20:30
 https://issues.asterisk.org/view.php?id=18554#c130476 
---------------------------------------------------------------------- 
I get this error between 3 and 5 times a day (I am running 1.8.1-rc1,
around 300 calls a day) however despite my best efforts I have not been
able to replicate it at will - which means I don't have any further debug
information.

What I can tell you is that I get the error shortly after making a SIP
call to another asterisk (1.2) server. I don't get the error on every call
but every time the bug is triggered it is while making a SIP/udp call to
another asterisk server.  

What then happens is the asterisk1.2 believes the call is still in
progress (so the phone on that server keeps ringing) even after the 1.8
server has hung up.  

I have around a dozen phones connected via SIP/TCP to the 1.8 server, all
using blf, so the server is busy updating extension states at the time of
the call (which may be a factor) - however I never see the bug when calling
one of the local phones so it's either something that only affects SIP/UDP
not /TCP or the 1.2 server is doing something 1.8 doesn't like... :) 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2011-01-13 20:30 MKemner        Note Added: 0130476                          
======================================================================