using DEADLOCK_AVOIDANCE in handle queue but not in send_setup_to_lcr deadlock in pbx_builtin_getvar_helper, if not checked against asterisk channel C+(b477bb90) C-(b477bb90) 789 handle+(b477bb90) handle1(b477bb90) A8+(b370fb90) handle2(b477bb90) handleX(b477bb90) L+(b477bb90) L-(b477bb90) [Jul 4 21:01:12] NOTICE[6146]: chan_lcr.c:1393 receive_message: [call=NULL ast=NULL] Received new ref by LCR, as requested from chan_lcr. (ref=66) l(b477bb90) L+(b477bb90) L-(b477bb90) [Jul 4 21:01:12] NOTICE[6146]: chan_lcr.c:630 send_setup_to_lcr: [call=66 ast=lcr/64] Sending setup to LCR. (interface=Ext dialstring=, cid=) l(b477bb90) A10+(b477bb90) A10-(b477bb90) [Jul 4 21:01:14] WARNING[6157]: channel.c:1044 __ast_queue_frame: Exceptionally long voice queue length queuing to IAX2/iaxmodem0-156 Thread 22 (Thread 0xb477bb90 (LWP 6146)): #0 0xb7844424 in __kernel_vsyscall () #1 0xb7549c99 in __lll_lock_wait () from /lib/i686/cmov/libpthread.so.0 #2 0xb75450d3 in _L_lock_291 () from /lib/i686/cmov/libpthread.so.0 #3 0xb7544b36 in pthread_mutex_lock () from /lib/i686/cmov/libpthread.so.0 #4 0x08102c60 in pbx_builtin_getvar_helper (chan=0xb38e1658, name=0xb5a7d0ba "LCR_TRANSFERCAPABILITY") at /usr/src/asterisk-1.6.2.9/include/asterisk/lock.h:1715 #5 0xb5a7194d in send_setup_to_lcr () from /usr/lib/asterisk/modules/chan_lcr.so -------------------------- using DEADLOCK_AVOIDANCE in handle queue AND in send_setup_to_lcr last call befor kernel oops [Jul 4 23:44:18] NOTICE[5380] chan_lcr.c: [call=NULL ast=NULL] Received request from Asterisk. (data=Ext/06082XXXX23) [Jul 4 23:44:18] NOTICE[5380] chan_lcr.c: [call=0 ast=NULL] Call instance allocated. [Jul 4 23:44:18] NOTICE[5380] chan_lcr.c: [call=NULL ast=lcr/6] Received call from Asterisk. [Jul 4 23:44:18] NOTICE[5380] chan_lcr.c: [call=NULL ast=NULL] Sending (null) to socket. [Jul 4 23:44:18] NOTICE[5079] chan_lcr.c: [call=NULL ast=NULL] Received new ref by LCR, as requested from chan_lcr. (ref=6) [Jul 4 23:44:18] NOTICE[5079] chan_lcr.c: [call=6 ast=lcr/6] Sending setup to LCR. (interface=Ext dialstring=06082XXXX23, cid=) [Jul 4 23:44:18] NOTICE[5079] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_SETUP to socket. [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=NULL ast=NULL] Received new ref by LCR, due to incomming call. (ref=7) [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=0 ast=NULL] Call instance allocated. [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=7 ast=NULL] Incomming setup from LCR. (callerid 6082XXXX0, dialing 23) [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=7 ast=lcr/7] Try to start pbx. (exten=23 context=from-ISDN-extern complete=no) [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_OVERLAP to socket. [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=7 ast=lcr/7] Extensions matches. [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=7 ast=lcr/7] Starting call to Asterisk due to matching extension. [Jul 4 23:44:19] NOTICE[5381] chan_lcr.c: [call=7 ast=lcr/7] Received answer from Asterisk (maybe during lcr_bridge). [Jul 4 23:44:19] NOTICE[5381] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_CONNECT to socket. [Jul 4 23:44:19] NOTICE[5381] chan_lcr.c: [call=7 ast=lcr/7] Requesting B-channel. [Jul 4 23:44:19] NOTICE[5381] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_HELLO to socket. [Jul 4 23:44:19] NOTICE[5381] chan_lcr.c: [call=7 ast=lcr/7] Received indicate -1. [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=NULL ast=NULL] Received BCHANNEL_ASSIGN message. (handle=00000002) for ref 7 [Jul 4 23:44:19] NOTICE[5079] bchannel.c: [call=7 ast=NULL] Open DSP audio [Jul 4 23:44:19] NOTICE[5079] bchannel.c: [call=7 ast=NULL] Activating B-channel. [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_HELLO to socket. [Jul 4 23:44:19] NOTICE[5079] bchannel.c: [call=7 ast=NULL] DL_ESTABLISH confirm: bchannel is now activated (socket 51). [Jul 4 23:44:19] NOTICE[5079] bchannel.c: [call=NULL ast=NULL] Sending PH_CONTROL DSP-TX_DEJITTER 240f,0 [Jul 4 23:44:19] NOTICE[5079] bchannel.c: [call=NULL ast=NULL] Sending PH_CONTROL DSP-DTMF 2100,0 [Jul 4 23:44:19] NOTICE[5381] chan_lcr.c: [call=7 ast=lcr/7] Received indicate AST_CONTROL_RINGING from Asterisk. [Jul 4 23:44:19] NOTICE[5381] chan_lcr.c: [call=7 ast=lcr/7] Using Asterisk 'ring' indication [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=6 ast=lcr/6] Incomming pattern indication from LCR. [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=6 ast=lcr/6] Requesting B-channel. [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_HELLO to socket. [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=6 ast=lcr/6] Channel clear to send to Asterisk. [Jul 4 23:44:19] NOTICE[5381] chan_lcr.c: [call=7 ast=lcr/7] Received answer from Asterisk (maybe during lcr_bridge). [Jul 4 23:44:19] NOTICE[5381] chan_lcr.c: [call=7 ast=lcr/7] Received indicate -1. [Jul 4 23:44:19] NOTICE[5381] chan_lcr.c: [call=7 ast=lcr/7] Received AST_CONTROL_SRCUPDATE from Asterisk. [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=6 ast=lcr/6] Incomming setup acknowledge from LCR. [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=NULL ast=NULL] Received BCHANNEL_ASSIGN message. (handle=00000001) for ref 6 [Jul 4 23:44:19] NOTICE[5079] bchannel.c: [call=6 ast=NULL] Open DSP audio [Jul 4 23:44:19] NOTICE[5079] bchannel.c: [call=6 ast=NULL] Activating B-channel. [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_HELLO to socket. [Jul 4 23:44:19] NOTICE[5079] bchannel.c: [call=6 ast=NULL] DL_ESTABLISH confirm: bchannel is now activated (socket 54). [Jul 4 23:44:19] NOTICE[5079] bchannel.c: [call=NULL ast=NULL] Sending PH_CONTROL DSP-TX_DEJITTER 240f,0 [Jul 4 23:44:19] NOTICE[5079] bchannel.c: [call=NULL ast=NULL] Sending PH_CONTROL DSP-DTMF 2100,0 [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=6 ast=lcr/6] Incomming connect (answer) from LCR. [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=6 ast=lcr/6] Channel clear to send to Asterisk. [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=6 ast=lcr/6] Sending queued ANSWER to Asterisk. [Jul 4 23:44:19] NOTICE[5380] chan_lcr.c: [call=6 ast=lcr/6] Received AST_CONTROL_SRCUPDATE from Asterisk. [Jul 4 23:44:19] NOTICE[5079] chan_lcr.c: [call=6 ast=lcr/6] Incomming facility from LCR. A9+(b351fb90) 0--1356 A9-(b351fb90) *2(b351fb90) *3(b351fb90) a9(b351fb90) c(b4773b90) C+(b4773b90) C-(b4773b90) 789 A9+(b35d3b90) 0--1356 A9-(b35d3b90) *2(b35d3b90) *3(b35d3b90) a9(b35d3b90) c(b4773b90) C+(b4773b90) C-(b4773b90) 789 A9+(b351fb90) 0--1356 A9-(b351fb90) *2(b351fb90) *3(b351fb90) a9(b351fb90) c(b4773b90) C+(b4773b90) C-(b4773b90) 789 A9+(b35d3b90) 0--1356 A9-(b35d3b90) *2(b35d3b90) *3(b35d3b90) a9(b35d3b90) c(b4773b90) C+(b4773b90) C-(b4773b90) 789 A9+(b351fb90) 0--1356 A9-(b351fb90) *2(b351fb90) *3(b351fb90) a9(b351fb90) c(b4773b90) C+(b4773b90) C-(b4773b90) 789 A9+(b35d3b90) 0--1356 A9-(b35d3b90) *2(b35d3b90) *3(b35d3b90) a9(b35d3b90) c(b4773b90) A8+(b35d3b90) A8-(b35d3b90) a8(b35d3b90) C+(b4773b90) C-(b4773b90) 789 A9+(b351fb90) 0--1356 A9-(b351fb90) *2(b351fb90) *3(b351fb90) a9(b351fb90) c(b4773b90) C+(b4773b90) C-(b4773b90) 789 A9+(b35d3b90) 0--1356 A9-(b35d3b90) *2(b35d3b90) *3(b35d3b90) a9(b35d3b90) c(b4773b90) A8+(b351fb90) A8-(b351fb90) a8(b351fb90) C+(b4773b90) C-(b4773b90) 789 A9+(b351fb90) 0--1356 A9-(b351fb90) *2(b351fb90) *3(b351fb90) a9(b351fb90) c(b4773b90) C+(b4773b90) C-(b4773b90) 789 A9+(b35d3b90) 0--1356 A9-(b35d3b90) *2(b35d3b90) *3(b35d3b90) a9(b35d3b90) c(b4773b90) C+(b4773b90) C-(b4773b90) 789 A9+(b351fb90) 0--1356 A9-(b351fb90) *2(b351fb90) *3(b351fb90) a9(b351fb90) c(b4773b90) C+(b4773b90) C-(b4773b90) 789 A9+(b35d3b90) 0--1356 A9-(b35d3b90) *2(b35d3b90) *3(b35d3b90) a9(b35d3b90) c(b4773b90) C+(b4773b90) C-(b4773b90) 789 A9+(b351fb90) 0--1356 A9-(b351fb90) *2(b351fb90) *3(b351fb90) a9(b351fb90) c(b4773b90) C+(b4773b90) C-(b4773b90) 789 A9+(b35d3b90) 0--1356 A9-(b35d3b90) *2(b35d3b90) *3(b35d3b90) a9(b35d3b90) c(b4773b90) C+(b4773b90) C-(b4773b90) 789 A9+(b351fb90) 0--13* occurence of DEADLOCK_AVOIDANCE during test run -- 362909-[Jul 4 23:39:45] NOTICE[5079] chan_lcr.c: [call=NULL ast=NULL] Received new ref by LCR, as requested from chan_lcr. (ref=1) 362910-[Jul 4 23:39:45] NOTICE[5079] chan_lcr.c: [call=1 ast=lcr/1] Sending setup to LCR. (interface=Ext dialstring=06082XXXX23, cid=) 362911-[Jul 4 23:39:45] NOTICE[5079] chan_lcr.c: [call=1 ast=lcr/1] Wait for unlock of Asterisk before reading LCR_TRANSFERCAPABILITY. 362912-[Jul 4 23:39:45] NOTICE[5079] chan_lcr.c: [call=1 ast=lcr/1] Wait for unlock of Asterisk before reading LCR_TRANSFERCAPABILITY. 362913:[Jul 4 23:39:45] NOTICE[5079] chan_lcr.c: [call=1 ast=lcr/1] Avoiding deadlock before reading LCR_TRANSFERCAPABILITY. 362914-[Jul 4 23:39:45] NOTICE[5079] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_SETUP to socket. 362915-[Jul 4 23:39:45] NOTICE[5079] chan_lcr.c: [call=1 ast=lcr/1] Incomming release from LCR, releasing ref. (cause=34) 362916-[Jul 4 23:39:45] NOTICE[5079] chan_lcr.c: [call=0 ast=lcr/1] Channel clear to send to Asterisk. 362917-[Jul 4 23:39:45] NOTICE[5079] chan_lcr.c: [call=0 ast=lcr/1] Sending queued HANGUP to Asterisk. -- 362924-[Jul 4 23:40:36] NOTICE[5164] chan_lcr.c: [call=NULL ast=NULL] Sending (null) to socket. 362925-[Jul 4 23:40:37] NOTICE[5079] chan_lcr.c: [call=NULL ast=NULL] Received new ref by LCR, as requested from chan_lcr. (ref=2) 362926-[Jul 4 23:40:37] NOTICE[5079] chan_lcr.c: [call=2 ast=lcr/2] Sending setup to LCR. (interface=Ext dialstring=06082XXXX23, cid=) 362927-[Jul 4 23:40:37] NOTICE[5079] chan_lcr.c: [call=2 ast=lcr/2] Wait for unlock of Asterisk before reading LCR_TRANSFERCAPABILITY. 362928:[Jul 4 23:40:37] NOTICE[5079] chan_lcr.c: [call=2 ast=lcr/2] Avoiding deadlock before reading LCR_TRANSFERCAPABILITY. 362929-[Jul 4 23:40:37] NOTICE[5079] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_SETUP to socket. 362930-[Jul 4 23:40:37] NOTICE[5079] chan_lcr.c: [call=2 ast=lcr/2] Incomming release from LCR, releasing ref. (cause=34) 362931-[Jul 4 23:40:37] NOTICE[5079] chan_lcr.c: [call=0 ast=lcr/2] Channel clear to send to Asterisk. 362932-[Jul 4 23:40:37] NOTICE[5079] chan_lcr.c: [call=0 ast=lcr/2] Sending queued HANGUP to Asterisk. -- 362939-[Jul 4 23:42:17] NOTICE[5272] chan_lcr.c: [call=NULL ast=NULL] Sending (null) to socket. 362940-[Jul 4 23:42:17] NOTICE[5079] chan_lcr.c: [call=NULL ast=NULL] Received new ref by LCR, as requested from chan_lcr. (ref=3) 362941-[Jul 4 23:42:17] NOTICE[5079] chan_lcr.c: [call=3 ast=lcr/3] Sending setup to LCR. (interface=Ext dialstring=06082XXXX23, cid=) 362942-[Jul 4 23:42:17] NOTICE[5079] chan_lcr.c: [call=3 ast=lcr/3] Wait for unlock of Asterisk before reading LCR_TRANSFERCAPABILITY. 362943:[Jul 4 23:42:17] NOTICE[5079] chan_lcr.c: [call=3 ast=lcr/3] Avoiding deadlock before reading LCR_TRANSFERCAPABILITY. 362944-[Jul 4 23:42:17] NOTICE[5079] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_SETUP to socket. 362945-[Jul 4 23:42:18] NOTICE[5079] chan_lcr.c: [call=NULL ast=NULL] Received new ref by LCR, due to incomming call. (ref=4) 362946-[Jul 4 23:42:18] NOTICE[5079] chan_lcr.c: [call=0 ast=NULL] Call instance allocated. 362947-[Jul 4 23:42:18] NOTICE[5079] chan_lcr.c: [call=4 ast=NULL] Incomming setup from LCR. (callerid 6082XXXX0, dialing 23) kernel oops [ 1215.884008] INFO: RCU detected CPU 0 stall (t=32500 jiffies) [ 1215.884008] sending NMI to all CPUs: [ 1095.884007] NMI backtrace for cpu 1 [ 1095.884007] Modules linked in: ppdev lp ipv6 reiserfs w83781d hwmon_vid mISDN_dsp snd_emu10k1_synth snd_emux_synth snd_seq_virmidi snd_seq_midi_emul snd_emu10k1 snd_ac97_codec ac97_bus snd_pcm_oss snd_mixer_oss snd_pcm snd_page_alloc snd_util_mem snd_hwdep snd_seq_dummy snd_seq_oss snd_seq_midi snd_rawmidi snd_seq_midi_event snd_seq container snd_timer snd_seq_device avmfritz mISDNipac parport_pc parport button i2c_piix4 processor tpm_tis tpm tpm_bios mISDN_core emu10k1_gp snd gameport i2c_core sworks_agp agpgart soundcore pcspkr evdev ext3 jbd mbcache ide_cd_mod ide_gd_mod cdrom ata_generic libata sym53c8xx scsi_transport_spi ohci_hcd usbcore serverworks ide_pci_generic ide_core scsi_mod nls_base e100 mii thermal fan thermal_sys [last unloaded: scsi_wait_scan] [ 1095.884007] [ 1095.884007] Pid: 1427, comm: mISDN_AVM.1 Not tainted 2.6.34 #2 CUR-DLS/System Name [ 1095.884007] EIP: 0060:[] EFLAGS: 00000093 CPU: 1 [ 1095.884007] EIP is at _raw_spin_lock_irqsave+0x27/0x31 [ 1095.884007] EAX: 00000292 EBX: 00000292 ECX: 00006967 EDX: f69aab20 [ 1095.884007] ESI: f6aa982c EDI: f69aab20 EBP: f69aab20 ESP: f6443f54 [ 1095.884007] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 [ 1095.884007] Process mISDN_AVM.1 (pid: 1427, ti=f6442000 task=f6444e40 task.ti=f6442000) [ 1095.884007] Stack: [ 1095.884007] f6a21e00 00000296 f83c15fb 00000001 f6aa9830 f846d2b2 f69aab38 00000001 [ 1095.884007] <0> f719a1e0 f6443fb4 f69aab20 f83bde45 f6444e40 f719a1fc f719a1f0 f69aab38 [ 1095.884007] <0> f719a258 f719a20c f719a244 00000000 f6444e40 c104490e f6443fac f6443fac [ 1095.884007] Call Trace: [ 1095.884007] [] ? l2_send+0x637/0x7f3 [mISDN_core] [ 1095.884007] [] ? isac_l1hw+0x43/0xcf [mISDNipac] [ 1095.884007] [] ? mISDNStackd+0x2f5/0x524 [mISDN_core] [ 1095.884007] [] ? autoremove_wake_function+0x0/0x2d [ 1095.884007] [] ? mISDNStackd+0x0/0x524 [mISDN_core] [ 1095.884007] [] ? kthread+0x61/0x66 [ 1095.884007] [] ? kthread+0x0/0x66 [ 1095.884007] [] ? kernel_thread_helper+0x6/0x10 [ 1095.884007] Code: 10 eb f6 c3 56 89 c6 53 83 ec 0c 9c 58 8d 74 26 00 89 c3 fa 90 8d 74 26 00 b9 00 01 00 00 f0 66 0f c1 0e 38 e9 74 06 f3 90 8a 0e f6 83 c4 0c 89 d8 5b 5e c3 83 ec 04 89 c1 fa 90 8d 74 26 00 [ 1095.884007] Call Trace: [ 1095.884007] [] ? l2_send+0x637/0x7f3 [mISDN_core] [ 1095.884007] [] ? isac_l1hw+0x43/0xcf [mISDNipac] [ 1095.884007] [] ? mISDNStackd+0x2f5/0x524 [mISDN_core] [ 1095.884007] [] ? autoremove_wake_function+0x0/0x2d [ 1095.884007] [] ? mISDNStackd+0x0/0x524 [mISDN_core] [ 1095.884007] [] ? kthread+0x61/0x66 [ 1095.884007] [] ? kthread+0x0/0x66 [ 1095.884007] [] ? kernel_thread_helper+0x6/0x10 [ 1095.884007] Pid: 1427, comm: mISDN_AVM.1 Not tainted 2.6.34 #2 [ 1095.884007] Call Trace: [ 1095.884007] [] ? nmi_watchdog_tick+0x9b/0x155 [ 1095.884007] [] ? do_nmi+0x90/0x287 [ 1095.884007] [] ? nmi_stack_correct+0x28/0x2d [ 1095.884007] [] ? _raw_spin_lock_irqsave+0x27/0x31 [ 1095.884007] [] ? l2_send+0x637/0x7f3 [mISDN_core] [ 1095.884007] [] ? isac_l1hw+0x43/0xcf [mISDNipac] [ 1095.884007] [] ? mISDNStackd+0x2f5/0x524 [mISDN_core] [ 1095.884007] [] ? autoremove_wake_function+0x0/0x2d [ 1095.884007] [] ? mISDNStackd+0x0/0x524 [mISDN_core] [ 1095.884007] [] ? kthread+0x61/0x66 [ 1095.884007] [] ? kthread+0x0/0x66 [ 1095.884007] [] ? kernel_thread_helper+0x6/0x10 [ 1215.884008] NMI backtrace for cpu 0 [ 1215.884008] Modules linked in: ppdev lp ipv6 reiserfs w83781d hwmon_vid mISDN_dsp snd_emu10k1_synth snd_emux_synth snd_seq_virmidi snd_seq_midi_emul snd_emu10k1 snd_ac97_codec ac97_bus snd_pcm_oss snd_mixer_oss snd_pcm snd_page_alloc snd_util_mem snd_hwdep snd_seq_dummy snd_seq_oss snd_seq_midi snd_rawmidi snd_seq_midi_event snd_seq container snd_timer snd_seq_device avmfritz mISDNipac parport_pc parport button i2c_piix4 processor tpm_tis tpm tpm_bios mISDN_core emu10k1_gp snd gameport i2c_core sworks_agp agpgart soundcore pcspkr evdev ext3 jbd mbcache ide_cd_mod ide_gd_mod cdrom ata_generic libata sym53c8xx scsi_transport_spi ohci_hcd usbcore serverworks ide_pci_generic ide_core scsi_mod nls_base e100 mii thermal fan thermal_sys [last unloaded: scsi_wait_scan] [ 1215.884008] [ 1215.884008] Pid: 5079, comm: asterisk Not tainted 2.6.34 #2 CUR-DLS/System Name [ 1215.884008] EIP: 0060:[] EFLAGS: 00000046 CPU: 0 [ 1215.884008] EIP is at delay_tsc+0x2b/0x62 [ 1215.884008] EAX: 18c5494c EBX: 000f2280 ECX: 00c67000 EDX: 0000012f [ 1215.884008] ESI: 00000000 EDI: 18c54927 EBP: 00000000 ESP: f5dc7d34 [ 1215.884008] DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068 [ 1215.884008] Process asterisk (pid: 5079, ti=f5dc6000 task=f1cda5a0 task.ti=f5dc6000) [ 1215.884008] Stack: [ 1215.884008] 18c543f7 00000006 00000000 00000000 c131da00 00000001 c131da00 c2003dec [ 1215.884008] <0> f5dc7e1c c11337d2 c1015ac9 00000000 c107160f c12ae3b4 00000000 00007ef4 [ 1215.884008] <0> c131da00 c139cdd0 00000000 00000000 f1cda5a0 f5dc7e1c c10717f4 00000000 [ 1215.884008] Call Trace: [ 1215.884008] [] ? __const_udelay+0x29/0x2a [ 1215.884008] [] ? arch_trigger_all_cpu_backtrace+0x3f/0x49 [ 1215.884008] [] ? __rcu_pending+0x52/0x21b [ 1215.884008] [] ? rcu_check_callbacks+0x1c/0xd8 [ 1215.884008] [] ? update_process_times+0x2a/0x43 [ 1215.884008] [] ? tick_sched_timer+0x61/0x8e [ 1215.884008] [] ? tick_sched_timer+0x0/0x8e [ 1215.884008] [] ? __run_hrtimer+0xaf/0xfb [ 1215.884008] [] ? hrtimer_interrupt+0xdf/0x1cf [ 1215.884008] [] ? smp_apic_timer_interrupt+0x66/0x75 [ 1215.884008] [] ? apic_timer_interrupt+0x2a/0x30 [ 1215.884008] [] ? _raw_spin_lock+0xe/0x15 [ 1215.884008] [] ? avm_fritzv2_interrupt+0xf/0x150 [avmfritz] [ 1215.884008] [] ? handle_IRQ_event+0x4e/0x101 [ 1215.884008] [] ? handle_fasteoi_irq+0x6d/0x9e [ 1215.884008] [] ? handle_irq+0x17/0x1c [ 1215.884008] [] ? do_IRQ+0x38/0x8e [ 1215.884008] [] ? common_interrupt+0x29/0x30 [ 1215.884008] [] ? do_sync_write+0xa0/0xe4 [ 1215.884008] [] ? ext3_fill_super+0x87d/0x15ce [ext3] [ 1215.884008] [] ? flush_cpu_workqueue+0x4a/0x63 [ 1215.884008] [] ? flush_workqueue+0x28/0x45 [ 1215.884008] [] ? mISDN_freebchannel+0x22/0x26 [mISDN_core] [ 1215.884008] [] ? avm_bctrl+0x42/0xbe [avmfritz] [ 1215.884008] [] ? dsp_ctrl+0x45/0x147 [mISDN_dsp] [ 1215.884008] [] ? delete_channel+0x5e/0x16c [mISDN_core] [ 1215.884008] [] ? data_sock_release+0x67/0xe1 [mISDN_core] [ 1215.884008] [] ? sock_release+0x11/0x51 [ 1215.884008] [] ? sock_close+0x19/0x1c [ 1215.884008] [] ? __fput+0xc0/0x16a [ 1215.884008] [] ? filp_close+0x4e/0x54 [ 1215.884008] [] ? sys_close+0x5a/0x8d [ 1215.884008] [] ? sysenter_do_call+0x12/0x28 [ 1215.884008] [] ? threshold_create_bank+0x17e/0x236 [ 1215.884008] Code: 55 57 56 53 89 c3 83 ec 14 64 8b 35 78 bd 39 c1 8d 76 00 8d 76 00 0f 31 8d 74 26 00 89 04 24 8d 76 00 8d 76 00 0f 31 8d 74 26 00 <89> c7 2b 04 24 39 d8 73 26 f3 90 64 8b 2d 78 bd 39 c1 39 ee 74 [ 1215.884008] Call Trace: [ 1215.884008] [] ? __const_udelay+0x29/0x2a [ 1215.884008] [] ? arch_trigger_all_cpu_backtrace+0x3f/0x49 [ 1215.884008] [] ? __rcu_pending+0x52/0x21b [ 1215.884008] [] ? rcu_check_callbacks+0x1c/0xd8 [ 1215.884008] [] ? update_process_times+0x2a/0x43 [ 1215.884008] [] ? tick_sched_timer+0x61/0x8e [ 1215.884008] [] ? tick_sched_timer+0x0/0x8e [ 1215.884008] [] ? __run_hrtimer+0xaf/0xfb [ 1215.884008] [] ? hrtimer_interrupt+0xdf/0x1cf [ 1215.884008] [] ? smp_apic_timer_interrupt+0x66/0x75 [ 1215.884008] [] ? apic_timer_interrupt+0x2a/0x30 [ 1215.884008] [] ? _raw_spin_lock+0xe/0x15 [ 1215.884008] [] ? avm_fritzv2_interrupt+0xf/0x150 [avmfritz] [ 1215.884008] [] ? handle_IRQ_event+0x4e/0x101 [ 1215.884008] [] ? handle_fasteoi_irq+0x6d/0x9e [ 1215.884008] [] ? handle_irq+0x17/0x1c [ 1215.884008] [] ? do_IRQ+0x38/0x8e [ 1215.884008] [] ? common_interrupt+0x29/0x30 [ 1215.884008] [] ? do_sync_write+0xa0/0xe4 [ 1215.884008] [] ? ext3_fill_super+0x87d/0x15ce [ext3] [ 1215.884008] [] ? flush_cpu_workqueue+0x4a/0x63 [ 1215.884008] [] ? flush_workqueue+0x28/0x45 [ 1215.884008] [] ? mISDN_freebchannel+0x22/0x26 [mISDN_core] [ 1215.884008] [] ? avm_bctrl+0x42/0xbe [avmfritz] [ 1215.884008] [] ? dsp_ctrl+0x45/0x147 [mISDN_dsp] [ 1215.884008] [] ? delete_channel+0x5e/0x16c [mISDN_core] [ 1215.884008] [] ? data_sock_release+0x67/0xe1 [mISDN_core] [ 1215.884008] [] ? sock_release+0x11/0x51 [ 1215.884008] [] ? sock_close+0x19/0x1c [ 1215.884008] [] ? __fput+0xc0/0x16a [ 1215.884008] [] ? filp_close+0x4e/0x54 [ 1215.884008] [] ? sys_close+0x5a/0x8d [ 1215.884008] [] ? sysenter_do_call+0x12/0x28 [ 1215.884008] [] ? threshold_create_bank+0x17e/0x236 [ 1215.884008] Pid: 5079, comm: asterisk Not tainted 2.6.34 #2 [ 1215.884008] Call Trace: [ 1215.884008] [] ? nmi_watchdog_tick+0x9b/0x155 [ 1215.884008] [] ? do_nmi+0x90/0x287 [ 1215.884008] [] ? nmi_stack_correct+0x28/0x2d [ 1215.884008] [] ? delay_tsc+0x2b/0x62 [ 1215.884008] [] ? __const_udelay+0x29/0x2a [ 1215.884008] [] ? arch_trigger_all_cpu_backtrace+0x3f/0x49 [ 1215.884008] [] ? __rcu_pending+0x52/0x21b [ 1215.884008] [] ? rcu_check_callbacks+0x1c/0xd8 [ 1215.884008] [] ? update_process_times+0x2a/0x43 [ 1215.884008] [] ? tick_sched_timer+0x61/0x8e [ 1215.884008] [] ? tick_sched_timer+0x0/0x8e [ 1215.884008] [] ? __run_hrtimer+0xaf/0xfb [ 1215.884008] [] ? hrtimer_interrupt+0xdf/0x1cf [ 1215.884008] [] ? smp_apic_timer_interrupt+0x66/0x75 [ 1215.884008] [] ? apic_timer_interrupt+0x2a/0x30 [ 1215.884008] [] ? _raw_spin_lock+0xe/0x15 [ 1215.884008] [] ? avm_fritzv2_interrupt+0xf/0x150 [avmfritz] [ 1215.884008] [] ? handle_IRQ_event+0x4e/0x101 [ 1215.884008] [] ? handle_fasteoi_irq+0x6d/0x9e [ 1215.884008] [] ? handle_irq+0x17/0x1c [ 1215.884008] [] ? do_IRQ+0x38/0x8e [ 1215.884008] [] ? common_interrupt+0x29/0x30 [ 1215.884008] [] ? do_sync_write+0xa0/0xe4 [ 1215.884008] [] ? ext3_fill_super+0x87d/0x15ce [ext3] [ 1215.884008] [] ? flush_cpu_workqueue+0x4a/0x63 [ 1215.884008] [] ? flush_workqueue+0x28/0x45 [ 1215.884008] [] ? mISDN_freebchannel+0x22/0x26 [mISDN_core] [ 1215.884008] [] ? avm_bctrl+0x42/0xbe [avmfritz] [ 1215.884008] [] ? dsp_ctrl+0x45/0x147 [mISDN_dsp] [ 1215.884008] [] ? delete_channel+0x5e/0x16c [mISDN_core] [ 1215.884008] [] ? data_sock_release+0x67/0xe1 [mISDN_core] [ 1215.884008] [] ? sock_release+0x11/0x51 [ 1215.884008] [] ? sock_close+0x19/0x1c [ 1215.884008] [] ? __fput+0xc0/0x16a [ 1215.884008] [] ? filp_close+0x4e/0x54 [ 1215.884008] [] ? sys_close+0x5a/0x8d [ 1215.884008] [] ? sysenter_do_call+0x12/0x28 [ 1215.884008] [] ? threshold_create_bank+0x17e/0x236 -------------------------------------------------------------------- usinf DEADLOCK_AVOIDANCE in handle_queue but commenting out the complete code part in send_setup_to_lcr C+(b4785b90) C-(b4785b90) 789 A9+(b371fb90) 0--1356 A9-(b371fb90) *2(b371fb90) *3(b371fb90) a9(b371fb90) c(b4785b90) A8+(b36e3b90) A8-(b36e3b90) a8(b36e3b90) C+(b4785b90) C-(b4785b90) 789 A9+(b36e3b90) 0--1356 A9-(b36e3b90) *2(b36e3b90) *3(b36e3b90) a9(b36e3b90) c(b4785b90) C+(b4785b90) C-(b4785b90) 789 A9+(b371fb90) 0--1356 A9-(b371fb90) *2 last call before hang [Jul 5 00:44:31] NOTICE[7235] chan_lcr.c: [call=NULL ast=NULL] Received request from Asterisk. (data=Ext/06082XXXX23) [Jul 5 00:44:31] NOTICE[7235] chan_lcr.c: [call=0 ast=NULL] Call instance allocated. [Jul 5 00:44:31] NOTICE[7235] chan_lcr.c: [call=NULL ast=lcr/23] Received call from Asterisk. [Jul 5 00:44:31] NOTICE[7235] chan_lcr.c: [call=NULL ast=NULL] Sending (null) to socket. [Jul 5 00:44:31] NOTICE[4782] chan_lcr.c: [call=NULL ast=NULL] Received new ref by LCR, as requested from chan_lcr. (ref=23) [Jul 5 00:44:31] NOTICE[4782] chan_lcr.c: [call=23 ast=lcr/23] Sending setup to LCR. (interface=Ext dialstring=06082XXXX23, cid=) [Jul 5 00:44:31] NOTICE[4782] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_SETUP to socket. [Jul 5 00:44:32] NOTICE[4782] chan_lcr.c: [call=NULL ast=NULL] Received new ref by LCR, due to incomming call. (ref=24) [Jul 5 00:44:32] NOTICE[4782] chan_lcr.c: [call=0 ast=NULL] Call instance allocated. [Jul 5 00:44:32] NOTICE[4782] chan_lcr.c: [call=24 ast=NULL] Incomming setup from LCR. (callerid 6082XXXX0, dialing 23) [Jul 5 00:44:32] NOTICE[4782] chan_lcr.c: [call=24 ast=lcr/24] Try to start pbx. (exten=23 context=from-ISDN-extern complete=no) [Jul 5 00:44:32] NOTICE[4782] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_OVERLAP to socket. [Jul 5 00:44:32] NOTICE[4782] chan_lcr.c: [call=24 ast=lcr/24] Extensions matches. [Jul 5 00:44:32] NOTICE[4782] chan_lcr.c: [call=24 ast=lcr/24] Starting call to Asterisk due to matching extension. [Jul 5 00:44:32] NOTICE[7236] chan_lcr.c: [call=24 ast=lcr/24] Received answer from Asterisk (maybe during lcr_bridge). [Jul 5 00:44:32] NOTICE[7236] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_CONNECT to socket. [Jul 5 00:44:32] NOTICE[7236] chan_lcr.c: [call=24 ast=lcr/24] Requesting B-channel. [Jul 5 00:44:32] NOTICE[7236] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_HELLO to socket. [Jul 5 00:44:32] NOTICE[7236] chan_lcr.c: [call=24 ast=lcr/24] Received indicate -1. [Jul 5 00:44:32] NOTICE[4782] chan_lcr.c: [call=NULL ast=NULL] Received BCHANNEL_ASSIGN message. (handle=00000002) for ref 24 [Jul 5 00:44:32] NOTICE[4782] bchannel.c: [call=24 ast=NULL] Open DSP audio [Jul 5 00:44:32] NOTICE[4782] bchannel.c: [call=24 ast=NULL] Activating B-channel. [Jul 5 00:44:32] NOTICE[4782] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_HELLO to socket. [Jul 5 00:44:32] NOTICE[4782] bchannel.c: [call=24 ast=NULL] DL_ESTABLISH confirm: bchannel is now activated (socket 50). [Jul 5 00:44:32] NOTICE[4782] bchannel.c: [call=NULL ast=NULL] Sending PH_CONTROL DSP-TX_DEJITTER 240f,0 [Jul 5 00:44:32] NOTICE[4782] bchannel.c: [call=NULL ast=NULL] Sending PH_CONTROL DSP-DTMF 2100,0 [Jul 5 00:44:32] NOTICE[7236] chan_lcr.c: [call=24 ast=lcr/24] Received indicate AST_CONTROL_RINGING from Asterisk. [Jul 5 00:44:32] NOTICE[7236] chan_lcr.c: [call=24 ast=lcr/24] Using Asterisk 'ring' indication [Jul 5 00:44:32] NOTICE[7236] chan_lcr.c: [call=24 ast=lcr/24] Received answer from Asterisk (maybe during lcr_bridge). [Jul 5 00:44:32] NOTICE[7236] chan_lcr.c: [call=24 ast=lcr/24] Received indicate -1. [Jul 5 00:44:32] NOTICE[7236] chan_lcr.c: [call=24 ast=lcr/24] Received AST_CONTROL_SRCUPDATE from Asterisk. [Jul 5 00:44:32] NOTICE[4782] chan_lcr.c: [call=23 ast=lcr/23] Incomming pattern indication from LCR. [Jul 5 00:44:32] NOTICE[4782] chan_lcr.c: [call=23 ast=lcr/23] Requesting B-channel. [Jul 5 00:44:32] NOTICE[4782] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_HELLO to socket. [Jul 5 00:44:32] NOTICE[4782] chan_lcr.c: [call=23 ast=lcr/23] Channel clear to send to Asterisk. [Jul 5 00:44:32] NOTICE[4782] chan_lcr.c: [call=23 ast=lcr/23] Incomming setup acknowledge from LCR. [Jul 5 00:44:32] NOTICE[4782] chan_lcr.c: [call=NULL ast=NULL] Received BCHANNEL_ASSIGN message. (handle=00000001) for ref 23 [Jul 5 00:44:32] NOTICE[4782] bchannel.c: [call=23 ast=NULL] Open DSP audio [Jul 5 00:44:32] NOTICE[4782] bchannel.c: [call=23 ast=NULL] Activating B-channel. [Jul 5 00:44:32] NOTICE[4782] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_HELLO to socket. [Jul 5 00:44:32] NOTICE[4782] bchannel.c: [call=23 ast=NULL] DL_ESTABLISH confirm: bchannel is now activated (socket 53). [Jul 5 00:44:32] NOTICE[4782] bchannel.c: [call=NULL ast=NULL] Sending PH_CONTROL DSP-TX_DEJITTER 240f,0 [Jul 5 00:44:32] NOTICE[4782] bchannel.c: [call=NULL ast=NULL] Sending PH_CONTROL DSP-DTMF 2100,0 [Jul 5 00:44:33] NOTICE[4782] chan_lcr.c: [call=23 ast=lcr/23] Incomming connect (answer) from LCR. [Jul 5 00:44:33] NOTICE[4782] chan_lcr.c: [call=23 ast=lcr/23] Channel clear to send to Asterisk. [Jul 5 00:44:33] NOTICE[4782] chan_lcr.c: [call=23 ast=lcr/23] Sending queued ANSWER to Asterisk. [Jul 5 00:44:33] NOTICE[7235] chan_lcr.c: [call=23 ast=lcr/23] Received AST_CONTROL_SRCUPDATE from Asterisk. [Jul 5 00:44:33] NOTICE[4782] chan_lcr.c: [call=23 ast=lcr/23] Incomming facility from LCR. occurrence of DEADLOCK_AVOIDANCE during test 363734-[Jul 5 00:40:32] NOTICE[4782] chan_lcr.c: [call=18 ast=lcr/18] Incomming disconnect from LCR. (cause=16) 363735-[Jul 5 00:40:33] NOTICE[4782] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_HELLO to socket. 363736-[Jul 5 00:40:33] NOTICE[4782] chan_lcr.c: [call=NULL ast=NULL] Sending MESSAGE_RELEASE to socket. 363737:[Jul 5 00:40:33] NOTICE[4782] chan_lcr.c: [call=0 ast=lcr/18] Avoiding deadlock before sending to Asterisk. 363738:[Jul 5 00:40:33] NOTICE[4782] chan_lcr.c: [call=0 ast=lcr/18] Deadlock avoided before sending to Asterisk. 363739-[Jul 5 00:40:33] NOTICE[4782] chan_lcr.c: [call=0 ast=lcr/18] Channel clear to send to Asterisk. 363740-[Jul 5 00:40:33] NOTICE[4782] chan_lcr.c: [call=0 ast=lcr/18] Sending queued HANGUP to Asterisk. 363741-[Jul 5 00:40:33] NOTICE[6870] chan_lcr.c: [call=NULL ast=NULL] Received request from Asterisk. (data=Ext/) 363742-[Jul 5 00:40:33] NOTICE[6870] chan_lcr.c: [call=0 ast=NULL] Call instance allocated. kernel oops, did not reach my serial console :/