asterisk users - Jan 2006 - avoided deadlock/channel already in use

Hello!

After upgrading my production machine to 1.2.1(used to be 1.2.0) on friday
i experienced strange behaviour yesterday, i received
deadlock-avoided-messages and channels refusing to hangup on span1(used
for inbound calls), both messages in all cases paired:

Jan  9 17:40:01 WARNING[30003] chan_zap.c: Ring requested on channel 0/17
already in use on span 1.  Hanging up owner.
Jan  9 17:40:01 WARNING[21571] channel.c: Avoided deadlock for
'0xb6e89798', 10 retries!

first they appeared twice at 17:40 and once at 18:07 but at 19:30 span 1
refused to accept any call, spitting out the "ring requested"-message
every second for different channels on span1(about 60 times) and 4 avoided
deadlock messages, until i restarted asterisk 1 minute later.

not only that this is very annoying and severe, also most of the
concurrent calls are hungup when that happens(drop from 20 calls to 2).
Both
error-messages(ring requested, Avoided deadlock) didn't yield much on
google, 2 recommendations to ask the tech support@digium. i use a digium
te410p but i guess the tech support will ask me to send them a debugging
trace - as this is a production machine(which used to work with the same
configuration for at least 2 months without much fuss) i can't recompile
asterisk with debugging support atm.

When doing ps faux|grep asterisk i see daughter processes of asterisk -
this didn't appear on installations prior to 1.2.1 and my second machine
has only one process running as it used to be(same version 1.2.1), also
the times when the daughter processes were started fit the times when the
problems above happend, though there are other daughter processes started
at times were no problems occured, some were started on 6.January(the day
of the upgrade). i rebooted the machine yesterday in the night(since 19:40
no more problems occured), but there are some daughter process again:

# ps fauxw|grep asterisk
root      5882  0.0  0.0   2344  1100 ?        S    00:53   0:00 /bin/sh
/usr/sbin/monit_asterisk
asterisk  5891  1.8  0.9  35228 19744 ?        Sl   00:53  16:43  \_
/usr/sbin/asterisk -U asterisk -G asterisk -p
asterisk  5940  0.0  0.2   5608  4376 ?        S    00:54   0:02      \_
mpg123 -q -s --mono -r 8000 -b 2048 -f 8192 fpm-calm-river.mp3
fpm-sunshine.mp3 fpm-world-mix.mp3
asterisk  5944  0.0  0.0   3712   412 ?        S    00:54   0:00      |  
\_ mpg123 -q -s --mono -r 8000 -b 2048 -f 8192 fpm-calm-river.mp3
fpm-sunshine.mp3 fpm-world-mix.mp3
asterisk  5941  0.0  0.0   4328  1836 ?        S    00:54   0:00      \_
mpg123 -q -s --mono -r 8000 -b 2048 -f 8192 tvm128.mp3
asterisk  5943  0.0  0.0   3712   480 ?        S    00:54   0:00      |  
\_ mpg123 -q -s --mono -r 8000 -b 2048 -f 8192 tvm128.mp3
asterisk  5942  0.0  0.2  11848  5820 ?        S    00:54   0:00      \_
mpg123 -q -s --mono -r 8000 -b 2048 -f 8192
06_-_Massive_Attack_-_Prayer_for_england.mp3
asterisk  5963  0.0  0.0   3712   424 ?        S    00:54   0:00      |  
\_ mpg123 -q -s --mono -r 8000 -b 2048 -f 8192
06_-_Massive_Attack_-_Prayer_for_england.mp3
asterisk 11894  0.0  0.5  30356 11676 ?        S    12:41   0:00      \_
/usr/sbin/asterisk -U asterisk -G asterisk -p
asterisk 13179  0.0  0.5  31012 12272 ?        S    12:49   0:00      \_
/usr/sbin/asterisk -U asterisk -G asterisk -p
asterisk 13657  0.0  0.5  31012 12272 ?        S    12:51   0:00      \_
/usr/sbin/asterisk -U asterisk -G asterisk -p
asterisk  2394  0.0  0.7  35048 15144 ?        S    15:53   0:00      \_
/usr/sbin/asterisk -U asterisk -G asterisk -p
root     21099  0.0  0.0   4104  1592 pts/0    S+   13:55   0:01  |
           \_ rasterisk r
root     24101  0.0  0.0   4104  1592 pts/1    S+   14:20   0:01  |
           \_ rasterisk r
root      6009  0.0  0.0   1500   476 pts/2    S+   16:18   0:00  |
           \_ grep asterisk
root     29100  0.0  0.0   4104  1576 pts/3    S+   14:58   0:00
           \_ rasterisk r
asthost log #

are daughter processes a new behaviour? there are none on my other box,
which is identical in hard- and software(a harddisk-clone) despite that it
has a sangoma-card...

on my box(intel xeon dual se7520jr2) the raid-controller and the te410p
share irq11 - but since there were no problems at all since 6 months i
assumed that it works. hope this is still not related!

i send a lot of calls via sip to the other machine(first machine inbound,
second machine outbound) and yesterday i had 2 "avoided deadlock"
messages
on the second machine as well(but no corresponding ringing-message as on
the first machine), the first one was 80minutes before the first messages
on the first machine, the second one was at the same time at 18:07 when i
had two pairs(avoided deadlock&ringing) on the first machine...

my final assumption would be that this is related to my telco, some
pri-problem on their side maybe...

i can't reproduce the problem and yesterday there was not more traffic on
the machine than usual, it is running fine again since 15h...

i hope my report is clear enough, unfortunately i'm too unexperienced to
find a explanation with my own skills, thanks for all suggestions...

best regards
christian

Hi Crhistian. Please try activating the debug output, so may be some
helpfull message will help us. Hopefully some developer will look at
this message and try to help. I have checked the source code but have
not concluded the source of the problem May be with the verbose output
i can help you little bit further.

Regards

On 1/10/06, Christian Benke <a0305292@unet.univie.ac.at>
wrote:
> Hello!
>
> After upgrading my production machine to 1.2.1(used to be 1.2.0) on friday
> i experienced strange behaviour yesterday, i received
> deadlock-avoided-messages and channels refusing to hangup on span1(used
> for inbound calls), both messages in all cases paired:
>
> Jan  9 17:40:01 WARNING[30003] chan_zap.c: Ring requested on channel 0/17
> already in use on span 1.  Hanging up owner.
> Jan  9 17:40:01 WARNING[21571] channel.c: Avoided deadlock for
> '0xb6e89798', 10 retries!
>
> first they appeared twice at 17:40 and once at 18:07 but at 19:30 span 1
> refused to accept any call, spitting out the "ring
requested"-message
> every second for different channels on span1(about 60 times) and 4 avoided
> deadlock messages, until i restarted asterisk 1 minute later.
>
> not only that this is very annoying and severe, also most of the
> concurrent calls are hungup when that happens(drop from 20 calls to 2).
> Both
> error-messages(ring requested, Avoided deadlock) didn't yield much on
> google, 2 recommendations to ask the tech support@digium. i use a digium
> te410p but i guess the tech support will ask me to send them a debugging
> trace - as this is a production machine(which used to work with the same
> configuration for at least 2 months without much fuss) i can't
recompile
> asterisk with debugging support atm.
>
> When doing ps faux|grep asterisk i see daughter processes of asterisk -
> this didn't appear on installations prior to 1.2.1 and my second
machine
> has only one process running as it used to be(same version 1.2.1), also
> the times when the daughter processes were started fit the times when the
> problems above happend, though there are other daughter processes started
> at times were no problems occured, some were started on 6.January(the day
> of the upgrade). i rebooted the machine yesterday in the night(since 19:40
> no more problems occured), but there are some daughter process again:
>
> # ps fauxw|grep asterisk
> root      5882  0.0  0.0   2344  1100 ?        S    00:53   0:00 /bin/sh
> /usr/sbin/monit_asterisk
> asterisk  5891  1.8  0.9  35228 19744 ?        Sl   00:53  16:43  \_
> /usr/sbin/asterisk -U asterisk -G asterisk -p
> asterisk  5940  0.0  0.2   5608  4376 ?        S    00:54   0:02      \_
> mpg123 -q -s --mono -r 8000 -b 2048 -f 8192 fpm-calm-river.mp3
> fpm-sunshine.mp3 fpm-world-mix.mp3
> asterisk  5944  0.0  0.0   3712   412 ?        S    00:54   0:00      |
> \_ mpg123 -q -s --mono -r 8000 -b 2048 -f 8192 fpm-calm-river.mp3
> fpm-sunshine.mp3 fpm-world-mix.mp3
> asterisk  5941  0.0  0.0   4328  1836 ?        S    00:54   0:00      \_
> mpg123 -q -s --mono -r 8000 -b 2048 -f 8192 tvm128.mp3
> asterisk  5943  0.0  0.0   3712   480 ?        S    00:54   0:00      |
> \_ mpg123 -q -s --mono -r 8000 -b 2048 -f 8192 tvm128.mp3
> asterisk  5942  0.0  0.2  11848  5820 ?        S    00:54   0:00      \_
> mpg123 -q -s --mono -r 8000 -b 2048 -f 8192
> 06_-_Massive_Attack_-_Prayer_for_england.mp3
> asterisk  5963  0.0  0.0   3712   424 ?        S    00:54   0:00      |
> \_ mpg123 -q -s --mono -r 8000 -b 2048 -f 8192
> 06_-_Massive_Attack_-_Prayer_for_england.mp3
> asterisk 11894  0.0  0.5  30356 11676 ?        S    12:41   0:00      \_
> /usr/sbin/asterisk -U asterisk -G asterisk -p
> asterisk 13179  0.0  0.5  31012 12272 ?        S    12:49   0:00      \_
> /usr/sbin/asterisk -U asterisk -G asterisk -p
> asterisk 13657  0.0  0.5  31012 12272 ?        S    12:51   0:00      \_
> /usr/sbin/asterisk -U asterisk -G asterisk -p
> asterisk  2394  0.0  0.7  35048 15144 ?        S    15:53   0:00      \_
> /usr/sbin/asterisk -U asterisk -G asterisk -p
> root     21099  0.0  0.0   4104  1592 pts/0    S+   13:55   0:01  |
>            \_ rasterisk r
> root     24101  0.0  0.0   4104  1592 pts/1    S+   14:20   0:01  |
>            \_ rasterisk r
> root      6009  0.0  0.0   1500   476 pts/2    S+   16:18   0:00  |
>            \_ grep asterisk
> root     29100  0.0  0.0   4104  1576 pts/3    S+   14:58   0:00
>            \_ rasterisk r
> asthost log #
>
> are daughter processes a new behaviour? there are none on my other box,
> which is identical in hard- and software(a harddisk-clone) despite that it
> has a sangoma-card...
>
> on my box(intel xeon dual se7520jr2) the raid-controller and the te410p
> share irq11 - but since there were no problems at all since 6 months i
> assumed that it works. hope this is still not related!
>
> i send a lot of calls via sip to the other machine(first machine inbound,
> second machine outbound) and yesterday i had 2 "avoided deadlock"
messages
> on the second machine as well(but no corresponding ringing-message as on
> the first machine), the first one was 80minutes before the first messages
> on the first machine, the second one was at the same time at 18:07 when i
> had two pairs(avoided deadlock&ringing) on the first machine...
>
> my final assumption would be that this is related to my telco, some
> pri-problem on their side maybe...
>
> i can't reproduce the problem and yesterday there was not more traffic
on
> the machine than usual, it is running fine again since 15h...
>
> i hope my report is clear enough, unfortunately i'm too unexperienced
to
> find a explanation with my own skills, thanks for all suggestions...
>
> best regards
> christian
>
>
>
> _______________________________________________
> --Bandwidth and Colocation provided by Easynews.com --
>
> Asterisk-Users mailing list
> To UNSUBSCRIBE or update options visit:
>    http://lists.digium.com/mailman/listinfo/asterisk-users
>

--
"Su nombre es GNU/Linux, no solamente Linux, mas info en
http://www.gnu.org"