Re: mISDN_send: error -12 strikes again

On Mon, Mar 19, 2012 at 05:54:24PM +0100, Ralf Schlatterbeck wrote:
> 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.

> > > i guess it is because chan_lcr runs into deadlock inside asterisk.
> > 
> > > 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.

OK I've done this -- except that I used my own lock-debugging
instrumentation. The instrumentation uses a file per thread and writes
the line number and time (in seconds and microseconds obtained from
gettimeofday) to the file. It also maintains a lock-count per thread
(asterisk has set up locking so that a single thread can lock the same
mutex more than once).

Part of the filename is the time asterisk was started, so a restart of
asterisk won't overwrite my files.

The lock-debugging avoids using lots of disk-space as each file is
overwritten again and again (we're not interested in historical locking
information). Each file is only 32 bytes.

If there is interest I can make my debug code available.

Now I'm seeing the following when we ran into the error again:
Line-numbers are translated to the current version of chan_lcr although
I'm using an earlier version without the patches for newer asterisk.

- The log_lock is unlocked
- the asterisk lock (using ast_channel_trylock) is unlocked
- only the chan_lock is locked, I'm seeing the following events:
  - at time: 2012-03-29.05:03:57 usec: 726997 the lock is obtained in
    line 2012 in function lock_chan. This is never unlocked, seems there
    is some other way the select_main function can block while having
    the channel locked!
  - at time: 2012-03-29.05:04:01 usec: 802099 the lock is tried in
    line 2802 in function lcr_write.
  - starting at time: 2012-03-29.05:04:02 usec: 45710 until the machine
    is rebootet at 2012-03-30.11:42:55 I'm seeing around 700 (!)
    attempts to lock the lock_chan lock in line 2067 in lcr_request by
    different threads. I don't know if we have such a high number of
    blocked threads or if asterisk aborts threads when no lock is
    obtained.

Thats the status when the machine is rebooted at 2012-03-30.11:42:55.
Note that the file-modification times match the timestamps inside the
lock-debug files above.

Andreas: Any idea what can block the lcr thread inside select_main while
holding the lock_chan lock? I'm not seeing a classical deadlock where
two locks are locked in the wrong order or similar.

I'll try to further instrument this for the next time...

Ralf
-- 
Ralf Schlatterbeck             email: [email protected]