No subject
Thu Jul 12 09:23:04 CDT 2007
that the "Unlock when not locked" error is often the result of accessing
the c-client simultaneously from multiple threads, perhaps as the result of
making c-client calls from callbacks. I'm not familiar enough with c-client
to understand the details (or, for that matter, what exactly c-client's
contract with its caller is). From the source code, it certainly doesn't
seem likely that the locking hierarchy would get messed up from a single
thread.
I have automatic mail actions configured on the server (via "sieve") that
can delete mail messages from the IMAP store as soon as they're being
delivered. (Part of a voice-junk filter system.) If asterisk uses IDLE or
other notification hooks, it may get notifications before it's entirely
done delivering the message. That's probably not a well-tested path.
If there's a particular path that you suspect may lead to a thread race
with imap_send, let me know and I can retry with breakpoints in place
there.
Cheers
-- perry
So here's the relevant part of asterisk's debug output:
[hermod:~] root# asterisk -vvvvcg
Asterisk 1.4.22, Copyright (C) 1999 - 2008 Digium, Inc. and others.
Created by Mark Spencer <markster at digium.com>
Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for
details.
This is free software, with components licensed under the GNU General
Public
License version 2 and other licenses; you are welcome to redistribute it
under
certain conditions. Type 'core show license' for details.
=========================================================================
== Parsing '/etc/asterisk/asterisk.conf': Found
[... lots of verbiage ...]
Asterisk Ready.
*CLI> -- Starting simple switch on 'Zap/3-1'
-- Executing [s at incoming-pots:1] Set("Zap/3-1", "~~EXTEN~~=s") in new
stack
-- Executing [s at incoming-pots:2] NoOp("Zap/3-1", "Incoming call
CID="KIEHTREIBER AUD" <4083787798>") in new stack
-- Executing [s at incoming-pots:3] Set("Zap/3-1",
"__TRANSFER_CONTEXT=local-functions") in new stack
-- Executing [s at incoming-pots:4] Answer("Zap/3-1", "") in new stack
-- Executing [s at incoming-pots:5] Set("Zap/3-1",
"LASTCALLER=4083787798|g") in new stack
[Oct 17 20:51:49] WARNING[14346]: pbx.c:5910 pbx_builtin_setvar: The use
of the 'g' flag is deprecated. Please use Set(GLOBAL(foo)=bar) instead
== Setting global variable 'LASTCALLER' to '4083787798'
-- Executing [s at incoming-pots:6] GotoIf("Zap/3-1", "0?7:9") in new
stack
-- Goto (incoming-pots,s,9)
-- Executing [s at incoming-pots:9] NoOp("Zap/3-1", "Finish
if-incoming-1") in new stack
-- Executing [s at incoming-pots:10] GotoIf("Zap/3-1", "0?11:22") in new
stack
-- Goto (incoming-pots,s,22)
-- Executing [s at incoming-pots:22] NoOp("Zap/3-1", "Finish
if-incoming-2") in new stack
-- Executing [s at incoming-pots:23] Set("Zap/3-1", "blstate=") in new
stack
-- Executing [s at incoming-pots:24] GotoIf("Zap/3-1", "?25:27") in new
stack
-- Goto (incoming-pots,s,27)
-- Executing [s at incoming-pots:27] NoOp("Zap/3-1", "Finish
if-incoming-4") in new stack
-- Executing [s at incoming-pots:28] Dial("Zap/3-1",
"Zap/1&Zap/2&SIP/pap2t-1&SIP/pap2t-2&SIP/xlite-loki|27|dtwM(accept-call)")
in new stack
-- Called 1
-- Called 2
Really destroying SIP dialog
'5d54cec70a9330df53d5a27821d34a4d at 192.231.102.144' Method: INVITE
[Oct 17 20:51:49] WARNING[14346]: app_dial.c:1242 dial_exec_full: Unable
to create channel of type 'SIP' (cause 20 - Unknown)
Really destroying SIP dialog
'6770df0c0911962c629184dc13e767fc at 192.231.102.144' Method: INVITE
[Oct 17 20:51:49] WARNING[14346]: app_dial.c:1242 dial_exec_full: Unable
to create channel of type 'SIP' (cause 20 - Unknown)
Really destroying SIP dialog
'0815dc20506c14da39244970158e2734 at 192.231.102.144' Method: INVITE
[Oct 17 20:51:49] WARNING[14346]: app_dial.c:1242 dial_exec_full: Unable
to create channel of type 'SIP' (cause 20 - Unknown)
-- Zap/1-1 is ringing
-- Zap/2-1 is ringing
-- Zap/1-1 is ringing
-- Zap/2-1 is ringing
-- Zap/1-1 is ringing
-- Zap/2-1 is ringing
-- Zap/1-1 is ringing
-- Zap/2-1 is ringing
-- Zap/1-1 is ringing
-- Zap/2-1 is ringing
-- Zap/1-1 is ringing
-- Zap/2-1 is ringing
-- Nobody picked up in 27000 ms
-- Hungup 'Zap/2-1'
-- Hungup 'Zap/1-1'
-- Executing [s at incoming-pots:29] NoOp("Zap/3-1", "Local ring =>
NOANSWER") in new stack
-- Executing [s at incoming-pots:30] Goto("Zap/3-1", "sw-6-NOANSWER|10")
in new stack
-- Goto (incoming-pots,sw-6-NOANSWER,10)
-- Executing [sw-6-NOANSWER at incoming-pots:10] Macro("Zap/3-1",
"voicemail") in new stack
-- Executing [s at macro-voicemail:1] Wait("Zap/3-1", "0.5") in new
stack
-- Executing [s at macro-voicemail:2] Playback("Zap/3-1", "sorry2") in
new stack
-- <Zap/3-1> Playing 'sorry2' (language 'en')
-- Executing [s at macro-voicemail:3] VoiceMail("Zap/3-1",
"main at vm-cynics") in new stack
-- <Zap/3-1> Playing 'vm-intro' (language 'en')
-- <Zap/3-1> Playing 'beep' (language 'en')
-- Recording the message
-- x=0, open writing:
/var/spool/asterisk/voicemail/vm-cynics/main/tmp/NsDsxc format: wav,
0x81e7650
-- x=1, open writing:
/var/spool/asterisk/voicemail/vm-cynics/main/tmp/NsDsxc format: gsm,
0x81d9410
-- Recording automatically stopped after a silence of 5 seconds
-- <Zap/3-1> Playing 'auth-thankyou' (language 'en')
-- Executing [s at macro-voicemail:4] NoOp("Zap/3-1", "VM
Result=SUCCESS") in new stack
-- Executing [s at macro-voicemail:5] Hangup("Zap/3-1", "") in new stack
== Spawn extension (macro-voicemail, s, 5) exited non-zero on 'Zap/3-1'
-- Hungup 'Zap/3-1'
[Oct 17 20:53:02] WARNING[14339]: app_voicemail.c:1710 mm_log: IMAP
Warning: Unknown message data: 1 FETCH
[Oct 17 20:53:11] WARNING[14339]: app_voicemail.c:1710 mm_log: IMAP
Warning: Unknown message data: 1 FETCH
-- Starting simple switch on 'Zap/3-1'
-- Executing [s at incoming-pots:1] Set("Zap/3-1", "~~EXTEN~~=s") in new
stack
-- Executing [s at incoming-pots:2] NoOp("Zap/3-1", "Incoming call
CID="KIEHTREIBER AUD" <4083787798>") in new stack
-- Executing [s at incoming-pots:3] Set("Zap/3-1",
"__TRANSFER_CONTEXT=local-functions") in new stack
-- Executing [s at incoming-pots:4] Answer("Zap/3-1", "") in new stack
-- Executing [s at incoming-pots:5] Set("Zap/3-1",
"LASTCALLER=4083787798|g") in new stack
[Oct 17 20:53:33] WARNING[14348]: pbx.c:5910 pbx_builtin_setvar: The use
of the 'g' flag is deprecated. Please use Set(GLOBAL(foo)=bar) instead
== Setting global variable 'LASTCALLER' to '4083787798'
-- Executing [s at incoming-pots:6] GotoIf("Zap/3-1", "0?7:9") in new
stack
-- Goto (incoming-pots,s,9)
-- Executing [s at incoming-pots:9] NoOp("Zap/3-1", "Finish
if-incoming-1") in new stack
-- Executing [s at incoming-pots:10] GotoIf("Zap/3-1", "0?11:22") in new
stack
-- Goto (incoming-pots,s,22)
-- Executing [s at incoming-pots:22] NoOp("Zap/3-1", "Finish
if-incoming-2") in new stack
-- Executing [s at incoming-pots:23] Set("Zap/3-1", "blstate=") in new
stack
-- Executing [s at incoming-pots:24] GotoIf("Zap/3-1", "?25:27") in new
stack
-- Goto (incoming-pots,s,27)
-- Executing [s at incoming-pots:27] NoOp("Zap/3-1", "Finish
if-incoming-4") in new stack
-- Executing [s at incoming-pots:28] Dial("Zap/3-1",
"Zap/1&Zap/2&SIP/pap2t-1&SIP/pap2t-2&SIP/xlite-loki|27|dtwM(accept-call)")
in new stack
-- Called 1
-- Called 2
Really destroying SIP dialog
'0743c6e6264ea8f92147de6c376926f0 at 192.231.102.144' Method: INVITE
[Oct 17 20:53:33] WARNING[14348]: app_dial.c:1242 dial_exec_full: Unable
to create channel of type 'SIP' (cause 20 - Unknown)
Really destroying SIP dialog
'6d56235e2e5d5f3b085f7caa2ee4321d at 192.231.102.144' Method: INVITE
[Oct 17 20:53:33] WARNING[14348]: app_dial.c:1242 dial_exec_full: Unable
to create channel of type 'SIP' (cause 20 - Unknown)
Really destroying SIP dialog
'0ac8129265c0eb8d6b3617426f6ee19f at 192.231.102.144' Method: INVITE
[Oct 17 20:53:33] WARNING[14348]: app_dial.c:1242 dial_exec_full: Unable
to create channel of type 'SIP' (cause 20 - Unknown)
-- Zap/1-1 is ringing
-- Zap/2-1 is ringing
-- Zap/1-1 is ringing
-- Zap/2-1 is ringing
-- Zap/1-1 is ringing
-- Zap/2-1 is ringing
-- Zap/1-1 is ringing
-- Zap/2-1 is ringing
-- Zap/1-1 is ringing
-- Zap/2-1 is ringing
-- Zap/1-1 is ringing
-- Zap/2-1 is ringing
-- Nobody picked up in 27000 ms
-- Hungup 'Zap/2-1'
-- Hungup 'Zap/1-1'
-- Executing [s at incoming-pots:29] NoOp("Zap/3-1", "Local ring =>
NOANSWER") in new stack
-- Executing [s at incoming-pots:30] Goto("Zap/3-1", "sw-6-NOANSWER|10")
in new stack
-- Goto (incoming-pots,sw-6-NOANSWER,10)
-- Executing [sw-6-NOANSWER at incoming-pots:10] Macro("Zap/3-1",
"voicemail") in new stack
-- Executing [s at macro-voicemail:1] Wait("Zap/3-1", "0.5") in new
stack
-- Executing [s at macro-voicemail:2] Playback("Zap/3-1", "sorry2") in
new stack
-- <Zap/3-1> Playing 'sorry2' (language 'en')
-- Executing [s at macro-voicemail:3] VoiceMail("Zap/3-1",
"main at vm-cynics") in new stack
-- <Zap/3-1> Playing 'vm-intro' (language 'en')
-- <Zap/3-1> Playing 'beep' (language 'en')
-- Recording the message
-- x=0, open writing:
/var/spool/asterisk/voicemail/vm-cynics/main/tmp/dd6Pvp format: wav,
0x81d8670
-- x=1, open writing:
/var/spool/asterisk/voicemail/vm-cynics/main/tmp/dd6Pvp format: gsm,
0x81d89f0
-- Recording automatically stopped after a silence of 5 seconds
-- <Zap/3-1> Playing 'auth-thankyou' (language 'en')
-- Executing [s at macro-voicemail:4] NoOp("Zap/3-1", "VM
Result=SUCCESS") in new stack
-- Executing [s at macro-voicemail:5] Hangup("Zap/3-1", "") in new stack
== Spawn extension (macro-voicemail, s, 5) exited non-zero on 'Zap/3-1'
-- Hungup 'Zap/3-1'
-- Starting simple switch on 'Zap/3-1'
-- Executing [s at incoming-pots:1] Set("Zap/3-1", "~~EXTEN~~=s") in new
stack
-- Executing [s at incoming-pots:2] NoOp("Zap/3-1", "Incoming call
CID="KIEHTREIBER AUD" <4083787798>") in new stack
-- Executing [s at incoming-pots:3] Set("Zap/3-1",
"__TRANSFER_CONTEXT=local-functions") in new stack
-- Executing [s at incoming-pots:4] Answer("Zap/3-1", "") in new stack
-- Executing [s at incoming-pots:5] Set("Zap/3-1",
"LASTCALLER=4083787798|g") in new stack
[Oct 17 20:55:55] WARNING[14350]: pbx.c:5910 pbx_builtin_setvar: The use
of the 'g' flag is deprecated. Please use Set(GLOBAL(foo)=bar) instead
== Setting global variable 'LASTCALLER' to '4083787798'
-- Executing [s at incoming-pots:6] GotoIf("Zap/3-1", "0?7:9") in new
stack
-- Goto (incoming-pots,s,9)
-- Executing [s at incoming-pots:9] NoOp("Zap/3-1", "Finish
if-incoming-1") in new stack
-- Executing [s at incoming-pots:10] GotoIf("Zap/3-1", "0?11:22") in new
stack
-- Goto (incoming-pots,s,22)
-- Executing [s at incoming-pots:22] NoOp("Zap/3-1", "Finish
if-incoming-2") in new stack
-- Executing [s at incoming-pots:23] Set("Zap/3-1", "blstate=") in new
stack
-- Executing [s at incoming-pots:24] GotoIf("Zap/3-1", "?25:27") in new
stack
-- Goto (incoming-pots,s,27)
-- Executing [s at incoming-pots:27] NoOp("Zap/3-1", "Finish
if-incoming-4") in new stack
-- Executing [s at incoming-pots:28] Dial("Zap/3-1",
"Zap/1&Zap/2&SIP/pap2t-1&SIP/pap2t-2&SIP/xlite-loki|27|dtwM(accept-call)")
in new stack
-- Called 1
-- Called 2
Really destroying SIP dialog
'6e4e3baf7bf6a3250065f6095dbac4d0 at 192.231.102.144' Method: INVITE
[Oct 17 20:55:55] WARNING[14350]: app_dial.c:1242 dial_exec_full: Unable
to create channel of type 'SIP' (cause 20 - Unknown)
Really destroying SIP dialog
'023055d0486d6f8a6fb731e6572810f2 at 192.231.102.144' Method: INVITE
[Oct 17 20:55:55] WARNING[14350]: app_dial.c:1242 dial_exec_full: Unable
to create channel of type 'SIP' (cause 20 - Unknown)
Really destroying SIP dialog
'21a019bb0f905d8c30d436ce38ea12ee at 192.231.102.144' Method: INVITE
[Oct 17 20:55:55] WARNING[14350]: app_dial.c:1242 dial_exec_full: Unable
to create channel of type 'SIP' (cause 20 - Unknown)
-- Zap/1-1 is ringing
-- Zap/2-1 is ringing
-- Zap/1-1 is ringing
-- Zap/2-1 is ringing
-- Zap/1-1 is ringing
-- Zap/2-1 is ringing
-- Zap/1-1 is ringing
-- Zap/2-1 is ringing
-- Zap/1-1 is ringing
-- Zap/2-1 is ringing
-- Zap/1-1 is ringing
-- Zap/2-1 is ringing
-- Nobody picked up in 27000 ms
-- Hungup 'Zap/2-1'
-- Hungup 'Zap/1-1'
-- Executing [s at incoming-pots:29] NoOp("Zap/3-1", "Local ring =>
NOANSWER") in new stack
-- Executing [s at incoming-pots:30] Goto("Zap/3-1", "sw-6-NOANSWER|10")
in new stack
-- Goto (incoming-pots,sw-6-NOANSWER,10)
-- Executing [sw-6-NOANSWER at incoming-pots:10] Macro("Zap/3-1",
"voicemail") in new stack
-- Executing [s at macro-voicemail:1] Wait("Zap/3-1", "0.5") in new
stack
-- Executing [s at macro-voicemail:2] Playback("Zap/3-1", "sorry2") in
new stack
-- <Zap/3-1> Playing 'sorry2' (language 'en')
-- Executing [s at macro-voicemail:3] VoiceMail("Zap/3-1",
"main at vm-cynics") in new stack
-- <Zap/3-1> Playing 'vm-intro' (language 'en')
-- <Zap/3-1> Playing 'beep' (language 'en')
-- Recording the message
-- x=0, open writing:
/var/spool/asterisk/voicemail/vm-cynics/main/tmp/rjKRjM format: wav,
0x81d96f8
-- x=1, open writing:
/var/spool/asterisk/voicemail/vm-cynics/main/tmp/rjKRjM format: gsm,
0x81e7c78
-- Recording automatically stopped after a silence of 5 seconds
-- <Zap/3-1> Playing 'auth-thankyou' (language 'en')
[Oct 17 20:59:00] WARNING[14350]: app_voicemail.c:1710 mm_log: IMAP
Warning: Unknown message data: 2 FETCH
[Oct 17 20:59:00] WARNING[14350]: app_voicemail.c:1710 mm_log: IMAP
Warning: Unexpected tagged response: Voicemail FROM "KIEHTREIBER AUD"
<4083787798> (("Asterisk PBX" NIL "voicemail" "cynic.org")) ((
[Oct 17 20:59:00] WARNING[14350]: app_voicemail.c:1710 mm_log: IMAP
Warning: IMAP server sent a blank line
[Oct 17 20:59:00] WARNING[14350]: app_voicemail.c:1710 mm_log: IMAP
Warning: Missing IMAP reply key: )
[Oct 17 20:59:00] WARNING[14350]: app_voicemail.c:1710 mm_log: IMAP
Warning: Unexpected tagged response: 00000d2e OK Completed (0.000 sec)
-- Executing [s at macro-voicemail:4] NoOp("Zap/3-1", "VM
Result=SUCCESS") in new stack
-- Executing [s at macro-voicemail:5] Hangup("Zap/3-1", "") in new stack
== Spawn extension (macro-voicemail, s, 5) exited non-zero on 'Zap/3-1'
-- Hungup 'Zap/3-1'
[Oct 17 21:00:00] ERROR[14339]: app_voicemail.c:1773 mm_fatal: IMAP access
FATAL error: Unlock when not locked
And here is the gdb traceback you've been waiting for. Note that c-client
is still optimized, so some tail-call optimizations happened there:
[hermod:/files/src/asterisk-1.4.22] root# gdb
GNU gdb 6.4.90-debian
Copyright (C) 2006 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you
are
welcome to change it and/or distribute copies of it under certain
conditions.
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-linux-gnu".
(gdb) attach 14329
Attaching to process 14329
Reading symbols from /usr/sbin/asterisk...done.
Using host libthread_db library "/lib/tls/i686/cmov/libthread_db.so.1".
Reading symbols from /lib/tls/i686/cmov/libdl.so.2...done.
Loaded symbols for /lib/tls/i686/cmov/libdl.so.2
Reading symbols from /lib/tls/i686/cmov/libpthread.so.0...done.
[Thread debugging using libthread_db enabled]
[New Thread -1210258592 (LWP 14329)]
[New Thread -1222538320 (LWP 14340)]
[New Thread -1221047376 (LWP 14339)]
[New Thread -1217889360 (LWP 14338)]
[New Thread -1217234000 (LWP 14337)]
[New Thread -1216386128 (LWP 14336)]
[New Thread -1214084176 (LWP 14335)]
[New Thread -1210999888 (LWP 14334)]
[New Thread -1210754128 (LWP 14333)]
[New Thread -1210508368 (LWP 14332)]
[New Thread -1210262608 (LWP 14331)]
Loaded symbols for /lib/tls/i686/cmov/libpthread.so.0
Reading symbols from /lib/libncurses.so.5...done.
[... lots more "reading symbols" messages ...]
(gdb) b abort
Breakpoint 1 at 0xb7df8eb6
(gdb) b exit
Breakpoint 2 at 0xb7dfa2e6
(gdb) b _exit
Breakpoint 3 at 0xb7e5cdf4
(gdb) c
Continuing.
[New Thread -1222829136 (LWP 14346)]
[Thread -1222829136 (LWP 14346) exited]
[New Thread -1222829136 (LWP 14348)]
[Thread -1222829136 (LWP 14348) exited]
[New Thread -1222829136 (LWP 14350)]
[Switching to Thread -1221047376 (LWP 14339)]
Breakpoint 1, 0xb7df8eb6 in abort () from /lib/tls/i686/cmov/libc.so.6
(gdb) info threads
14 Thread -1222829136 (LWP 14350) 0xffffe410 in __kernel_vsyscall ()
11 Thread -1210262608 (LWP 14331) 0xffffe410 in __kernel_vsyscall ()
10 Thread -1210508368 (LWP 14332) 0xffffe410 in __kernel_vsyscall ()
9 Thread -1210754128 (LWP 14333) 0xffffe410 in __kernel_vsyscall ()
8 Thread -1210999888 (LWP 14334) 0xffffe410 in __kernel_vsyscall ()
7 Thread -1214084176 (LWP 14335) 0xffffe410 in __kernel_vsyscall ()
6 Thread -1216386128 (LWP 14336) 0xffffe410 in __kernel_vsyscall ()
5 Thread -1217234000 (LWP 14337) 0xffffe410 in __kernel_vsyscall ()
4 Thread -1217889360 (LWP 14338) 0xffffe410 in __kernel_vsyscall ()
* 3 Thread -1221047376 (LWP 14339) 0xb7df8eb6 in abort ()
from /lib/tls/i686/cmov/libc.so.6
2 Thread -1222538320 (LWP 14340) 0xffffe410 in __kernel_vsyscall ()
1 Thread -1210258592 (LWP 14329) 0xffffe410 in __kernel_vsyscall ()
(gdb) bt
http://bugs.digium.com/view.php?id=0 0xb7df8eb6 in abort () from
/lib/tls/i686/cmov/libc.so.6
http://bugs.digium.com/view.php?id=1 0xb7440ee0 in fatal (string=0xb74b4ce8
"Unlock when not locked") at
ftl_unix.c:38
http://bugs.digium.com/view.php?id=2 0xb7477362 in imap_send (stream=0x81cead8,
cmd=0xb7515df0 "FETCH",
args=0xb73837a8)
at imap4r1.c:3115
http://bugs.digium.com/view.php?id=3 0xb74776f0 in imap_fetch
(stream=0x81cead8, sequence=0x81e7860 "2",
flags=128)
at imap4r1.c:5563
http://bugs.digium.com/view.php?id=4 0xb747a377 in imap_search
(stream=0x81cead8, charset=0x0,
pgm=0x81e7870,
flags=<value optimized out>) at imap4r1.c:2089
http://bugs.digium.com/view.php?id=5 0xb744d21e in mail_search_full
(stream=0x81cead8, charset=0x0,
pgm=0x81e7870, flags=0)
at mail.c:2351
http://bugs.digium.com/view.php?id=6 0xb7423d4a in messagecount
(context=0xb7383e6d "vm-cynics",
mailbox=0xb7383e68 "main", folder=0x0) at app_voicemail.c:1223
http://bugs.digium.com/view.php?id=7 0xb74248c0 in has_voicemail
(mailbox=0x81b79e8 "main at vm-cynics",
folder=0x0)
at app_voicemail.c:1393
http://bugs.digium.com/view.php?id=8 0x0805eaf2 in ast_app_has_voicemail
(mailbox=0x81b79e8
"main at vm-cynics", folder=0x0)
at app.c:172
http://bugs.digium.com/view.php?id=9 0xb73d282c in do_monitor (data=0x0) at
chan_dahdi.c:7024
http://bugs.digium.com/view.php?id=10 0x0810055f in dummy_start (data=0x819b040)
at utils.c:912
http://bugs.digium.com/view.php?id=11 0xb7f7f240 in start_thread () from
/lib/tls/i686/cmov/libpthread.so.0
http://bugs.digium.com/view.php?id=12 0xb7e9a49e in clone () from
/lib/tls/i686/cmov/libc.so.6
Issue History
Date Modified Username Field Change
======================================================================
2008-10-17 23:43 Perry The CynicNote Added: 0093931
======================================================================
More information about the asterisk-bugs
mailing list