Olivier Fauchon
2008-Nov-05 21:20 UTC
[asterisk-users] b410p mIDSN - RNIS signaling problems
Hi. I'm running Asterisk server with 10 sip phones, and 2 grouped T0 lines with 10 DDI numbers. My provider is France Telecom and my setup is : - Debian Lenny - Asterisk 1.4 - Linux kernel 2.6.25.17 - mISDN 1.1.8 driver - Sip phones Thomson ST2030 No problem with the SIP . But when reveiving a call on RNIS line (any of the DDI numbers), the associated SIP phone rings indicating _two_ incoming calls ! Turning on misdn debuging seems to indicate there are _2 identical incoming calls_ on 2 ports at the same time (See the log below) It' now many days I'm looking for an answer, I really need help ! Thx * /etc/asterisk/misdn.conf [general] debug=0 method=standard append_digits2exten=yes bridging=yes bridging=no language=fr echocancel=yes echotraining=yes jitterbuffer=4000 jitterbuffer_upper_threshold=0 use_callingpres=yes presentation=allowed [default] context=numeris language=fr nationalprefix=0 internationalprefix=00 rxgain=0 txgain=0 ;dialplan=0 use_callingpres=yes presentation=allowed senddtmf=yes [numeris] context=numeris-in ports=1,2,3,4 msns=* * /etc/misdn-init.conf card=1,0x4 te_ptmp=1,2,3,4 poll=128 dsp_poll=128 dsp_options=0 dtmfthreshold=100 debug=0 obelix:/etc/as * SIP configuration [default] exten => 412,1,Dial(SIP/hard_sysadmins&SIP/ofauchon_soft,30) exten => 412,2,Voicemail(412) [numeris-in] exten => 0412,1,Goto(default,412,1) * Log of an incoming call (notice the activity on both ports) Wed Nov 5 21:04:12 2008: P[ 0] Got empty Msg.. Wed Nov 5 21:04:15 2008: P[ 0] MGMT: Short status dinfo 1000001 Wed Nov 5 21:04:15 2008: P[ 0] MGMT: SSTATUS: L1_ACTIVATED Wed Nov 5 21:04:15 2008: P[ 0] MGMT: Short status dinfo 1000001 Wed Nov 5 21:04:15 2008: P[ 0] MGMT: SSTATUS: L1_ACTIVATED Wed Nov 5 21:04:15 2008: P[ 2] handle_frm: frm->addr:42000203 frm->prim:3f082 Wed Nov 5 21:04:15 2008: P[ 2] --> lib: NEW_CR Ind with l3id:4004e on this port. Wed Nov 5 21:04:15 2008: P[ 2] channel with stid:0 for one second still in use! Wed Nov 5 21:04:15 2008: P[ 2] --> new_process: New L3Id: 4004e Wed Nov 5 21:04:15 2008: P[ 2] handle_frm: frm->addr:42000203 frm->prim:30582 Wed Nov 5 21:04:15 2008: P[ 2] set_channel: bc->channel:0 channel:1 Wed Nov 5 21:04:15 2008: P[ 2] $$$ find_chan: No channel found for oad:610493763 dad:0412 Wed Nov 5 21:04:15 2008: P[ 0] get_index: event not found! Wed Nov 5 21:04:15 2008: P[ 2] I IND :NEW_CHANNEL oad:610493763 dad:0412 pid:74 state:none Wed Nov 5 21:04:15 2008: P[ 2] --> channel:1 mode:TE cause:16 ocause:16 rad: cad: Wed Nov 5 21:04:15 2008: P[ 2] --> info_dad: onumplan:2 dnumplan:0 rnumplan: cpnnumplan:0 Wed Nov 5 21:04:15 2008: P[ 2] --> caps:Speech pi:0 keypad: sending_complete:1 Wed Nov 5 21:04:15 2008: P[ 2] --> screen:0 --> pres:0 Wed Nov 5 21:04:15 2008: P[ 2] --> addr:0 l3id:4004e b_stid:0 layer_id:50010280 Wed Nov 5 21:04:15 2008: P[ 2] --> facility:Fac_None out_facility:Fac_None Wed Nov 5 21:04:15 2008: P[ 2] --> urate:0 rate:16 mode:0 user1:0 Wed Nov 5 21:04:15 2008: P[ 2] --> bc:4352e1c h:0 sh:0 Wed Nov 5 21:04:15 2008: P[ 2] --> bc_state:BCHAN_CLEANED Wed Nov 5 21:04:15 2008: P[ 0] get_index: event not found! Wed Nov 5 21:04:15 2008: P[ 2] Chan not existing at the moment bc->l3id:4004e bc:0x4352e1c event:NEW_CHANNEL port:2 channel:1 Wed Nov 5 21:04:15 2008: P[ 2] NO USERUESRINFO Wed Nov 5 21:04:15 2008: P[ 2] find_free_chan: req_chan:1 Wed Nov 5 21:04:15 2008: P[ 2] --> found chan (preselected): 1 Wed Nov 5 21:04:15 2008: P[ 2] set_chan_in_stack: 1 Wed Nov 5 21:04:15 2008: P[ 2] Idx:0 stack->cchan:0 in_use:1 Chan:1 Wed Nov 5 21:04:15 2008: P[ 2] Idx:1 stack->cchan:0 in_use:0 Chan:2 Wed Nov 5 21:04:15 2008: P[ 2] Idx:2 stack->cchan:0 in_use:0 Chan:3 Wed Nov 5 21:04:15 2008: P[ 2] $$$ Setting up bc with stid :10010200 Wed Nov 5 21:04:15 2008: P[ 2] setup_bc: with dsp Wed Nov 5 21:04:15 2008: P[ 2] --> Channel is 1 Wed Nov 5 21:04:15 2008: P[ 2] --> TRANSPARENT Mode Wed Nov 5 21:04:15 2008: P[ 2] $$$ Bchan Activated addr 50010202 Wed Nov 5 21:04:15 2008: P[ 2] BC_STATE_CHANGE: l3id:4004e from:BCHAN_CLEANED to:BCHAN_ACTIVATED Wed Nov 5 21:04:15 2008: P[ 2] lib Got Prim: Addr 42000203 prim 30582 dinfo 4004e Wed Nov 5 21:04:15 2008: P[ 2] $$$ find_chan: No channel found for oad:610493763 dad:0412 Wed Nov 5 21:04:15 2008: P[ 2] I IND :SETUP oad:610493763 dad:0412 pid:74 state:none Wed Nov 5 21:04:15 2008: P[ 2] --> channel:1 mode:TE cause:16 ocause:16 rad: cad: Wed Nov 5 21:04:15 2008: P[ 2] --> info_dad: onumplan:2 dnumplan:0 rnumplan: cpnnumplan:0 Wed Nov 5 21:04:15 2008: P[ 2] --> caps:Speech pi:0 keypad: sending_complete:1 Wed Nov 5 21:04:15 2008: P[ 2] --> screen:0 --> pres:0 Wed Nov 5 21:04:15 2008: P[ 2] --> addr:50010202 l3id:4004e b_stid:10010200 layer_id:50010280 Wed Nov 5 21:04:15 2008: P[ 2] --> facility:Fac_None out_facility:Fac_None Wed Nov 5 21:04:15 2008: P[ 2] --> urate:0 rate:16 mode:0 user1:0 Wed Nov 5 21:04:15 2008: P[ 2] --> bc:4352e1c h:0 sh:0 Wed Nov 5 21:04:15 2008: P[ 2] --> bc_state:BCHAN_ACTIVATED Wed Nov 5 21:04:15 2008: P[ 2] $$$ find_chan: No channel found for oad:610493763 dad:0412 Wed Nov 5 21:04:15 2008: P[ 2] --> Bearer: Speech Wed Nov 5 21:04:15 2008: P[ 2] --> Codec: Alaw Wed Nov 5 21:04:15 2008: P[ 2] --> Bearer: Speech Wed Nov 5 21:04:15 2008: P[ 2] --> Codec: Alaw Wed Nov 5 21:04:15 2008: P[ 0] --> * NEW CHANNEL dad:0412 oad:610493763 Wed Nov 5 21:04:15 2008: P[ 2] read_config: Getting Config Wed Nov 5 21:04:15 2008: P[ 2] config_jb: Called Wed Nov 5 21:04:15 2008: P[ 2] --> * CallGrp: PickupGrp: Wed Nov 5 21:04:15 2008: P[ 2] --> CTON: Unknown Wed Nov 5 21:04:15 2008: P[ 2] --> EXPORT_PID: pid:74 Wed Nov 5 21:04:15 2008: P[ 2] --> PRES: Restricted (0) Wed Nov 5 21:04:15 2008: P[ 2] --> SCREEN: Unscreened (0) Wed Nov 5 21:04:15 2008: P[ 2] * Queuing chan 0x9121c28 Wed Nov 5 21:04:15 2008: P[ 2] CONTEXT:numeris-in Wed Nov 5 21:04:15 2008: P[ 2] SENDEVENT: stack->nt:0 stack->uperid:40000204 Wed Nov 5 21:04:15 2008: P[ 2] I SEND:PROCEEDING oad:0610493763 dad:0412 pid:74 Wed Nov 5 21:04:15 2008: P[ 2] --> bc_state:BCHAN_ACTIVATED Wed Nov 5 21:04:15 2008: P[ 2] --> channel:1 mode:TE cause:16 ocause:16 rad: cad: Wed Nov 5 21:04:15 2008: P[ 2] --> info_dad: onumplan:2 dnumplan:0 rnumplan: cpnnumplan:0 Wed Nov 5 21:04:15 2008: P[ 2] --> caps:Speech pi:0 keypad: sending_complete:1 Wed Nov 5 21:04:15 2008: P[ 2] --> screen:0 --> pres:0 Wed Nov 5 21:04:15 2008: P[ 2] --> addr:50010202 l3id:4004e b_stid:10010200 layer_id:50010280 Wed Nov 5 21:04:15 2008: P[ 2] --> facility:Fac_None out_facility:Fac_None Wed Nov 5 21:04:15 2008: P[ 2] --> urate:0 rate:16 mode:0 user1:0 Wed Nov 5 21:04:15 2008: P[ 2] --> bc:4352e1c h:0 sh:0 Wed Nov 5 21:04:15 2008: P[ 2] Sending msg, prim:30280 addr:41000204 dinfo:4004e Wed Nov 5 21:04:15 2008: P[ 2] GOT SETUP OK Wed Nov 5 21:04:15 2008: P[ 2] Freeing Msg on prim:30582 Wed Nov 5 21:04:15 2008: P[ 1] handle_frm: frm->addr:42000103 frm->prim:3f082 Wed Nov 5 21:04:15 2008: P[ 1] --> lib: NEW_CR Ind with l3id:20052 on this port. Wed Nov 5 21:04:15 2008: P[ 1] channel with stid:0 for one second still in use! Wed Nov 5 21:04:16 2008: P[ 1] --> new_process: New L3Id: 20052 Wed Nov 5 21:04:16 2008: P[ 1] handle_frm: frm->addr:42000103 frm->prim:30582 Wed Nov 5 21:04:16 2008: P[ 1] set_channel: bc->channel:0 channel:1 Wed Nov 5 21:04:16 2008: P[ 1] $$$ find_chan: No channel found for oad:610493763 dad:0412 Wed Nov 5 21:04:16 2008: P[ 0] get_index: event not found! Wed Nov 5 21:04:16 2008: P[ 1] I IND :NEW_CHANNEL oad:610493763 dad:0412 pid:75 state:none Wed Nov 5 21:04:16 2008: P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad: cad: Wed Nov 5 21:04:16 2008: P[ 2] * IND : Indication [3] from 412 Wed Nov 5 21:04:16 2008: P[ 2] * IND : ringing pid:74 Wed Nov 5 21:04:16 2008: P[ 1] --> info_dad: onumplan:2 dnumplan:0 rnumplan: cpnnumplan:0 Wed Nov 5 21:04:16 2008: P[ 2] --> * IND : ringing pid:74 Wed Nov 5 21:04:16 2008: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1 Wed Nov 5 21:04:16 2008: P[ 1] --> screen:0 --> pres:0 Wed Nov 5 21:04:16 2008: P[ 2] SENDEVENT: stack->nt:0 stack->uperid:40000204 Wed Nov 5 21:04:16 2008: P[ 2] I SEND:ALERTING oad:0610493763 dad:0412 pid:74 Wed Nov 5 21:04:16 2008: P[ 1] --> addr:0 l3id:20052 b_stid:0 layer_id:50010180 Wed Nov 5 21:04:16 2008: P[ 2] --> bc_state:BCHAN_ACTIVATED Wed Nov 5 21:04:16 2008: P[ 1] --> facility:Fac_None out_facility:Fac_None Wed Nov 5 21:04:16 2008: P[ 2] --> channel:1 mode:TE cause:16 ocause:16 rad: cad: Wed Nov 5 21:04:16 2008: P[ 1] --> urate:0 rate:16 mode:0 user1:0 Wed Nov 5 21:04:16 2008: P[ 2] --> info_dad: onumplan:2 dnumplan:0 rnumplan: cpnnumplan:0 Wed Nov 5 21:04:16 2008: P[ 1] --> bc:434680c h:0 sh:0 Wed Nov 5 21:04:16 2008: P[ 2] --> caps:Speech pi:0 keypad: sending_complete:1 Wed Nov 5 21:04:16 2008: P[ 1] --> bc_state:BCHAN_CLEANED Wed Nov 5 21:04:16 2008: P[ 2] --> screen:0 --> pres:0 Wed Nov 5 21:04:16 2008: P[ 0] get_index: event not found! Wed Nov 5 21:04:16 2008: P[ 2] --> addr:50010202 l3id:4004e b_stid:10010200 layer_id:50010280 Wed Nov 5 21:04:16 2008: P[ 1] Chan not existing at the moment bc->l3id:20052 bc:0x434680c event:NEW_CHANNEL port:1 channel:1 Wed Nov 5 21:04:16 2008: P[ 2] --> facility:Fac_None out_facility:Fac_None Wed Nov 5 21:04:16 2008: P[ 1] NO USERUESRINFO Wed Nov 5 21:04:16 2008: P[ 2] --> urate:0 rate:16 mode:0 user1:0 Wed Nov 5 21:04:16 2008: P[ 1] find_free_chan: req_chan:1 Wed Nov 5 21:04:16 2008: P[ 2] --> bc:4352e1c h:0 sh:0 Wed Nov 5 21:04:16 2008: P[ 2] Sending msg, prim:30180 addr:41000204 dinfo:4004e Wed Nov 5 21:04:16 2008: P[ 1] --> found chan (preselected): 1 Wed Nov 5 21:04:16 2008: P[ 1] set_chan_in_stack: 1 Wed Nov 5 21:04:16 2008: P[ 2] --> * SEND: State Ring pid:74 Wed Nov 5 21:04:16 2008: P[ 1] Idx:0 stack->cchan:0 in_use:1 Chan:1 Wed Nov 5 21:04:16 2008: P[ 2] --> incoming_early_audio off Wed Nov 5 21:04:16 2008: P[ 1] Idx:1 stack->cchan:0 in_use:0 Chan:2 Wed Nov 5 21:04:16 2008: P[ 1] Idx:2 stack->cchan:0 in_use:0 Chan:3 Wed Nov 5 21:04:16 2008: P[ 1] $$$ Setting up bc with stid :10010100 Wed Nov 5 21:04:16 2008: P[ 1] setup_bc: with dsp Wed Nov 5 21:04:16 2008: P[ 1] --> Channel is 1 Wed Nov 5 21:04:16 2008: P[ 1] --> TRANSPARENT Mode Wed Nov 5 21:04:16 2008: P[ 1] $$$ Bchan Activated addr 50010102 Wed Nov 5 21:04:16 2008: P[ 1] BC_STATE_CHANGE: l3id:20052 from:BCHAN_CLEANED to:BCHAN_ACTIVATED Wed Nov 5 21:04:16 2008: P[ 1] lib Got Prim: Addr 42000103 prim 30582 dinfo 20052 Wed Nov 5 21:04:16 2008: P[ 1] $$$ find_chan: No channel found for oad:610493763 dad:0412 Wed Nov 5 21:04:16 2008: P[ 1] I IND :SETUP oad:610493763 dad:0412 pid:75 state:none Wed Nov 5 21:04:16 2008: P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad: cad: Wed Nov 5 21:04:16 2008: P[ 1] --> info_dad: onumplan:2 dnumplan:0 rnumplan: cpnnumplan:0 Wed Nov 5 21:04:16 2008: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1 Wed Nov 5 21:04:16 2008: P[ 1] --> screen:0 --> pres:0 Wed Nov 5 21:04:16 2008: P[ 1] --> addr:50010102 l3id:20052 b_stid:10010100 layer_id:50010180 Wed Nov 5 21:04:16 2008: P[ 1] --> facility:Fac_None out_facility:Fac_None Wed Nov 5 21:04:16 2008: P[ 1] --> urate:0 rate:16 mode:0 user1:0 Wed Nov 5 21:04:16 2008: P[ 1] --> bc:434680c h:0 sh:0 Wed Nov 5 21:04:16 2008: P[ 1] --> bc_state:BCHAN_ACTIVATED Wed Nov 5 21:04:16 2008: P[ 1] $$$ find_chan: No channel found for oad:610493763 dad:0412 Wed Nov 5 21:04:16 2008: P[ 1] --> Bearer: Speech Wed Nov 5 21:04:16 2008: P[ 1] --> Codec: Alaw Wed Nov 5 21:04:16 2008: P[ 1] --> Bearer: Speech Wed Nov 5 21:04:16 2008: P[ 1] --> Codec: Alaw Wed Nov 5 21:04:16 2008: P[ 0] --> * NEW CHANNEL dad:0412 oad:610493763 Wed Nov 5 21:04:16 2008: P[ 1] read_config: Getting Config Wed Nov 5 21:04:16 2008: P[ 1] config_jb: Called Wed Nov 5 21:04:16 2008: P[ 1] --> * CallGrp: PickupGrp: Wed Nov 5 21:04:16 2008: P[ 1] --> CTON: Unknown Wed Nov 5 21:04:16 2008: P[ 1] --> EXPORT_PID: pid:75 Wed Nov 5 21:04:16 2008: P[ 1] --> PRES: Restricted (0) Wed Nov 5 21:04:16 2008: P[ 1] --> SCREEN: Unscreened (0) Wed Nov 5 21:04:16 2008: P[ 1] * Queuing chan 0x4422258 Wed Nov 5 21:04:16 2008: P[ 1] CONTEXT:numeris-in Wed Nov 5 21:04:16 2008: P[ 1] SENDEVENT: stack->nt:0 stack->uperid:40000104 Wed Nov 5 21:04:16 2008: P[ 1] I SEND:PROCEEDING oad:0610493763 dad:0412 pid:75 Wed Nov 5 21:04:16 2008: P[ 1] --> bc_state:BCHAN_ACTIVATED Wed Nov 5 21:04:16 2008: P[ 1] --> channel:1 mode:TE cause:16 ocause:16 rad: cad: Wed Nov 5 21:04:16 2008: P[ 1] --> info_dad: onumplan:2 dnumplan:0 rnumplan: cpnnumplan:0 Wed Nov 5 21:04:16 2008: P[ 1] --> caps:Speech pi:0 keypad: sending_complete:1 Wed Nov 5 21:04:16 2008: P[ 1] --> screen:0 --> pres:0 Wed Nov 5 21:04:16 2008: P[ 1] --> addr:50010102 l3id:20052 b_stid:10010100 layer_id:50010180 Wed Nov 5 21:04:16 2008: P[ 1] --> facility:Fac_None out_facility:Fac_None Wed Nov 5 21:04:16 2008: P[ 1] --> urate:0 rate:16 mode:0 user1:0 Wed Nov 5 21:04:16 2008: P[ 1] --> bc:434680c h:0 sh:0 Wed Nov 5 21:04:16 2008: P[ 1] Sending msg, prim:30280 addr:41000104 dinfo:20052 Wed Nov 5 21:04:16 2008: P[ 1] GOT SETUP OK Wed Nov 5 21:04:16 2008: P[ 1] Freeing Msg on prim:30582 Wed Nov 5 21:04:16 2008: P[ 2] BCHAN: bchan ACT Confirm pid:74 Wed Nov 5 21:04:16 2008: P[ 0] misdn_jb_empty: Wait...requested:48 p:43d18b8 Wed Nov 5 21:04:16 2008: P[ 2] Transmitting 48 samples 2 misdn Wed Nov 5 21:04:16 2008: P[ 2] writing 48 bytes 2 asterisk Wed Nov 5 21:04:16 2008: P[ 0] misdn_jb_empty: Wait...requested:128 p:43d18b8 Wed Nov 5 21:04:16 2008: P[ 2] Transmitting 128 samples 2 misdn Wed Nov 5 21:04:16 2008: P[ 2] writing 128 bytes 2 asterisk Wed Nov 5 21:04:16 2008: P[ 0] misdn_jb_empty: Wait...requested:128 p:43d18b8 Wed Nov 5 21:04:16 2008: P[ 1] * IND : Indication [3] from 412 Wed Nov 5 21:04:16 2008: P[ 2] Transmitting 128 samples 2 misdn Wed Nov 5 21:04:16 2008: P[ 1] * IND : ringing pid:75 Wed Nov 5 21:04:16 2008: P[ 2] writing 128 bytes 2 asterisk -- Olivier Fauchon Freelance System-Network Admin Phone: +33 610 493 763 http://www.aixmarseille.com