Ok i've finally a trace and after spent 1 day monitoring the PBX i
found a timeslice where the problem happened cleanly.
Current customer platform stack is:
- Asterisk 1.2.13
- chan_misdn 0.3.1-rc26
- mISDN 1.0.4
- mISDN-user 1.0.3
- module loaded: mISDN_core 78528 6
mISDN_dsp,hfcpci,mISDN_capi,l3udss1,mISDN_l2,mISDN_l1
- linux 2.6.17.4
cat /proc/interrupts
CPU0
0: 211192736 local-APIC-edge timer
1: 8 IO-APIC-edge i8042
8: 865022423 IO-APIC-edge rtc
14: 357293 IO-APIC-edge ide0
169: 17363606 IO-APIC-level acpi, eth0
177: 11193820 IO-APIC-level HFC PCI
185: 0 IO-APIC-level libata
193: 0 IO-APIC-level libata
201: 0 IO-APIC-level ehci_hcd:usb1, ohci_hcd:usb2,
ohci_hcd:usb3
NMI: 0
LOC: 208601360
ERR: 0
MIS: 0
Problem summary: when the customer answer a 2nd call from ISDN the 1st
call is hanged up.
Customer only uses ISDN (no VOIP trunks). Customer didn't have the
problem if i use ZAPHFC bristuffed driver.
I extracted asterisk-debug log and misdn debug log, normalized them at
the same format and merged them with
sort -k 1 -k 2 -k 3 --merge file1 file2 so for the same second you can
see more-or-less the same lines.
------------------------------------------------------------------------
Customer has 1 outgoing call (SIP/31 is a FAX connected to Linksys ATA):
Jan 19 09:23:52 VERBOSE[30645] logger.c: -- mISDN/1-u5 answered
SIP/31-0820bdf8
We call customer to test it:
Jan 19 09:24:11 2007: P[ 1] set_channel: bc->channel:0 channel:0
Jan 19 09:24:11 2007: P[ 1] I IND :SETUP oad:<our_number>
dad:<customer_number> pid:12 state:none
Jan 19 09:24:11 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:24:11 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:24:11 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
Jan 19 09:24:11 2007: P[ 1] --> Bearer: Speech
Jan 19 09:24:11 2007: P[ 1] --> Codec: Alaw
Jan 19 09:24:11 2007: P[ 0] --> * NEW CHANNEL dad:<customer_number>
oad:<our_number>
Jan 19 09:24:11 2007: P[ 1] --> CTON: Unknown
Jan 19 09:24:11 2007: P[ 1] EXPORT_PID: pid:12
Jan 19 09:24:11 2007: P[ 1] --> PRES: Restricted (0)
Jan 19 09:24:11 2007: P[ 1] --> SCREEN: Unscreened (0)
Jan 19 09:24:11 2007: P[ 1] I SEND:PROCEEDING oad:0<our_number>
dad:0<customer_number> pid:12
Jan 19 09:24:11 2007: P[ 1] --> bc_state:BCHAN_CLEANED
Jan 19 09:24:11 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:24:11 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:24:11 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
Jan 19 09:24:11 2007: P[ 1] * IND : Indication [3] from s
Jan 19 09:24:11 2007: P[ 1] --> * IND : ringing pid:12
Jan 19 09:24:11 2007: P[ 1] I SEND:ALERTING oad:0<our_number>
dad:0<customer_number> pid:12
Jan 19 09:24:11 2007: P[ 1] --> bc_state:BCHAN_CLEANED
Jan 19 09:24:11 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:24:11 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:24:11 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
Jan 19 09:24:11 2007: P[ 1] --> * SEND: State Ring pid:12
Jan 19 09:24:11 2007: P[ 1] --> incoming_early_audio off
Our call start ringing local phones:
Jan 19 09:24:11 VERBOSE[30673] logger.c: -- Executing SIPAddHeader("mISDN/1-u6",
"Alert-Info: <Mercurius>;info=external") in new stack
Jan 19 09:24:11 VERBOSE[30673] logger.c: -- AGI Script Executing Application:
(Dial) Options: (SIP/22&SIP/21&SIP/20|45|tTrR)
Jan 19 09:24:12 VERBOSE[30673] logger.c: -- SIP/21-081ef140 is ringing
Jan 19 09:24:12 VERBOSE[30673] logger.c: -- SIP/22-081daf50 is ringing
Jan 19 09:24:12 VERBOSE[30673] logger.c: -- SIP/20-08214e70 is ringing
Jan 19 09:24:20 2007: P[ 1] * IND : Indication [-1] from s
Jan 19 09:24:20 2007: P[ 1] --> * IND : -1! (stop indication) pid:12
Jan 19 09:24:20 2007: P[ 1] --> None
Jan 19 09:24:20 2007: P[ 1] * ANSWER:
Jan 19 09:24:20 2007: P[ 1] --> Connection is without BF encryption
Jan 19 09:24:20 2007: P[ 1] --> ECHO OFF
Jan 19 09:24:20 2007: P[ 1] --> None
Jan 19 09:24:20 2007: P[ 1] --> empty cad using dad
Jan 19 09:24:20 2007: P[ 1] I SEND:CONNECT oad:0<our_number>
dad:0<customer_number> pid:12
Jan 19 09:24:20 2007: P[ 1] --> bc_state:BCHAN_CLEANED
Jan 19 09:24:20 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad:
cad:0<customer_number>
Jan 19 09:24:20 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:24:20 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
Jan 19 09:24:20 2007: P[ 1] --> TRANSPARENT Mode
Jan 19 09:24:20 DEBUG[28281] chan_sip.c: build_route: Contact hop: <sip:[EMAIL
PROTECTED]:5060;user=phone>
Jan 19 09:24:20 DEBUG[28269] channel.c: Avoiding initial deadlock for
'SIP/21-081ef140'
Ok our call is answered:
Jan 19 09:24:20 VERBOSE[30673] logger.c: -- SIP/21-081ef140 answered
mISDN/1-u6
Jan 19 09:24:20 VERBOSE[28269] logger.c: Extension Changed 21 new state InUse
for Notify User 21
Jan 19 09:24:20 VERBOSE[28269] logger.c: Extension Changed 20 new state Idle
for Notify User 21
Jan 19 09:24:20 VERBOSE[28269] logger.c: Extension Changed 22 new state Idle
for Notify User 21
We call the customer to trying estabilish a 2nd call
What is this?
Jan 19 09:24:25 2007: P[ 1] $$$ Set StackIND Err: -1 Illegal seek
Jan 19 09:24:25 2007: P[ 1] I IND :BCHAN_ERROR oad:0<our_number>
dad:0<customer_number> pid:12 state:CONNECTED
Jan 19 09:24:25 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad:
cad:0<customer_number>
Jan 19 09:24:25 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:24:25 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
Jan 19 09:24:25 2007: P[ 1] hangup_chan
Jan 19 09:24:25 2007: P[ 1] -> queue_hangup
Jan 19 09:24:25 2007: P[ 1] release_chan: bc with l3id: 20007
Jan 19 09:24:25 2007: P[ 1] * RELEASING CHANNEL pid:12 ctx:macro-dialgroup dad:s
oad:0<our_number> state: CONNECTED
Jan 19 09:24:25 2007: P[ 1] --> * State Down
Jan 19 09:24:25 2007: P[ 1] --> Setting AST State to down
Jan 19 09:24:25 2007: P[ 1] send_event: setup_bc failed
Jan 19 09:24:25 2007: P[ 1] ec_enable
Jan 19 09:24:25 2007: P[ 1] Sending Control ECHOCAN_ON taps:32 training:0
Jan 19 09:24:25 2007: P[ 1] BCHAN: MGR_DELLAYER|CNF pid:11
Jan 19 09:24:25 2007: P[ 0] handle_bchan: BC not found for prim:120282 with
addr:52010101 dinfo:ffffffff
Jan 19 09:24:25 2007: P[ 0] handle_bchan: BC not found for prim:120282 with
addr:52010101 dinfo:ffffffff
Jan 19 09:24:25 2007: P[ 0] handle_bchan: BC not found for prim:120282 with
addr:52010101 dinfo:ffffffff
Jan 19 09:24:25 2007: P[ 0] handle_bchan: BC not found for prim:120282 with
addr:52010101 dinfo:ffffffff
Jan 19 09:24:25 2007: P[ 1] $$$ CLEANUP CALLED pid:12
Jan 19 09:24:25 2007: P[ 1] $$$ Cleaning up bc with stid :10010100 pid:12
Jan 19 09:24:25 2007: P[ 1] ec_disable
Jan 19 09:24:25 2007: P[ 1] Sending Control ECHOCAN_OFF
Jan 19 09:24:25 2007: P[ 1] I IND :RELEASE oad: dad: pid:12 state:none
Jan 19 09:24:25 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:24:25 2007: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0
cpnnumplan:0
Jan 19 09:24:25 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:0
Jan 19 09:24:25 2007: P[ 1] Chan not existing at the moment bc->l3id:20007
bc:0x817aff4 event:RELEASE port:1 channel:0
Jan 19 09:24:25 2007: P[ 1] $$$ CLEANUP CALLED pid:12
Jan 19 09:24:25 2007: P[ 0] handle_bchan: BC not found for prim:f2481 with
addr:55010181 dinfo:0
Jan 19 09:24:25 2007: P[ 0] MGMT: DELLAYER|CONFIRM Addr: 55010181 !
47 of those lines:
Jan 19 09:24:25 2007: P[ 0] handle_bchan: BC not found for prim:120282 with
addr:52010101 dinfo:ffffffff
Uhm... our 1st call is misteriously hanged up:
Jan 19 09:24:25 WARNING[30673] res_features.c: Bridge failed on channels
mISDN/1-u6 and SIP/21-081ef140
Jan 19 09:24:25 DEBUG[30673] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Jan 19 09:24:25 DEBUG[30673] res_agi.c: mISDN/1-u6 hungup
Jan 19 09:24:25 VERBOSE[30673] logger.c: == Spawn extension (macro-dialgroup,
s, 4) exited non-zero on 'mISDN/1-u6' in macro 'dialgroup'
Jan 19 09:24:25 VERBOSE[30673] logger.c: == Spawn extension (macro-dialgroup,
s, 4) exited non-zero on 'mISDN/1-u6'
Jan 19 09:24:25 DEBUG[28269] channel.c: Avoiding initial deadlock for
'mISDN/1-u6'
Jan 19 09:24:25 DEBUG[28269] channel.c: Avoiding initial deadlock for
'mISDN/1-u6'
Jan 19 09:24:25 DEBUG[28269] channel.c: Avoiding initial deadlock for
'mISDN/1-u6'
Jan 19 09:24:25 DEBUG[30673] cdr_addon_mysql.c: cdr_mysql: inserting a CDR
record.
Jan 19 09:24:25 DEBUG[30673] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield)
VALUES ('2007-01-19 09:24:11','\"0<our_number>\"
<0<our_number>>','0<our_number>','100','local',
'mISDN/1-u6','SIP/21-081ef140','Dial','SIP/22&SIP/21&SIP/20|45|tTrR',14,0,'ANSWERED',3,'','1169195051.32','')
Jan 19 09:24:25 DEBUG[30673] chan_misdn.c: misdn_hangup(mISDN/1-u6)
Jan 19 09:24:25 VERBOSE[28269] logger.c: Extension Changed 21 new state Idle
for Notify User 21
40 of those lines repeated:
Jan 19 09:24:26 2007: P[ 0] handle_bchan: BC not found for prim:120282 with
addr:52010101 dinfo:ffffffff
Jan 19 09:24:26 2007: P[ 1] set_channel: bc->channel:0 channel:0
This is us trying to estabisligh a 2nd concurrent call with the customer:
Jan 19 09:24:26 2007: P[ 1] I IND :SETUP oad:<our_number>
dad:<customer_number> pid:13 state:none
Jan 19 09:24:26 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:24:26 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:24:26 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
Jan 19 09:24:26 2007: P[ 1] --> Bearer: Speech
Jan 19 09:24:26 2007: P[ 1] --> Codec: Alaw
Jan 19 09:24:26 2007: P[ 0] --> * NEW CHANNEL dad:<customer_number>
oad:<our_number>
Jan 19 09:24:26 2007: P[ 1] --> CTON: Unknown
Jan 19 09:24:26 2007: P[ 1] EXPORT_PID: pid:13
Jan 19 09:24:26 2007: P[ 1] --> PRES: Restricted (0)
Jan 19 09:24:26 2007: P[ 1] --> SCREEN: Unscreened (0)
Jan 19 09:24:26 2007: P[ 1] I SEND:PROCEEDING oad:0<our_number>
dad:0<customer_number> pid:13
Jan 19 09:24:26 2007: P[ 1] --> bc_state:BCHAN_CLEANED
Jan 19 09:24:26 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:24:26 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:24:26 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
10 of those lines:
Jan 19 09:24:26 2007: P[ 0] handle_bchan: BC not found for prim:120282 with
addr:52010101 dinfo:ffffffff
Jan 19 09:24:26 2007: P[ 1] * IND : Indication [3] from s
Jan 19 09:24:26 2007: P[ 1] --> * IND : ringing pid:13
Jan 19 09:24:26 2007: P[ 1] I SEND:ALERTING oad:0<our_number>
dad:0<customer_number> pid:13
Jan 19 09:24:26 2007: P[ 1] --> bc_state:BCHAN_CLEANED
Jan 19 09:24:26 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:24:26 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:24:26 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
Jan 19 09:24:26 2007: P[ 1] --> * SEND: State Ring pid:13
Jan 19 09:24:26 2007: P[ 1] --> incoming_early_audio off
10 of those lines:
Jan 19 09:24:26 2007: P[ 0] handle_bchan: BC not found for prim:120282 with
addr:52010101 dinfo:ffffffff
My 2nd call is ringing:
Jan 19 09:24:26 VERBOSE[30695] logger.c: -- AGI Script Executing Application:
(Dial) Options: (SIP/22&SIP/21&SIP/20|45|tTrR)
Jan 19 09:24:26 VERBOSE[30695] logger.c: -- SIP/21-081ef140 is ringing
Jan 19 09:24:26 VERBOSE[30695] logger.c: -- SIP/22-081dbef8 is ringing
Jan 19 09:24:26 VERBOSE[30695] logger.c: -- SIP/20-08214e70 is ringing
340 of those lines:
Jan 19 09:24:32 2007: P[ 0] handle_bchan: BC not found for prim:120282 with
addr:52010101 dinfo:ffffffff
Seems customer FAX SIP/31 has hungup up too
Jan 19 09:24:32 2007: P[ 0] handle_bchan: BC not found for prim:120282 with
addr:52010101 dinfo:ffffffff
Jan 19 09:24:32 2007: P[ 1] I IND :DISCONNECT oad:31 dad:0376221223 pid:0
state:CONNECTED
Jan 19 09:24:32 2007: P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad:
cad:376221223
Jan 19 09:24:32 2007: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0
cpnnumplan:2
Jan 19 09:24:32 2007: P[ 1] --> caps:Speech pi:8 keypad: sending_complete:0
Jan 19 09:24:32 2007: P[ 1] --> org:1 nt:0, inbandavail:1 state:10
Jan 19 09:24:32 2007: P[ 1] hangup_chan
Jan 19 09:24:32 2007: P[ 1] -> queue_hangup
Jan 19 09:24:32 2007: P[ 1] I SEND:RELEASE oad:31 dad:0376221223 pid:0
Jan 19 09:24:32 2007: P[ 1] --> bc_state:BCHAN_ACTIVATED
Jan 19 09:24:32 2007: P[ 1] --> channel:1 mode:TE cause:16 ocause:-1 rad:
cad:376221223
Jan 19 09:24:32 2007: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0
cpnnumplan:2
Jan 19 09:24:32 2007: P[ 1] --> caps:Speech pi:8 keypad: sending_complete:0
Jan 19 09:24:32 2007: P[ 1] * IND : HANGUP pid:0 ctx:from-trunk-misdn-1
dad:0376221223 oad:0376221223 State:CONNECTED
Jan 19 09:24:32 2007: P[ 1] --> l3id:30004
Jan 19 09:24:32 2007: P[ 1] --> cause:16
Jan 19 09:24:32 2007: P[ 1] --> out_cause:16
Jan 19 09:24:32 2007: P[ 1] --> state:CONNECTED
Jan 19 09:24:32 2007: P[ 1] Channel: mISDN/1-u5 hanguped new state:CLEANING
Asterisk completing FAX hangup:
Jan 19 09:24:32 2007: P[ 0] handle_bchan: BC not found for prim:120282 with
addr:52010101 dinfo:ffffffff
Jan 19 09:24:32 2007: P[ 0] handle_bchan: BC not found for prim:120282 with
addr:52010101 dinfo:ffffffff
Jan 19 09:24:32 2007: P[ 0] handle_bchan: BC not found for prim:120282 with
addr:52010101 dinfo:ffffffff
Jan 19 09:24:32 2007: P[ 0] handle_bchan: BC not found for prim:120282 with
addr:52010101 dinfo:ffffffff
Jan 19 09:24:32 2007: P[ 0] handle_bchan: BC not found for prim:120282 with
addr:52010101 dinfo:ffffffff
Jan 19 09:24:32 2007: P[ 1] $$$ CLEANUP CALLED pid:0
Jan 19 09:24:32 2007: P[ 1] $$$ Cleaning up bc with stid :10010100 pid:0
Jan 19 09:24:32 2007: P[ 1] ec_disable
Jan 19 09:24:32 2007: P[ 1] Sending Control ECHOCAN_OFF
Jan 19 09:24:32 2007: P[ 1] I IND :RELEASE_COMPLETE oad: dad: pid:0
state:CLEANING
Jan 19 09:24:32 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:24:32 2007: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0
cpnnumplan:0
Jan 19 09:24:32 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:0
Jan 19 09:24:32 2007: P[ 1] ast_hangup already called, so we have no ast ptr
anymore in event(RELEASE_COMPLETE)
Jan 19 09:24:32 2007: P[ 1] hangup_chan
Jan 19 09:24:32 2007: P[ 1] No need to queue hangup
Jan 19 09:24:32 2007: P[ 1] Cannot hangup chan, no ast
Jan 19 09:24:32 2007: P[ 1] release_chan: bc with l3id: 30004
Jan 19 09:24:32 2007: P[ 0] Unhandled Message: prim 20081 len -22 from addr
1000000, dinfo 0 on this port.
Jan 19 09:24:32 2007: P[ 0] handle_bchan: BC not found for prim:f2481 with
addr:55010180 dinfo:0
Jan 19 09:24:32 2007: P[ 0] MGMT: DELLAYER|CONFIRM Addr: 55010180 !
Jan 19 09:24:32 DEBUG[30645] channel.c: Didn't get a frame from channel:
mISDN/1-u5
Jan 19 09:24:32 DEBUG[30645] channel.c: Bridge stops bridging channels
SIP/31-0820bdf8 and mISDN/1-u5
Jan 19 09:24:32 DEBUG[30645] chan_misdn.c: misdn_hangup(mISDN/1-u5)
Jan 19 09:24:32 DEBUG[30645] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Jan 19 09:24:32 VERBOSE[30645] logger.c: == Spawn extension (macro-dialtrunk,
s, 15) exited non-zero on 'SIP/31-0820bdf8' in macro 'dialtrunk'
Jan 19 09:24:32 VERBOSE[30645] logger.c: == Spawn extension (macro-dialtrunk,
s, 15) exited non-zero on 'SIP/31-0820bdf8' in macro 'outgoing-99'
Jan 19 09:24:32 VERBOSE[30645] logger.c: == Spawn extension (macro-dialtrunk,
s, 15) exited non-zero on 'SIP/31-0820bdf8'
Jan 19 09:24:32 DEBUG[30645] cdr_addon_mysql.c: cdr_mysql: inserting a CDR
record.
Jan 19 09:24:32 DEBUG[30645] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO
cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield)
VALUES ('2007-01-19 09:23:42','\"FAX vecchio\"
<31>','31','0376221223','interni',
'SIP/31-0820bdf8','mISDN/1-u5','Dial','mISDN/g:card1/0376221223|120|tTwWR',50,40,'ANSWERED',3,'','1169195022.30','CHANUNAVAIL')
Ok, pid:13 is our 2nd call to the customer PBX:
NOTE: i never was able to talk with the customer using this 2nd call
Jan 19 09:24:34 2007: P[ 1] * IND : Indication [-1] from s
Jan 19 09:24:34 2007: P[ 1] --> * IND : -1! (stop indication) pid:13
Jan 19 09:24:34 2007: P[ 1] --> None
Jan 19 09:24:34 2007: P[ 1] * ANSWER:
Jan 19 09:24:34 2007: P[ 1] --> Connection is without BF encryption
Jan 19 09:24:34 2007: P[ 1] --> ECHO OFF
Jan 19 09:24:34 2007: P[ 1] --> None
Jan 19 09:24:34 2007: P[ 1] --> empty cad using dad
Jan 19 09:24:34 2007: P[ 1] I SEND:CONNECT oad:0<our_number>
dad:0<customer_number> pid:13
Jan 19 09:24:34 2007: P[ 1] --> bc_state:BCHAN_CLEANED
Jan 19 09:24:34 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad:
cad:0<customer_number>
Jan 19 09:24:34 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:24:34 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
Jan 19 09:24:34 2007: P[ 1] --> TRANSPARENT Mode
Jan 19 09:24:34 2007: P[ 1] bchan: DL_ESTABLISH|CNF
Jan 19 09:24:34 2007: P[ 1] ec_enable
Jan 19 09:24:34 2007: P[ 1] Sending Control ECHOCAN_ON taps:32 training:0
Jan 19 09:24:34 2007: P[ 1] $$$ CLEANUP CALLED pid:13
Jan 19 09:24:34 2007: P[ 1] $$$ Cleaning up bc with stid :10010100 pid:13
Jan 19 09:24:34 2007: P[ 1] ec_disable
Jan 19 09:24:34 2007: P[ 1] Sending Control ECHOCAN_OFF
Jan 19 09:24:34 2007: P[ 1] I IND :RELEASE oad: dad: pid:13 state:CONNECTED
Jan 19 09:24:34 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:24:34 2007: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0
cpnnumplan:0
Jan 19 09:24:34 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:0
Jan 19 09:24:34 2007: P[ 1] hangup_chan
Jan 19 09:24:34 2007: P[ 1] -> queue_hangup
Jan 19 09:24:34 2007: P[ 1] release_chan: bc with l3id: 20008
Jan 19 09:24:34 2007: P[ 1] * RELEASING CHANNEL pid:13 ctx:macro-dialgroup dad:s
oad:0<our_number> state: CONNECTED
Jan 19 09:24:34 2007: P[ 1] --> * State Down
Jan 19 09:24:34 2007: P[ 1] --> Setting AST State to down
Jan 19 09:24:34 2007: P[ 1] I SEND:RELEASE_COMPLETE oad: dad: pid:13
Jan 19 09:24:34 2007: P[ 1] --> bc_state:BCHAN_CLEANED
Jan 19 09:24:34 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:24:34 2007: P[ 1] --> info_dad: onumplan:0 dnumplan:0 rnumplan:0
cpnnumplan:0
Jan 19 09:24:34 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:0
Jan 19 09:24:34 2007: P[ 1] BCHAN: DeACT Conf pid:13
Jan 19 09:24:34 2007: P[ 1] BCHAN: MGR_DELLAYER|CNF pid:13
Jan 19 09:24:34 DEBUG[28281] chan_sip.c: build_route: Contact hop: <sip:[EMAIL
PROTECTED]:5060;user=phone>
Jan 19 09:24:34 DEBUG[28269] channel.c: Avoiding initial deadlock for
'SIP/21-081ef140'
Jan 19 09:24:34 VERBOSE[30695] logger.c: -- SIP/21-081ef140 answered
mISDN/1-u7
Jan 19 09:24:34 VERBOSE[28269] logger.c: Extension Changed 21 new state InUse
for Notify User 21
Jan 19 09:24:34 VERBOSE[28269] logger.c: Extension Changed 20 new state Idle
for Notify User 21
Jan 19 09:24:34 VERBOSE[28269] logger.c: Extension Changed 22 new state Idle
for Notify User 21
Jan 19 09:24:34 DEBUG[28269] channel.c: Avoiding initial deadlock for
'mISDN/1-u7'
Jan 19 09:24:34 DEBUG[30695] channel.c: Bridge stops because we're zombie or
need a soft hangup: c0=mISDN/1-u7, c1=SIP/21-081ef140, flags: No,Yes,No,No
Jan 19 09:24:34 DEBUG[30695] channel.c: Bridge stops bridging channels
mISDN/1-u7 and SIP/21-081ef140
Jan 19 09:24:34 VERBOSE[28269] logger.c: Extension Changed 21 new state Idle
for Notify User 21
Jan 19 09:24:34 DEBUG[30695] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Jan 19 09:24:34 DEBUG[30695] res_agi.c: mISDN/1-u7 hungup
Jan 19 09:24:34 VERBOSE[30695] logger.c: == Spawn extension (macro-dialgroup,
s, 4) exited non-zero on 'mISDN/1-u7' in macro 'dialgroup'
Jan 19 09:24:34 VERBOSE[30695] logger.c: == Spawn extension (macro-dialgroup,
s, 4) exited non-zero on 'mISDN/1-u7'
Jan 19 09:24:34 DEBUG[30695] cdr_addon_mysql.c: cdr_mysql: inserting a CDR
record.
Jan 19 09:24:34 DEBUG[30695] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield)
VALUES ('2007-01-19 09:24:26','\"0<our_number>\"
<0<our_number>>','0<our_number>','100','local',
'mISDN/1-u7','SIP/21-081ef140','Dial','SIP/22&SIP/21&SIP/20|45|tTrR',8,0,'ANSWERED',3,'','1169195066.36','')
Jan 19 09:24:34 DEBUG[30695] chan_misdn.c: misdn_hangup(mISDN/1-u7)
That's very strange we didn't recalled the customer
but seem our VOIP provider is trying to call it!!!
Jan 19 09:24:35 2007: P[ 1] set_channel: bc->channel:0 channel:1
Jan 19 09:24:36 2007: P[ 1] I IND :SETUP oad:341423318 dad:<customer_number>
pid:14 state:none
Jan 19 09:24:36 2007: P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:24:36 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:24:36 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
Jan 19 09:24:36 2007: P[ 1] --> Bearer: Speech
Jan 19 09:24:36 2007: P[ 1] --> Codec: Alaw
Jan 19 09:24:36 2007: P[ 0] --> * NEW CHANNEL dad:<customer_number>
oad:341423318
Jan 19 09:24:36 2007: P[ 1] --> CTON: Unknown
Jan 19 09:24:36 2007: P[ 1] EXPORT_PID: pid:14
Jan 19 09:24:36 2007: P[ 1] --> PRES: Restricted (0)
Jan 19 09:24:36 2007: P[ 1] --> SCREEN: Unscreened (0)
Jan 19 09:24:36 2007: P[ 1] I SEND:PROCEEDING oad:0341423318
dad:0<customer_number> pid:14
Jan 19 09:24:36 2007: P[ 1] --> bc_state:BCHAN_CLEANED
Jan 19 09:24:36 2007: P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:24:36 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:24:36 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
Jan 19 09:24:36 2007: P[ 1] * IND : Indication [3] from s
Jan 19 09:24:36 2007: P[ 1] --> * IND : ringing pid:14
Jan 19 09:24:36 2007: P[ 1] I SEND:ALERTING oad:0341423318
dad:0<customer_number> pid:14
Jan 19 09:24:36 2007: P[ 1] --> bc_state:BCHAN_CLEANED
Jan 19 09:24:36 2007: P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:24:36 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:24:36 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
Jan 19 09:24:36 2007: P[ 1] --> * SEND: State Ring pid:14
Jan 19 09:24:36 2007: P[ 1] --> incoming_early_audio off
Jan 19 09:24:40 2007: P[ 1] * IND : Indication [-1] from s
Jan 19 09:24:40 2007: P[ 1] --> * IND : -1! (stop indication) pid:14
Jan 19 09:24:40 2007: P[ 1] --> None
Jan 19 09:24:40 2007: P[ 1] * ANSWER:
Jan 19 09:24:40 2007: P[ 1] --> Connection is without BF encryption
Jan 19 09:24:40 2007: P[ 1] --> ECHO OFF
Jan 19 09:24:40 2007: P[ 1] --> None
Jan 19 09:24:40 2007: P[ 1] --> empty cad using dad
Jan 19 09:24:40 2007: P[ 1] I SEND:CONNECT oad:0341423318
dad:0<customer_number> pid:14
Jan 19 09:24:40 2007: P[ 1] --> bc_state:BCHAN_CLEANED
Jan 19 09:24:40 2007: P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad:
cad:0<customer_number>
Jan 19 09:24:40 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:24:40 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
Jan 19 09:24:40 2007: P[ 1] --> TRANSPARENT Mode
Jan 19 09:24:40 2007: P[ 1] bchan: DL_ESTABLISH|CNF
Jan 19 09:24:40 2007: P[ 1] ec_enable
Jan 19 09:24:40 2007: P[ 1] Sending Control ECHOCAN_ON taps:32 training:0
Jan 19 09:24:40 2007: P[ 1] I IND :CONNECT_ACKNOWLEDGE oad:0341423318
dad:0<customer_number> pid:14 state:CONNECTED
Jan 19 09:24:40 2007: P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad:
cad:0<customer_number>
Jan 19 09:24:40 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:24:40 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
Jan 19 09:24:40 DEBUG[28281] chan_sip.c: build_route: Contact hop: <sip:[EMAIL
PROTECTED]:5060;user=phone>
Jan 19 09:24:40 DEBUG[28269] channel.c: Avoiding initial deadlock for
'SIP/20-08209aa0'
Jan 19 09:24:40 VERBOSE[30766] logger.c: -- SIP/20-08209aa0 answered
mISDN/1-1
Jan 19 09:24:40 VERBOSE[28269] logger.c: Extension Changed 20 new state InUse
for Notify User 21
Jan 19 09:24:40 VERBOSE[28269] logger.c: Extension Changed 21 new state Idle
for Notify User 21
Jan 19 09:24:40 VERBOSE[28269] logger.c: Extension Changed 22 new state Idle
for Notify User 21
Jan 19 09:24:40 DEBUG[28269] channel.c: Avoiding initial deadlock for
'mISDN/1-1'
Jan 19 09:24:40 DEBUG[30766] channel.c: Dropping duplicate answer!
Jan 19 09:25:03 VERBOSE[28281] logger.c: -- Started music on hold, class
'default', on channel 'mISDN/1-1'
Jan 19 09:25:03 DEBUG[28281] channel.c: Scheduling timer at 160 sample intervals
Jan 19 09:25:03 DEBUG[30766] channel.c: Generator got voice, switching to phase
locked mode
Jan 19 09:25:03 DEBUG[30766] channel.c: Scheduling timer at 0 sample intervals
Jan 19 09:25:08 DEBUG[28281] chan_sip.c: Checking SIP call limits for device 20
Jan 19 09:25:08 DEBUG[28281] chan_sip.c: build_route: Contact hop: <sip:[EMAIL
PROTECTED]:5060;user=phone>
Here we go again: we didn't called the customer!
Jan 19 09:25:48 2007: P[ 1] set_channel: bc->channel:0 channel:0
Jan 19 09:25:48 2007: P[ 1] I IND :SETUP oad:<our_number>
dad:<customer_number> pid:15 state:none
Jan 19 09:25:48 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:25:48 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:25:48 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
Jan 19 09:25:48 2007: P[ 1] --> Bearer: Speech
Jan 19 09:25:48 2007: P[ 1] --> Codec: Alaw
Jan 19 09:25:48 2007: P[ 0] --> * NEW CHANNEL dad:<customer_number>
oad:<our_number>
Jan 19 09:25:48 2007: P[ 1] --> CTON: Unknown
Jan 19 09:25:48 2007: P[ 1] EXPORT_PID: pid:15
Jan 19 09:25:49 2007: P[ 1] --> PRES: Restricted (0)
Jan 19 09:25:49 2007: P[ 1] --> SCREEN: Unscreened (0)
Jan 19 09:25:49 2007: P[ 1] I SEND:PROCEEDING oad:0<our_number>
dad:0<customer_number> pid:15
Jan 19 09:25:49 2007: P[ 1] --> bc_state:BCHAN_CLEANED
Jan 19 09:25:49 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:25:49 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:25:49 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
Jan 19 09:25:49 2007: P[ 1] * IND : Indication [3] from s
Jan 19 09:25:49 2007: P[ 1] --> * IND : ringing pid:15
Jan 19 09:25:49 2007: P[ 1] I SEND:ALERTING oad:0<our_number>
dad:0<customer_number> pid:15
Jan 19 09:25:49 2007: P[ 1] --> bc_state:BCHAN_CLEANED
Jan 19 09:25:49 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:25:49 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:25:49 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
Jan 19 09:25:49 2007: P[ 1] --> * SEND: State Ring pid:15
Jan 19 09:25:49 2007: P[ 1] --> incoming_early_audio off
And again:
Jan 19 09:26:05 2007: P[ 1] set_channel: bc->channel:0 channel:0
Jan 19 09:26:05 2007: P[ 1] I IND :SETUP oad:<our_number>
dad:<customer_number> pid:16 state:none
Jan 19 09:26:05 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:26:05 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:26:05 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
Jan 19 09:26:05 2007: P[ 1] --> Bearer: Speech
Jan 19 09:26:05 2007: P[ 1] --> Codec: Alaw
Jan 19 09:26:05 2007: P[ 0] --> * NEW CHANNEL dad:<customer_number>
oad:<our_number>
Jan 19 09:26:05 2007: P[ 1] --> CTON: Unknown
Jan 19 09:26:05 2007: P[ 1] EXPORT_PID: pid:16
Jan 19 09:26:05 2007: P[ 1] --> PRES: Restricted (0)
Jan 19 09:26:05 2007: P[ 1] --> SCREEN: Unscreened (0)
Jan 19 09:26:05 2007: P[ 1] I SEND:PROCEEDING oad:0<our_number>
dad:0<customer_number> pid:16
Jan 19 09:26:05 2007: P[ 1] --> bc_state:BCHAN_CLEANED
Jan 19 09:26:05 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:26:05 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:26:05 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
15 of those lines:
Jan 19 09:26:05 2007: P[ 0] handle_bchan: BC not found for prim:120282 with
addr:52010101 dinfo:ffffffff
Jan 19 09:26:05 2007: P[ 1] * IND : Indication [3] from s
Jan 19 09:26:05 2007: P[ 1] --> * IND : ringing pid:16
Jan 19 09:26:05 2007: P[ 1] I SEND:ALERTING oad:0<our_number>
dad:0<customer_number> pid:16
Jan 19 09:26:05 2007: P[ 1] --> bc_state:BCHAN_CLEANED
Jan 19 09:26:05 2007: P[ 1] --> channel:0 mode:TE cause:16 ocause:16 rad: cad:
Jan 19 09:26:05 2007: P[ 1] --> info_dad: onumplan:2 dnumplan:2 rnumplan:
cpnnumplan:0
Jan 19 09:26:05 2007: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1
Jan 19 09:26:05 2007: P[ 1] --> * SEND: State Ring pid:16
Jan 19 09:26:05 2007: P[ 1] --> incoming_early_audio of
30 of those lines:
Jan 19 09:26:05 2007: P[ 0] handle_bchan: BC not found for prim:120282 with
addr:52010101 dinfo:ffffffff
------------------------------------------------------------------------
_______________________________________________
Misdn-asterisk mailing list
[email protected]
http://lists.beronet.com/cgi-bin/mailman/listinfo/misdn-asterisk
