Re: mISDN_send: error -12 strikes again

On Sun, Mar 18, 2012 at 05:53:30PM +0100, Ralf Schlatterbeck wrote:
> On Sun, Mar 18, 2012 at 07:29:08AM +0100, jolly wrote:
> > Ralf Schlatterbeck wrote:
> > > Yesterday we had the message "mISDN_send: error -12" filling
> > > /var/log/kern.log. Restarting asterisk "fixed" it.

> > hi ralf,
> > 
> > i guess it is because chan_lcr runs into deadlock inside asterisk. since
> > the process of chan_lcr holds a lock and never returns after calling
> > some asterisk function, bchannel read will not be processed, so the
> > kernel drops messages to prevent overfill. this is why you receive the
> > message above.
> 
> Yes, I've debugged this once and am following that bug for some time
> now... the kernel message simply indicates that we have a buffer
> overflow in kernel space, nobody is fetching the data.
> 
> > i suggest do debug which process calls the chan_lcr global lock and
> > unlock function. then, if asterisk hangs, use gdb to do backtrace all
> > threads of asterisk. you can see against which lock each thread runs.
> > since locking mechanism of asterisk is quite complex and unknown to me,
> > you might be on your own with that.

Problem with this approach is that we will do an automatic restart of
asterisk now once this happens again. So I've coded my own lock
debugging. When I ran this I observed that asterisk locks are
implemented using pthread locks with the PTHREAD_MUTEX_RECURSIVE
feature. This means the same thread can lock the same mutex multiple
times as long as lock/unlocks are properly nested. When the lock-count
reaches 0, other threads are free to obtain a lock.

> I've looked through the locking code and have some questions:
> - I don't understand why in lcr_hangup the lock is only obtained if the
>   thread is different from the lcr thread.

The more I think about this, the more I think it is wrong: This is
not used in other channel drivers I've examined. Even if this function
would be called when the thread already *has* a lock, this would not be
a problem (see above). On the other hand I think this can lead to an
inconsistent state if we modify data structures without a lock: the
asterisk thread and the lcr thread can concurrently modify data
structures here.

Maybe the error is not due to a deadlock but due to modification of data
structures without a lock? Is it possible that chan_lcr stops fetching
data from a socket when it no longer thinks there is an active call
because it has lost a reference for an active call?

A fact that supports this suspicion is that we observed different
channel counts in 'lcradmin state' and asterisk: asterisk hat only sip
channels while lcradmin showed three open connections. This was shortly
before asterisk was restarted after an hour in the error-state.

Ralf
-- 
Ralf Schlatterbeck             email: [email protected]