[Asterisk-Dev] Something nasty in current CVS-HEAD?
steve at daviesfam.org
steve at daviesfam.org
Fri Dec 31 02:22:25 MST 2004
Hi,
Is it just me - but is there something nasty going on in the current=20
CVS-HEAD?
I'm getting some weird entry in the channel list - with a nonsense name=20
(sometimes rubbish, sometimes a string that is ast_logged). And I'm=20
getting deadlocks and "avoided initial deadlock" messages on that entry,=20
and "freed too many times" semaphore errors. And sometimes seg faults.
This test is to pick up a Zap channel, attempt to Dial a CAPI/ channel.
The CAPI call doesn't go through (don't know why at the moment).
(I know CAPI isn't stock Asterisk; but I am seeing similar problems with=20
SIP/ and Local/ - just not so reproducible.)
Before the call attempt:
*CLI> show channels
Channel (Context Extension Pri ) State Appl. Data
0 active channel(s)
-- Starting simple switch on 'Zap/1-1'
-- Executing Macro("Zap/1-1", "dialplan-sa|6572770") in new stack
-- Executing Dial("Zap/1-1", "CAPI/0466:b6572770||T") in new stack
Dec 31 10:32:31 NOTICE[6032]: app_dial.c:828 dial_exec: Unable to create ch=
annel of type 'CAPI' (cause 0)
=3D=3D Everyone is busy/congested at this time (1:0/0/1)
-- Executing Busy("Zap/1-1", "") in new stack
Whilst still hearing the busy tone:
*CLI> show channels
Channel (Context Extension Pri ) State Appl. Data =
=20
,g$@,g$@tr1/0466]/0 (default s 1 ) Down (None) (=
None)
Zap/1-1 (macro-dialplan-sa s 102 ) Ring Busy =
(Empty)
2 active channel(s)
*CLI>=20
Presumably the top one is supposed to be the the CAPI channel. =20
If I then hangup the Zap side:
-- Hungup 'Zap/1-1'
Dec 31 10:38:10 WARNING[6032]: channel.c:599 ast_channel_free: Unable to fi=
nd channel in list
And do another show channels:
*CLI> show channels
Channel (Context Extension Pri ) State Appl. Data =
=20
Dg$@Dg$@ ( 0 ) Down (None) (None=
) =20
1 active channel(s)
"stop now" blocks and doesn't complete. Ctrl-\ and a bt full looks like=20
so:
GNU gdb 6.0
Copyright 2003 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you ar=
e
welcome to change it and/or distribute copies of it under certain condition=
s.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for details.
This GDB was configured as "i486-pc-linux-gnu"...Using host libthread_db li=
brary "/lib/libthread_db.so.1".
Core was generated by `asterisk -vvvvvvvddddgggg -c'.
Program terminated with signal 3, Quit.
=2E..
(gdb) bt full
#0 0x40145078 in sigsuspend () from /lib/libc.so.6
No symbol table info available.
#1 0x400230d8 in __pthread_wait_for_restart_signal () from /lib/libpthread=
=2Eso.0
No symbol table info available.
#2 0x40024b19 in __pthread_alt_lock () from /lib/libpthread.so.0
No symbol table info available.
#3 0x40021947 in pthread_mutex_lock () from /lib/libpthread.so.0
No symbol table info available.
#4 0x0805e6e9 in ast_queue_frame (chan=3D0x8157270, fin=3D0xbfffed90) at l=
ock.h:216
=09f =3D (struct ast_frame *) 0x81204b0
=09prev =3D (struct ast_frame *) 0x4002abdc
=09cur =3D (struct ast_frame *) 0xfffffffc
=09blah =3D 1
=09qlen =3D 135623484
#5 0x08068363 in ast_begin_shutdown (hangup=3D1) at channel.c:670
=09c =3D (struct ast_channel *) 0x8157270
#6 0x080b98e7 in quit_handler (num=3D0, nice=3D0, safeshutdown=3D1, restar=
t=3D0) at asterisk.c:551
=09filename =3D '\0' <repeats 79 times>
=09s =3D 1076124032
=09e =3D 1076126688
=09x =3D 0
#7 0x080b9b69 in handle_shutdown_now (fd=3D1, argc=3D2, argv=3D0xbfffef10)=
at asterisk.c:808
No locals.
#8 0x08093af1 in ast_cli_command (fd=3D1, s=3D0xfffffffc <Address 0xffffff=
fc out of bounds>) at cli.c:1229
=09argv =3D {0x8124850 "stop", 0x8124855 "now", 0x0, 0x40021b1a "=EB=CF\215=
t&", 0x0, 0x10 <Address 0x10 out of bounds>, 0x0,=20
0x40245980 "\224\230\022", 0x40245980 "\224\230\022", 0x402463e0 "", 0x40=
024cfb "\201=C3=E1^", 0x4002abdc "=DC=FA", 0x402463e0 "",=20
0x402463e0 "", 0xbfffef68 "\210=EF=FF=BF\003\b\031@=E0c$@0\005\022\b=A8=
=EF=FF=BF0\005\022\b\200=FD\021\b`=F0=FF=BF=A8=EF=FF=BF\212t\r\b0\005\022\b=
",=20
0x40021b1a "=EB=CF\215t&", 0x402463f0 "", 0x0, 0x402463e0 "", 0x40245980 =
"\224\230\022", 0x40245980 "\224\230\022",=20
0x8120530 "ld$@ld$@\200=FD\021\bh\005\022\b\030", 0xbfffef88 "=A8=EF=FF=
=BF\212t\r\b0\005\022\b", 0x40190803 "=EB=A0\211<$=FF=D0=EB=D4\215t&",=20
0x402463e0 "", 0x8120530 "ld$@ld$@\200=FD\021\bh\005\022\b\030",=20
0xbfffefa8 "=C8=EF=FF=BFlu\r\b\200=FD\021\b`=F0=FF=BF0\005\022\b_=F9\001@=
`=F0=FF=BFP=FD\021\b(=F0=FF=BF\221|\r\b\200=FD\021\b`=F0=FF=BF=C0=E6\021\bT=
=ED\027@",=20
0x8120530 "ld$@ld$@\200=FD\021\bh\005\022\b\030", 0x811fd80 "", 0xbffff06=
0 "\203",=20
0xbfffefa8 "=C8=EF=FF=BFlu\r\b\200=FD\021\b`=F0=FF=BF0\005\022\b_=F9\001@=
`=F0=FF=BFP=FD\021\b(=F0=FF=BF\221|\r\b\200=FD\021\b`=F0=FF=BF=C0=E6\021\bT=
=ED\027@",=20
0x80d748a "=FFN\030\215e=F8[^]=C3U\211=E5WVS\203=EC\030\213]\b\213}\fj\02=
0=E8=BA=AD=F7=FF\211=C6\211C\020\203=C4\020\205=C0t \203=EC\f=FFu\020=E8=E3=
=B1=F7=FF\211F\004\203=C4\020\203{\020", 0x8120530 "ld$@ld$@\200=FD\021\bh\=
005\022\b\030",=20
0x40013000 "\e[0;37;40mspawn mp3player\nWARNING\e[0;37;40m[5995]: \e[1;37=
;40mres_musiconhold.c\e[0;37;40m:\e[1;37;40m436\e[0;37;40m \e[1;37;40mmonmp=
3thread\e[0;37;40m: tack\n stack\n", 0x4002489b "\201=C3Ac", 0x811fd80 "", =
0x811fd80 "", 0xbffff060 "\203",=20
0xbfffefc8 "(=F0=FF=BF\221|\r\b\200=FD\021\b`=F0=FF=BF=C0=E6\021\bT=ED\02=
7@", 0x80d756c "\203=C4\020\213C\030;C\024~\004\205=C0\177=E4=BA", 0x811fd8=
0 "",=20
0xbffff060 "\203", 0x8120530 "ld$@ld$@\200=FD\021\bh\005\022\b\030", 0x40=
01f95f "\213}\b\211=C6\213E\f\205=C0u5\200=BE\202",=20
0xbffff060 "\203", 0x811fd50 "\200=FD\021\b\203", 0xbffff028 "=B8=F3=FF=
=BF=E9\207\v\b\001", 0x80d7c91 "\211=C2\203=C4\020\203=F8=FF\017\204=C9\001=
",=20
0x811fd80 "", 0xbffff060 "\203", 0x811e6c0 "stop now", 0x4017ed54 "=EB=E1=
\211<$=E8*%=FB=FF=EB=D0\211<$=E8P%=FB=FF=EB\237\215=B6",=20
0xbffff000 "0>\002@\200=3D$@\200=FF=FF=FF", 0x0, 0x40243d80 "\204*=AD=FB"=
, 0xffffffff <Address 0xffffffff out of bounds>,=20
0x8118ba0 "\b\212\021\b\200=3D$@=E0>$@", 0x9 <Address 0x9 out of bounds>,=
0xbffff028 "=B8=F3=FF=BF=E9\207\v\b\001",=20
0x1 <Address 0x1 out of bounds>, 0x40023e30 "U\211=E5\203=EC\b\213E\b\213=
@H\211\004$=E8\\=DC=FF=FF\211=EC]=C3\220\215=B4&", 0x40243d80 "\204*=AD=FB"=
,=20
0xffffff80 <Address 0xffffff80 out of bounds>, 0x0}
=09e =3D (struct ast_cli_entry *) 0x810c2a0
=09x =3D 2
=09dup =3D 0x8124850 "stop"
#9 0x080b87e9 in main (argc=3D135390912, argv=3D0xbffff06c) at asterisk.c:=
713
=09title =3D "Asterisk Console on 'bob' (pid 5988)", '\0' <repeats 80 times=
>, " \001@\000\000\000\000\000\000\000\0004=D0\020\b\024\201\004\b\000\000=
\000\000\000\000\000\001", '\0' <repeats 24 times>, "\001", '\0' <repeats 3=
5 times>, "\016=DB\000@\000\000\000\000\000\000\000\000\e\020\000@=A0$\001@=
)=F2=FF=BF\031\004\002\000\210=F3=FF=BFJ=CB\000 at 4\200\004\b\a\000\000\000\2=
34=F1=FF=BF\000\000\000"
=09c =3D -4
=09filename =3D "/root/.asterisk_history", '\0' <repeats 56 times>
=09hostname =3D "bob\000\001\000\000\000\000\000\000s$=B9\006@\200=F2=FF=BF=
=A1{\000@)=D8\004\b0=B9\006@[{\000@=A0$\001@\000\000\000\000=C3\a\000\000=
=C0=F2=FF=BF=C7z\000 at 2=CE\022@=E3\017\005\bx=B9\006@\000\000\000\000 \000\0=
00\000=DC=CE\022@=F0|\022@\220=F3\021 at x=B9\006@\n\000\000\000\\=BF\006@=A0$=
\001@\f(\001@%=DC\004\bp=F3=FF=BF=DAj\000@%=DC\004\b\216=FFw\001\030=C0\004=
\b =F3=FF=BF=C0'\001@\a\000\000\000 =D01@\000\000\000\000\001\000\000\000\0=
01", '\0' <repeats 11 times>, " =F3=FF=BF", '\0' <repeats 16 times>, "\216=
=FFw\001=B0=F3=FF=BFp&\001@\022\235\022@ *\022"...
=09tmp =3D "\e[1;37;40mAsterisk Ready.\n\e[0;37;40m\000=BB\006@\022\235\022=
@=DC=F2=FF=BF=DAj\000@\022\235\022@\202\211=B9\n *\022@\214=F2=FF=BF=C0'\00=
1@\a\000\000\000=A0=D41@"
=09xarg =3D 0x0
=09x =3D -1073747032
=09f =3D (FILE *) 0x811e6c0
=09sigs =3D {__val =3D {134238211, 0 <repeats 31 times>}}
=09num =3D 9
=09buf =3D 0x811e6c0 "stop now"
=09runuser =3D 0x0
=09rungroup =3D 0xbffff060 "\203"
=09runuser =3D 0x0
=09rungroup =3D 0xbffff060 "\203"
(gdb) quit
So deadlocked waiting on a mutex. I guess its that this dazed and=20
confused channel table entry is also left locked.
I rebuilt Asterisk with -DDETECT_DEADLOCKS, and here's what I got on exit:
channel.c line 381 (ast_queue_frame): Deadlock? waited 16 sec for mutex '&c=
han->lock'?
channel.c line 680 (ast_softhangup): '&chan->lock' was locked here.
I notice that ast_softhangup locks the channel, then calls=20
ast_softhangup_nolock that calls ast_queue_frame that locks again the same=
=20
mutex. Can they be "double locked" like that?
Thanks,
Steve
More information about the asterisk-dev
mailing list