[asterisk-bugs] [Asterisk 0013959]: Zaptel/DAHDi freezes E1 PRI channels when recieving fax.
Asterisk Bug Tracker
noreply at bugs.digium.com
Mon Nov 24 15:50:30 CST 2008
A NOTE has been added to this issue.
======================================================================
http://bugs.digium.com/view.php?id=13959
======================================================================
Reported By: vinsik
Assigned To:
======================================================================
Project: Asterisk
Issue ID: 13959
Category: Channels/chan_dahdi
Reproducibility: always
Severity: major
Priority: normal
Status: new
Asterisk Version: 1.4.23
SVN Branch (only for SVN checkouts, not tarball releases): 1.4
SVN Revision (number only!):
Disclaimer on File?: N/A
Request Review:
======================================================================
Date Submitted: 2008-11-24 07:23 CST
Last Modified: 2008-11-24 15:50 CST
======================================================================
Summary: Zaptel/DAHDi freezes E1 PRI channels when recieving
fax.
Description:
Asterisk locks up when trying to send fax from E1 PRI to SIP ATA device.
(Outbound works)
CLI stops responding when you try to access DAHDi or channel related
info.
Also 2M link is dropped down when this lock occurs.
Only asterisk restart helps.
This is 'core show locks' output:
=== <file> <line num> <function> <lock name> <lock addr> (times locked)
===
=== Thread ID: 3079187344 (pri_dchannel started at [ 9697]
chan_dahdi.c start_pri())
=== ---> Lock http://bugs.digium.com/view.php?id=0 (chan_dahdi.c): MUTEX 8678
pri_dchannel &pri->lock
0xb7940e24 (1)
=== ---> Waiting for Lock http://bugs.digium.com/view.php?id=1 (chan_dahdi.c):
MUTEX 9424 pri_dchannel
&pri->pvts[chanpos]->lock 0x821b6f8 (1)
=== --- ---> Locked Here: chan_dahdi.c line 4753 (dahdi_read)
=== -------------------------------------------------------------------
===
=== Thread ID: 3069733776 (autoservice_run started at [ 228]
autoservice.c ast_autoservice_start())
=== ---> Waiting for Lock http://bugs.digium.com/view.php?id=0 (channel.c):
MUTEX 1682 ast_waitfor_nandfds
&c[x]->lock 0x8281548 (1)
=== --- ---> Locked Here: channel.c line 1978 (__ast_read)
=== -------------------------------------------------------------------
===
=== Thread ID: 3069979536 (ss_thread started at [ 9060]
chan_dahdi.c pri_dchannel())
=== ---> Lock http://bugs.digium.com/view.php?id=0 (channel.c): MUTEX 1978
__ast_read &chan->lock 0x8281548
(1)
=== ---> Lock http://bugs.digium.com/view.php?id=1 (chan_dahdi.c): MUTEX 4753
dahdi_read &p->lock 0x821b6f8
(1)
=== ---> Lock http://bugs.digium.com/view.php?id=2 (pbx.c): RDLOCK 6127
ast_rdlock_contexts &conlock
0x81bde40 (1)
=== -------------------------------------------------------------------
Have tried asterisk-1.4.23-rc1 and DAHDi (linux/tools) 2.1.0-rc4.
I can provide more information if needed.
======================================================================
----------------------------------------------------------------------
(0095428) kreijnen (reporter) - 2008-11-24 15:50
http://bugs.digium.com/view.php?id=13959#c95428
----------------------------------------------------------------------
Here is the output from Asterisk 1.4.22 Dahdi 2.0
Also hangs.
-- Accepting call from '' to '455268146' on channel 0/1, span 3
[Nov 24 22:43:20] DEBUG[3823]: chan_dahdi.c:1485 dahdi_enable_ec: Enabled
echo cancellation on channel 63
[Nov 24 22:43:20] DEBUG[3836]: pbx.c:1842 pbx_extension_helper: Launching
'Set'
-- Executing [455268146 at mor_pstn_local:1] Set("Zap/63-1",
"CDR(ACCOUNTCODE)=3") in new stack
[Nov 24 22:43:20] DEBUG[3836]: pbx.c:1842 pbx_extension_helper: Launching
'Goto'
-- Executing [455268146 at mor_pstn_local:2] Goto("Zap/63-1",
"mor_pstn1|455268146|1") in new stack
-- Goto (mor_pstn1,455268146,1)
[Nov 24 22:43:20] DEBUG[3836]: pbx.c:1842 pbx_extension_helper: Launching
'Set'
-- Executing [455268146 at mor_pstn1:1] Set("Zap/63-1",
"CDR(ACCOUNTCODE)=3") in new stack
[Nov 24 22:43:20] DEBUG[3836]: pbx.c:1842 pbx_extension_helper: Launching
'Goto'
-- Executing [455268146 at mor_pstn1:2] Goto("Zap/63-1",
"mor|31455268146|1") in new stack
-- Goto (mor,31455268146,1)
[Nov 24 22:43:20] DEBUG[3836]: pbx.c:1691
pbx_substitute_variables_helper_full: Function result is ''
-- Executing AGI("Zap/63-1", "mor-recordings.php||31455268146")
-- Launched AGI Script /var/lib/asterisk/agi-bin/mor-recordings.php
== mor-recordings.php||31455268146: Starting Recording script for MOR
== mor-recordings.php||31455268146: Global CID Name: , User CID Name:
== mor-recordings.php||31455268146: Src: , dst: 31455268146, src
device_id: , dst device_id: 195,
== mor-recordings.php||31455268146: This call will not be recorded
-- AGI Script mor-recordings.php completed, returning 0
[Nov 24 22:43:20] DEBUG[3836]: pbx.c:1691
pbx_substitute_variables_helper_full: Function result is ''
[Nov 24 22:43:20] DEBUG[3836]: pbx.c:1759
pbx_substitute_variables_helper_full: Expression result is '0'
-- Executing GotoIf("Zap/63-1", "0?3:5")
-- Goto (mor,31455268146,5)
-- Executing mor("Zap/63-1", "31455268146")
[Nov 24 22:43:20] NOTICE[3836]: app_mor.c:3328 mor_get_variables: Tell
balance: 0, tell time: 0, tell time mod.: 1.000000, tell r.time when left:
0 s, tell r.time every: 60 s, card_id: 0, callback: 0
[Nov 24 22:43:20] NOTICE[3836]: app_mor.c:452 mor_authorize: Date:
2008-11-24, time: 22:43:20
[Nov 24 22:43:20] NOTICE[3836]: app_mor.c:503 mor_authorize: Src: , Dst:
31455268146, Acc/dev_id: 3, CID:
[Nov 24 22:43:20] NOTICE[3836]: app_mor.c:2728 mor_get_user_by_acc: User's
data retrieved: id: 4, lcr_id: 2, balance: 0.000000, frozen_balance:
0.000000, credit: -1.000000, blocked: 0, lcr_order: price, tariff_id: 2,
postpaid: 1, cut: , add: , day type: WD, exchange rate: 1.000000, ani: 0,
tell balance: 0, time: 0, when left: 60s, every: 60s, user currency: USD,
def.curr: EUR, tariff type: user
[Nov 24 22:43:20] NOTICE[3836]: app_mor.c:546 mor_authorize: Caller type:
Local
[Nov 24 22:43:20] NOTICE[3836]: app_mor.c:558 mor_authorize: Localized
destination: 31455268146
[Nov 24 22:43:20] NOTICE[3836]: app_mor.c:2767 mor_check_did: Checking
DID...
[Nov 24 22:43:20] NOTICE[3836]: app_mor.c:2878 mor_check_did: DID status:
active, Provider rate 0.000000, con. fee: 0.000000, inc: 1, min time: 0,
prov.id: 3, Inc. rate 0.000000, con. fee: 0.000000, inc: 1, min time: 0,
Owner. rate 0.000000, con. fee: 0.000000, inc: 1, min time: 0, language:
en, dialplan id: 0
[Nov 24 22:43:20] NOTICE[3836]: app_mor.c:2884 mor_check_did: DID DEVICE
id: 195, type = FAX, extension: 1013, is trunk? 0, name: 1013, USER id: 36,
postpaid: 1, balance: -1222.362305, frz_balance: 0.000000, credit:
-1.000000, callflows: 0
[Nov 24 22:43:20] NOTICE[3836]: app_mor.c:728 mor_authorize: Timeout:
36000, user_id: 4, callertype: Local, anitype: , postpaid: 1
[Nov 24 22:43:20] NOTICE[3836]: app_mor.c:1681 mor_exec: Dial string using
DID: 'Local/1013 at mor/n||L(36000000:60000:60000)'
-- Limit Data for this call:
> timelimit = 36000000
> play_warning = 60000
> play_to_caller = yes
> play_to_callee = no
> warning_freq = 60000
> start_sound = (null)
> warning_sound = timeleft
> end_sound = (null)
[Nov 24 22:43:20] DEBUG[3836]: rtp.c:1585 ast_rtp_make_compatible: Channel
'Local/1013 at mor-b205,1' has no RTP, not doing anything
[Nov 24 22:43:20] DEBUG[3836]: channel.c:3338
ast_channel_inherit_variables: Copying soft-transferable variable
MOR_CALL_FROM_DID.
[Nov 24 22:43:20] DEBUG[3836]: channel.c:3351
ast_channel_inherit_variables: Not copying variable AGISTATUS.
[Nov 24 22:43:20] DEBUG[3836]: channel.c:3351
ast_channel_inherit_variables: Not copying variable mor_cid_name.
[Nov 24 22:43:20] DEBUG[3836]: channel.c:3351
ast_channel_inherit_variables: Not copying variable CALLEDTON.
[Nov 24 22:43:20] DEBUG[3836]: channel.c:3351
ast_channel_inherit_variables: Not copying variable ANI2.
[Nov 24 22:43:20] DEBUG[3836]: channel.c:3351
ast_channel_inherit_variables: Not copying variable TRANSFERCAPABILITY.
-- Called 1013 at mor/n
[Nov 24 22:43:20] DEBUG[3838]: pbx.c:1691
pbx_substitute_variables_helper_full: Function result is '0'
[Nov 24 22:43:20] DEBUG[3838]: pbx.c:1759
pbx_substitute_variables_helper_full: Expression result is '0'
-- Executing GotoIf("Local/1013 at mor-b205,2", "0?2:4")
-- Goto (mor,1013,4)
-- Executing Set("Local/1013 at mor-b205,2", "CALLED_TO=1013")
-- Executing Set("Local/1013 at mor-b205,2", "MOR_FAX_ID=195")
[Nov 24 22:43:20] DEBUG[3838]: pbx.c:1691
pbx_substitute_variables_helper_full: Function result is ''
-- Executing Set("Local/1013 at mor-b205,2", "FAXSENDER=")
-- Executing Goto("Local/1013 at mor-b205,2", "mor_fax2email|1013|1")
-- Goto (mor_fax2email,1013,1)
[Nov 24 22:43:20] DEBUG[3838]: pbx.c:1842 pbx_extension_helper: Launching
'Answer'
-- Executing [1013 at mor_fax2email:1] Answer("Local/1013 at mor-b205,2",
"") in new stack
[Nov 24 22:43:20] DEBUG[3838]: devicestate.c:302
ast_device_state_changed_literal: Notification of state change to be queued
on device/channel Local/1013 at mor
[Nov 24 22:43:20] DEBUG[3836]: devicestate.c:302
ast_device_state_changed_literal: Notification of state change to be queued
on device/channel Local/1013 at mor
-- Local/1013 at mor-b205,1 answered Zap/63-1
[Nov 24 22:43:20] DEBUG[3838]: pbx.c:1842 pbx_extension_helper: Launching
'StopPlayTones'
-- Executing [1013 at mor_fax2email:2]
StopPlayTones("Local/1013 at mor-b205,2", "") in new stack
[Nov 24 22:43:20] DEBUG[3804]: chan_local.c:145 local_devicestate:
Checking if extension 1013 at mor exists (devicestate)
[Nov 24 22:43:20] DEBUG[3836]: rtp.c:1502 ast_rtp_early_bridge: Channel
'Zap/63-1' has no RTP, not doing anything
[Nov 24 22:43:20] DEBUG[3838]: pbx.c:1842 pbx_extension_helper: Launching
'Playback'
-- Executing [1013 at mor_fax2email:3] Playback("Local/1013 at mor-b205,2",
"beep") in new stack
[Nov 24 22:43:20] DEBUG[3836]: devicestate.c:302
ast_device_state_changed_literal: Notification of state change to be queued
on device/channel Zap/63
[Nov 24 22:43:20] DEBUG[3836]: chan_dahdi.c:5154 dahdi_indicate: Requested
indication 20 on channel Zap/63-1
[Nov 24 22:43:20] DEBUG[3838]: channel.c:2843 set_format: Set channel
Local/1013 at mor-b205,2 to write format gsm
[Nov 24 22:43:20] DEBUG[3804]: devicestate.c:287 do_state_change: Changing
state for Local/1013 at mor - state 2 (In use)
[Nov 24 22:43:20] DEBUG[3804]: chan_local.c:145 local_devicestate:
Checking if extension 1013 at mor exists (devicestate)
[Nov 24 22:43:20] DEBUG[3838]: channel.c:1832 ast_settimeout: Scheduling
timer at 160 sample intervals
-- <Local/1013 at mor-b205,2> Playing 'beep' (language 'nl')
[Nov 24 22:43:20] DEBUG[3820]: app_queue.c:661 handle_statechange: Device
'Local/1013 at mor' changed to state '2' (In use) but we don't care because
they're not a member of any queue.
[Nov 24 22:43:20] DEBUG[3804]: devicestate.c:287 do_state_change: Changing
state for Local/1013 at mor - state 2 (In use)
[Nov 24 22:43:20] DEBUG[3804]: devicestate.c:287 do_state_change: Changing
state for Zap/63 - state 2 (In use)
[Nov 24 22:43:20] DEBUG[3820]: app_queue.c:661 handle_statechange: Device
'Local/1013 at mor' changed to state '2' (In use) but we don't care because
they're not a member of any queue.
[Nov 24 22:43:20] DEBUG[3820]: app_queue.c:661 handle_statechange: Device
'Zap/63' changed to state '2' (In use) but we don't care because they're
not a member of any queue.
[Nov 24 22:43:20] DEBUG[3838]: channel.c:1832 ast_settimeout: Scheduling
timer at 0 sample intervals
[Nov 24 22:43:20] DEBUG[3838]: channel.c:1832 ast_settimeout: Scheduling
timer at 0 sample intervals
[Nov 24 22:43:20] DEBUG[3838]: channel.c:2843 set_format: Set channel
Local/1013 at mor-b205,2 to write format alaw
[Nov 24 22:43:20] DEBUG[3838]: pbx.c:1691
pbx_substitute_variables_helper_full: Function result is '1227563000.5'
[Nov 24 22:43:20] DEBUG[3838]: pbx.c:1842 pbx_extension_helper: Launching
'Set'
-- Executing [1013 at mor_fax2email:4] Set("Local/1013 at mor-b205,2",
"FAXFILE=1227563000.5") in new stack
[Nov 24 22:43:20] DEBUG[3838]: pbx.c:1842 pbx_extension_helper: Launching
'Set'
-- Executing [1013 at mor_fax2email:5] Set("Local/1013 at mor-b205,2",
"FAX_DISABLE_V17=1") in new stack
[Nov 24 22:43:20] DEBUG[3838]: pbx.c:1842 pbx_extension_helper: Launching
'RxFax'
-- Executing [1013 at mor_fax2email:6] RxFax("Local/1013 at mor-b205,2",
"/var/spool/asterisk/faxes/1227563000.5.tif|ecm") in new stack
[Nov 24 22:43:20] DEBUG[3838]: channel.c:2843 set_format: Set channel
Local/1013 at mor-b205,2 to read format slin
[Nov 24 22:43:20] DEBUG[3838]: channel.c:2843 set_format: Set channel
Local/1013 at mor-b205,2 to write format slin
[Nov 24 22:43:20] DEBUG[3838]: /usr/src/agx-ast-addons/app_rxfax.c:384
rxfax_exec: Enabling ECM mode for app_rxfax
[Nov 24 22:43:21] DEBUG[3836]: chan_dahdi.c:3706 dahdi_handle_dtmfup: DTMF
digit: f on Zap/63-1
[Nov 24 22:43:21] DEBUG[3806]: chan_sip.c:2174 __sip_autodestruct: Auto
destroying SIP dialog '0zsm6q at london.domain.com'
[Nov 24 22:43:21] DEBUG[3806]: chan_sip.c:3434 sip_destroy: Destroying SIP
dialog 0zsm6q at london.domain.com
Really destroying SIP dialog '0zsm6q at london.domain.com' Method: OPTIONS
[Nov 24 22:43:47] DEBUG[3828]: channel.c:1088 channel_find_locked:
Avoiding deadlock for channel '0x82d4660'
Issue History
Date Modified Username Field Change
======================================================================
2008-11-24 15:50 kreijnen Note Added: 0095428
======================================================================
More information about the asterisk-bugs
mailing list