[asterisk-dev] Deadlock in chan_dahdi when pbx_builtin_setvar_helper is called on a newly allocated channel. How to trace?

[Antonio Goméz Soto]

Hi,

I am experiencing nasty deadlocks in chan_dahdi. I'd like to tackle this problem,
but don't know how to go about this, because there's no core dump, just:

[Feb 24 15:41:56]     -- Executing [01234455677 at gg-outbound:13] Dial("SIP/gg1-00003270", "DAHDI/G1/01234455677,,M(dial)ot") in new stack
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:557 __ast_pthread_mutex_lock: chan_dahdi.c line 9912 (do_monitor): Deadlock? waited 5 sec for mutex '&iflock'?
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /usr/sbin/asterisk(ast_bt_get_addresses+0x19) [0x811aadf]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /usr/lib/asterisk/modules/chan_dahdi.so [0x3b13066]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /usr/lib/asterisk/modules/chan_dahdi.so [0x3b38556]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /usr/sbin/asterisk [0x819c15a]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /lib/libpthread.so.0 [0x868832]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /lib/libc.so.6(clone+0x5e) [0x792f6e]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:564 __ast_pthread_mutex_lock: chan_dahdi.c line 11319 (dahdi_request): '&iflock' was locked here.
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /usr/sbin/asterisk(ast_bt_get_addresses+0x19) [0x811aadf]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /usr/lib/asterisk/modules/chan_dahdi.so [0x3b13066]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /usr/lib/asterisk/modules/chan_dahdi.so [0x3b3d5bd]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /usr/sbin/asterisk(ast_request+0x1f8) [0x80aef58]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /usr/lib/asterisk/modules/app_dial.so [0xf579a9]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /usr/lib/asterisk/modules/app_dial.so [0xf5c1c9]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /usr/sbin/asterisk(pbx_exec+0x1bf) [0x812ea77]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /usr/sbin/asterisk [0x813781a]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /usr/sbin/asterisk(ast_spawn_extension+0x53) [0x81392da]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /usr/sbin/asterisk [0x81399c0]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /usr/sbin/asterisk [0x813ba29]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /usr/sbin/asterisk [0x819c15a]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /lib/libpthread.so.0 [0x868832]
[Feb 24 15:42:01] ERROR[3867]: sources/BUILD/asterisk-1.6.2.16/inc:236 __dump_backtrace: /lib/libc.so.6(clone+0x5e) [0x792f6e]
[Feb 24 15:42:03]     -- Requested transfer capability: 0x00 - SPEECH
[Feb 24 15:42:03]     -- Called G1/01234455677

And all running dahdi channels are dropped!

I don't know where this backtrace originates from, but it's not much use to me.
Core show locks doen not show anything after this happens, but I did manage to trace
it down to pbx_builtin_setvar_helper() being called at the end of dahdi_new()

   for (v = i->vars ; v ; v = v->next)
     pbx_builtin_setvar_helper(tmp, v->name, v->value);


Thanks,
Antonio