rendered paste bodyusing 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:[<c1234ff2>] 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] [<f83c15fb>] ? l2_send+0x637/0x7f3 [mISDN_core]
[ 1095.884007] [<f846d2b2>] ? isac_l1hw+0x43/0xcf [mISDNipac]
[ 1095.884007] [<f83bde45>] ? mISDNStackd+0x2f5/0x524 [mISDN_core]
[ 1095.884007] [<c104490e>] ? autoremove_wake_function+0x0/0x2d
[ 1095.884007] [<f83bdb50>] ? mISDNStackd+0x0/0x524 [mISDN_core]
[ 1095.884007] [<c10445b9>] ? kthread+0x61/0x66
[ 1095.884007] [<c1044558>] ? kthread+0x0/0x66
[ 1095.884007] [<c1003436>] ? 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 <eb> 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] [<f83c15fb>] ? l2_send+0x637/0x7f3 [mISDN_core]
[ 1095.884007] [<f846d2b2>] ? isac_l1hw+0x43/0xcf [mISDNipac]
[ 1095.884007] [<f83bde45>] ? mISDNStackd+0x2f5/0x524 [mISDN_core]
[ 1095.884007] [<c104490e>] ? autoremove_wake_function+0x0/0x2d
[ 1095.884007] [<f83bdb50>] ? mISDNStackd+0x0/0x524 [mISDN_core]
[ 1095.884007] [<c10445b9>] ? kthread+0x61/0x66
[ 1095.884007] [<c1044558>] ? kthread+0x0/0x66
[ 1095.884007] [<c1003436>] ? 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] [<c1015bf4>] ? nmi_watchdog_tick+0x9b/0x155
[ 1095.884007] [<c1003f0c>] ? do_nmi+0x90/0x287
[ 1095.884007] [<c1235a55>] ? nmi_stack_correct+0x28/0x2d
[ 1095.884007] [<c1234ff2>] ? _raw_spin_lock_irqsave+0x27/0x31
[ 1095.884007] [<f83c15fb>] ? l2_send+0x637/0x7f3 [mISDN_core]
[ 1095.884007] [<f846d2b2>] ? isac_l1hw+0x43/0xcf [mISDNipac]
[ 1095.884007] [<f83bde45>] ? mISDNStackd+0x2f5/0x524 [mISDN_core]
[ 1095.884007] [<c104490e>] ? autoremove_wake_function+0x0/0x2d
[ 1095.884007] [<f83bdb50>] ? mISDNStackd+0x0/0x524 [mISDN_core]
[ 1095.884007] [<c10445b9>] ? kthread+0x61/0x66
[ 1095.884007] [<c1044558>] ? kthread+0x0/0x66
[ 1095.884007] [<c1003436>] ? 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:[<c1133760>] 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] [<c11337d2>] ? __const_udelay+0x29/0x2a
[ 1215.884008] [<c1015ac9>] ? arch_trigger_all_cpu_backtrace+0x3f/0x49
[ 1215.884008] [<c107160f>] ? __rcu_pending+0x52/0x21b
[ 1215.884008] [<c10717f4>] ? rcu_check_callbacks+0x1c/0xd8
[ 1215.884008] [<c103af2b>] ? update_process_times+0x2a/0x43
[ 1215.884008] [<c10501d5>] ? tick_sched_timer+0x61/0x8e
[ 1215.884008] [<c1050174>] ? tick_sched_timer+0x0/0x8e
[ 1215.884008] [<c104735b>] ? __run_hrtimer+0xaf/0xfb
[ 1215.884008] [<c1047598>] ? hrtimer_interrupt+0xdf/0x1cf
[ 1215.884008] [<c1015217>] ? smp_apic_timer_interrupt+0x66/0x75
[ 1215.884008] [<c1235772>] ? apic_timer_interrupt+0x2a/0x30
[ 1215.884008] [<c1234fc4>] ? _raw_spin_lock+0xe/0x15
[ 1215.884008] [<f847b881>] ? avm_fritzv2_interrupt+0xf/0x150 [avmfritz]
[ 1215.884008] [<c106e52f>] ? handle_IRQ_event+0x4e/0x101
[ 1215.884008] [<c106fab2>] ? handle_fasteoi_irq+0x6d/0x9e
[ 1215.884008] [<c1004ca7>] ? handle_irq+0x17/0x1c
[ 1215.884008] [<c100451f>] ? do_IRQ+0x38/0x8e
[ 1215.884008] [<c1003429>] ? common_interrupt+0x29/0x30
[ 1215.884008] [<c10b0f7a>] ? do_sync_write+0xa0/0xe4
[ 1215.884008] [<f82f00d8>] ? ext3_fill_super+0x87d/0x15ce [ext3]
[ 1215.884008] [<c1041d63>] ? flush_cpu_workqueue+0x4a/0x63
[ 1215.884008] [<c1041ef4>] ? flush_workqueue+0x28/0x45
[ 1215.884008] [<f83bd138>] ? mISDN_freebchannel+0x22/0x26 [mISDN_core]
[ 1215.884008] [<f847ba04>] ? avm_bctrl+0x42/0xbe [avmfritz]
[ 1215.884008] [<f87973ff>] ? dsp_ctrl+0x45/0x147 [mISDN_dsp]
[ 1215.884008] [<f83bd5a2>] ? delete_channel+0x5e/0x16c [mISDN_core]
[ 1215.884008] [<f83bc492>] ? data_sock_release+0x67/0xe1 [mISDN_core]
[ 1215.884008] [<c11ba657>] ? sock_release+0x11/0x51
[ 1215.884008] [<c11ba6b0>] ? sock_close+0x19/0x1c
[ 1215.884008] [<c10b214a>] ? __fput+0xc0/0x16a
[ 1215.884008] [<c10af890>] ? filp_close+0x4e/0x54
[ 1215.884008] [<c10af8f0>] ? sys_close+0x5a/0x8d
[ 1215.884008] [<c1002eb8>] ? sysenter_do_call+0x12/0x28
[ 1215.884008] [<c1230000>] ? 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] [<c11337d2>] ? __const_udelay+0x29/0x2a
[ 1215.884008] [<c1015ac9>] ? arch_trigger_all_cpu_backtrace+0x3f/0x49
[ 1215.884008] [<c107160f>] ? __rcu_pending+0x52/0x21b
[ 1215.884008] [<c10717f4>] ? rcu_check_callbacks+0x1c/0xd8
[ 1215.884008] [<c103af2b>] ? update_process_times+0x2a/0x43
[ 1215.884008] [<c10501d5>] ? tick_sched_timer+0x61/0x8e
[ 1215.884008] [<c1050174>] ? tick_sched_timer+0x0/0x8e
[ 1215.884008] [<c104735b>] ? __run_hrtimer+0xaf/0xfb
[ 1215.884008] [<c1047598>] ? hrtimer_interrupt+0xdf/0x1cf
[ 1215.884008] [<c1015217>] ? smp_apic_timer_interrupt+0x66/0x75
[ 1215.884008] [<c1235772>] ? apic_timer_interrupt+0x2a/0x30
[ 1215.884008] [<c1234fc4>] ? _raw_spin_lock+0xe/0x15
[ 1215.884008] [<f847b881>] ? avm_fritzv2_interrupt+0xf/0x150 [avmfritz]
[ 1215.884008] [<c106e52f>] ? handle_IRQ_event+0x4e/0x101
[ 1215.884008] [<c106fab2>] ? handle_fasteoi_irq+0x6d/0x9e
[ 1215.884008] [<c1004ca7>] ? handle_irq+0x17/0x1c
[ 1215.884008] [<c100451f>] ? do_IRQ+0x38/0x8e
[ 1215.884008] [<c1003429>] ? common_interrupt+0x29/0x30
[ 1215.884008] [<c10b0f7a>] ? do_sync_write+0xa0/0xe4
[ 1215.884008] [<f82f00d8>] ? ext3_fill_super+0x87d/0x15ce [ext3]
[ 1215.884008] [<c1041d63>] ? flush_cpu_workqueue+0x4a/0x63
[ 1215.884008] [<c1041ef4>] ? flush_workqueue+0x28/0x45
[ 1215.884008] [<f83bd138>] ? mISDN_freebchannel+0x22/0x26 [mISDN_core]
[ 1215.884008] [<f847ba04>] ? avm_bctrl+0x42/0xbe [avmfritz]
[ 1215.884008] [<f87973ff>] ? dsp_ctrl+0x45/0x147 [mISDN_dsp]
[ 1215.884008] [<f83bd5a2>] ? delete_channel+0x5e/0x16c [mISDN_core]
[ 1215.884008] [<f83bc492>] ? data_sock_release+0x67/0xe1 [mISDN_core]
[ 1215.884008] [<c11ba657>] ? sock_release+0x11/0x51
[ 1215.884008] [<c11ba6b0>] ? sock_close+0x19/0x1c
[ 1215.884008] [<c10b214a>] ? __fput+0xc0/0x16a
[ 1215.884008] [<c10af890>] ? filp_close+0x4e/0x54
[ 1215.884008] [<c10af8f0>] ? sys_close+0x5a/0x8d
[ 1215.884008] [<c1002eb8>] ? sysenter_do_call+0x12/0x28
[ 1215.884008] [<c1230000>] ? threshold_create_bank+0x17e/0x236
[ 1215.884008] Pid: 5079, comm: asterisk Not tainted 2.6.34 #2
[ 1215.884008] Call Trace:
[ 1215.884008] [<c1015bf4>] ? nmi_watchdog_tick+0x9b/0x155
[ 1215.884008] [<c1003f0c>] ? do_nmi+0x90/0x287
[ 1215.884008] [<c1235a55>] ? nmi_stack_correct+0x28/0x2d
[ 1215.884008] [<c1133760>] ? delay_tsc+0x2b/0x62
[ 1215.884008] [<c11337d2>] ? __const_udelay+0x29/0x2a
[ 1215.884008] [<c1015ac9>] ? arch_trigger_all_cpu_backtrace+0x3f/0x49
[ 1215.884008] [<c107160f>] ? __rcu_pending+0x52/0x21b
[ 1215.884008] [<c10717f4>] ? rcu_check_callbacks+0x1c/0xd8
[ 1215.884008] [<c103af2b>] ? update_process_times+0x2a/0x43
[ 1215.884008] [<c10501d5>] ? tick_sched_timer+0x61/0x8e
[ 1215.884008] [<c1050174>] ? tick_sched_timer+0x0/0x8e
[ 1215.884008] [<c104735b>] ? __run_hrtimer+0xaf/0xfb
[ 1215.884008] [<c1047598>] ? hrtimer_interrupt+0xdf/0x1cf
[ 1215.884008] [<c1015217>] ? smp_apic_timer_interrupt+0x66/0x75
[ 1215.884008] [<c1235772>] ? apic_timer_interrupt+0x2a/0x30
[ 1215.884008] [<c1234fc4>] ? _raw_spin_lock+0xe/0x15
[ 1215.884008] [<f847b881>] ? avm_fritzv2_interrupt+0xf/0x150 [avmfritz]
[ 1215.884008] [<c106e52f>] ? handle_IRQ_event+0x4e/0x101
[ 1215.884008] [<c106fab2>] ? handle_fasteoi_irq+0x6d/0x9e
[ 1215.884008] [<c1004ca7>] ? handle_irq+0x17/0x1c
[ 1215.884008] [<c100451f>] ? do_IRQ+0x38/0x8e
[ 1215.884008] [<c1003429>] ? common_interrupt+0x29/0x30
[ 1215.884008] [<c10b0f7a>] ? do_sync_write+0xa0/0xe4
[ 1215.884008] [<f82f00d8>] ? ext3_fill_super+0x87d/0x15ce [ext3]
[ 1215.884008] [<c1041d63>] ? flush_cpu_workqueue+0x4a/0x63
[ 1215.884008] [<c1041ef4>] ? flush_workqueue+0x28/0x45
[ 1215.884008] [<f83bd138>] ? mISDN_freebchannel+0x22/0x26 [mISDN_core]
[ 1215.884008] [<f847ba04>] ? avm_bctrl+0x42/0xbe [avmfritz]
[ 1215.884008] [<f87973ff>] ? dsp_ctrl+0x45/0x147 [mISDN_dsp]
[ 1215.884008] [<f83bd5a2>] ? delete_channel+0x5e/0x16c [mISDN_core]
[ 1215.884008] [<f83bc492>] ? data_sock_release+0x67/0xe1 [mISDN_core]
[ 1215.884008] [<c11ba657>] ? sock_release+0x11/0x51
[ 1215.884008] [<c11ba6b0>] ? sock_close+0x19/0x1c
[ 1215.884008] [<c10b214a>] ? __fput+0xc0/0x16a
[ 1215.884008] [<c10af890>] ? filp_close+0x4e/0x54
[ 1215.884008] [<c10af8f0>] ? sys_close+0x5a/0x8d
[ 1215.884008] [<c1002eb8>] ? sysenter_do_call+0x12/0x28
[ 1215.884008] [<c1230000>] ? 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 :/