Hi,
I successfully managed to compile the DECT kernel, the libs and asterisk. I also can register PPs in asterisk, call them and place outbound calls from these PPs, but as soon as the connection is established, it takes about 2 seconds until the call drops, the PP loses connectivity and re-registers at asterisk. Whithin these 2 seconds the connection works in both directions correctly. I use the PCI Com-on-Air Card a Gigaset A58H PP and an older Gigaset 4000 Comfort.
Does anyone know what the reason for this behaviour is? See the asterisk-log below...
Thanks in advance, Johannes Graser
*CLI> LCE: link -1 (RELEASED): alloc LCE: link 42 (ESTABLISHED): start <LCE.05>: SDU timer LCE: link 42 (ESTABLISHED): new link: PMID: bb600 LCN: 0 LLN: 1 SAPI: 0
LCE: RX: 03 05 05 07 80 a8 00 a4 41 3a 28 06 07 a0 a5 01 |........A:(.....| LCE: RX: 18 27 d6 18 e0 80 7b 06 81 00 02 18 01 42 |.'....{......B| LCE: link 42 (ESTABLISHED): stop <LCE.05>: SDU timer LCE: link 42 (ESTABLISHED): new transaction: protocol: Call Control F: 0 TV: 0 CC: unknown transaction: msg type: 5 CC-SETUP parse {CC-SETUP} message IE: <<PORTABLE-IDENTITY>> id: 5 len: 9 dst: 0x2115ff0 type: IPUI (0) PUT: N (IPEI) EMC: 0a44 PSN: 13a28 IE: <<FIXED-IDENTITY>> id: 6 len: 9 dst: 0x2112700 type: PARK (20) class: A EMC: 1182 FPN: 0fac3 IE: <<BASIC-SERVICE>> id: e0 len: 2 dst: 0x2112b50 call class: normal call (8) service: basic speech default attributes (0) IE: <<ESCAPE-TO-PROPRIETARY>> id: 7b len: 8 dst: 0x2119d60 EMC: 2 Content: 18 01 42 |..B| LCE: link 42 (ESTABLISHED): set IPUI: N EMC: 0a44 PSN: 13a28 LCE: link 42 (ESTABLISHED): confirm transaction: Call Control TV: 0 Role: 1 CC: call 0x2112620 (CALL INITIATED): new call CC: call 0x2112620 (CALL INITIATED): MNCC_SETUP-ind
MM: link 42 (none): MM_AUTHENTICATE-req MM: link 42 (none): initiate procedure: authentication priority: 2 timeout: 10s LCE: link 42 (ESTABLISHED): open transaction: Mobility Management TV: 0 build {MM-AUTHENTICATION-REQUEST} message IE: <<AUTH-TYPE>> id: a 0x7f6c82671860 [Mar 17 16:22:43] NOTICE[1426]: chan_dect.c:1051 dect_mncc_setup_ind: PT 'DECT-PT-600': incoming call authentication algorithm: DSAA (1) authentication key type: User authentication key (1) authentication key number: 8 cipher key number: 0 INC: 0 DEF: 0 TXC: 0 UPC: 1 IE: <<RAND>> id: c 0x7f6c82671840 value: 13c93f577c813bcc IE: <<RS>> id: e 0x7f6c82671820 value: 4d90028926449990 LCE: TX: 05 40 0a 03 01 18 10 0c 08 cc 3b 81 7c 57 3f c9 |.@........;.|W?.| LCE: TX: 13 0e 08 90 99 44 26 89 02 90 4d |.....D&...M|
LCE: RX: 85 41 0d 04 4d 1b d3 7f |.A..M...| MM: link 42 (authentication): AUTHENTICATION-REPLY parse {MM-AUTHENTICATION-REPLY} message IE: <<RES>> id: d len: 6 dst: 0x2116050 value: 7fd31b4d MM: link 42 (authentication): complete authentication procedure LCE: link 42 (ESTABLISHED): close transaction: Mobility Management TV: 0 Role: 0 LCE: link 42 (ESTABLISHED): partial release MM: link 42 (none): MM_AUTHENTICATE-cfm: accept: 1
MM: link 42 (none): MM_CIPHER-req MM: link 42 (none): initiate procedure: ciphering priority: 2 timeout: 10s LCE: link 42 (ESTABLISHED): open transaction: Mobility Management TV: 0 LCE: link 42 (ESTABLISHED): DL_ENC_KEY-req: 99dac9d705411edf build {MM-CIPHER-REQUEST} message IE: <<CIPHER-INFO>> id: 19 0x7f6c82671770 enable: 1 cipher algorithm: DECT Standard Cipher 1 (1) cipher key type: derived (9) cipher key num: 0 LCE: link 42 (ESTABLISHED): stop <LCE.05>: SDU timer [Mar 17 16:22:43] NOTICE[1426]: chan_dect.c:1327 dect_mm_authenticate_cfm: PT 'DECT-PT-600': authentication succeeded LCE: TX: 05 4c 19 02 81 98 |.L....|
LCE: link 42 (ESTABLISHED): DL_ENCRYPT-ind MM: link 42 (ciphering): CIPHER-cfm MM: link 42 (ciphering): complete ciphering procedure LCE: link 42 (ESTABLISHED): close transaction: Mobility Management TV: 0 Role: 0 LCE: link 42 (ESTABLISHED): partial release MM: link 42 (none): MM_CIPHER-cfm: accept: 1
CC: call 0x2112620 (CALL INITIATED): MNCC_CALL_PROC-req build {CC-CALL-PROC} message LCE: link 42 (ESTABLISHED): stop <LCE.05>: SDU timer LCE: TX: 83 02 |..| -- Executing [s@default:1] Wait("DECT/DECT-PT-600-02112698", "1") in new stack
LCE: RX: 03 7b 2c 03 31 32 33 |.{,.123| CC: call 0x2112620 (CALL PROCEEDING): receive msg type 7b CC: call 0x2112620 (CALL PROCEEDING): CC-INFO parse {CC-INFO} message IE: <<MULTI-KEYPAD>> id: 2c len: 5 dst: 0x211a370 Info: 31 32 33 |123| CC: call 0x2112620 (CALL PROCEEDING): MNCC_INFO-ind keypad: '1' (31) keypad: '2' (32) keypad: '3' (33)
LCE: RX: 03 7b 7b 05 81 00 02 30 00 |.{{....0.| CC: call 0x2112620 (CALL PROCEEDING): receive msg type 7b CC: call 0x2112620 (CALL PROCEEDING): CC-INFO parse {CC-INFO} message IE: <<ESCAPE-TO-PROPRIETARY>> id: 7b len: 7 dst: 0x2119900 EMC: 2 Content: 30 00 |0.| CC: call 0x2112620 (CALL PROCEEDING): MNCC_INFO-ind
CC: call 0x2112620 (CALL PROCEEDING): MNCC_CONNECT-req -- Executing [s@default:2] Answer("DECT/DECT-PT-600-02112698", "") in new stack CC: call 0x2112620 (CALL PROCEEDING): U-Plane connected build {CC-CONNECT} message LCE: TX: 83 07 |..| [Mar 17 16:22:45] NOTICE[1442]: chan_dect.c:665 dect_answer: PT 'DECT-PT-600': answer call state 4 [Mar 17 16:22:45] NOTICE[1442]: chan_dect.c:844 dect_indicate: PT 'DECT-PT-600': indicate condition -1 -- Executing [s@default:3] Set("DECT/DECT-PT-600-02112698", "TIMEOUT(digit)=5") in new stack -- Digit timeout set to 5.000 -- Executing [s@default:4] Set("DECT/DECT-PT-600-02112698", "TIMEOUT(response)=10") in new stack -- Response timeout set to 10.000 -- Executing [s@default:5] BackGround("DECT/DECT-PT-600-02112698", "demo-congrats") in new stack -- <DECT/DECT-PT-600-02112698> Playing 'demo-congrats.gsm' (language 'en') -- Executing [3@default:1] Set("DECT/DECT-PT-600-02112698", "LANGUAGE()=fr") in new stack [Mar 17 16:22:45] ERROR[1442]: pbx.c:3683 ast_func_write: Function LANGUAGE not registered -- Executing [3@default:2] Goto("DECT/DECT-PT-600-02112698", "s,restart") in new stack -- Goto (default,s,5) -- Executing [s@default:5] BackGround("DECT/DECT-PT-600-02112698", "demo-congrats") in new stack -- <DECT/DECT-PT-600-02112698> Playing 'demo-congrats.gsm' (language 'en') CC: call 0x2112620 (ACTIVE): LU1 Queue-Statistic: CC: call 0x2112620 (ACTIVE): RX-Bytes: 0 CC: call 0x2112620 (ACTIVE): RX-Underflow: 0 CC: call 0x2112620 (ACTIVE): TX-Bytes: 400 CC: call 0x2112620 (ACTIVE): TX-Underflow: 0 CC: call 0x2112620 (ACTIVE): LU1 Queue-Statistic: CC: call 0x2112620 (ACTIVE): RX-Bytes: 0 CC: call 0x2112620 (ACTIVE): RX-Underflow: 0 CC: call 0x2112620 (ACTIVE): TX-Bytes: 400 CC: call 0x2112620 (ACTIVE): TX-Underflow: 0 CC: call 0x2112620 (ACTIVE): LU1 Queue-Statistic: CC: call 0x2112620 (ACTIVE): RX-Bytes: 0 CC: call 0x2112620 (ACTIVE): RX-Underflow: 0 CC: call 0x2112620 (ACTIVE): TX-Bytes: 400 CC: call 0x2112620 (ACTIVE): TX-Underflow: 0
LCE: recvmsg: Connection timed out LCE: link 42 (ESTABLISHED): shutdown CC: call 0x2112620 (ACTIVE): shutdown CC: call 0x2112620 (ACTIVE): MNCC_REJECT-ind CC: call 0x2112620 (ACTIVE): LU1 Queue-Statistic: CC: call 0x2112620 (ACTIVE): RX-Bytes: 0 CC: call 0x2112620 (ACTIVE): RX-Underflow: 0 CC: call 0x2112620 (ACTIVE): TX-Bytes: 440 CC: call 0x2112620 (ACTIVE): TX-Underflow: 0 CC: call 0x2112620 (ACTIVE): U-Plane disconnected LCE: link 42 (RELEASED): close transaction: Call Control TV: 0 Role: 1 LCE: link 42 (RELEASED): destroy == Spawn extension (default, s, 5) exited non-zero on 'DECT/DECT-PT-600-02112698'
Am 17.03.2011 16:33, schrieb Johannes Graser:
Hi,
I successfully managed to compile the DECT kernel, the libs and asterisk. I also can register PPs in asterisk, call them and place outbound calls from these PPs, but as soon as the connection is established, it takes about 2 seconds until the call drops, the PP loses connectivity and re-registers at asterisk. Whithin these 2 seconds the connection works in both directions correctly. I use the PCI Com-on-Air Card a Gigaset A58H PP and an older Gigaset 4000 Comfort.
Does anyone know what the reason for this behaviour is? See the asterisk-log below...
This usually means the PTs got desynchronized. Do both phones reregister after the call got dropped?
Please try the following to get some more debugging information:
- build kernel with CONFIG_DYNAMIC_DEBUG=y - mount -t debugfs none /sys/kernel/debug/ - before placing a call, execute:
echo -n 'file mac_csf.c +p' > /debug/dynamic_debug/control echo -n 'file mac_ccf.c +p' > /debug/dynamic_debug/control
- after the call execute the same commands with -p and send the kernel log messages that got logged during that period.
Yes, both phones reregister after the call drops.
Attached are the debugging logs, starting immediately before placing a call and ending after the phone reregistered. On Samstag, 19. März 2011 at 02:02, Patrick McHardy wrote:
Am 17.03.2011 16:33, schrieb Johannes Graser:
Hi,
I successfully managed to compile the DECT kernel, the libs and asterisk. I also can register PPs in asterisk, call them and place outbound calls from these PPs, but as soon as the connection is established, it takes about 2 seconds until the call drops, the PP loses connectivity and re-registers at asterisk. Whithin these 2 seconds the connection works in both directions correctly. I use the PCI Com-on-Air Card a Gigaset A58H PP and an older Gigaset 4000 Comfort.
Does anyone know what the reason for this behaviour is? See the asterisk-log below...
This usually means the PTs got desynchronized. Do both phones reregister after the call got dropped?
Please try the following to get some more debugging information:
- build kernel with CONFIG_DYNAMIC_DEBUG=y
- mount -t debugfs none /sys/kernel/debug/
- before placing a call, execute:
echo -n 'file mac_csf.c +p' > /debug/dynamic_debug/control echo -n 'file mac_ccf.c +p' > /debug/dynamic_debug/control
- after the call execute the same commands with -p and send the
kernel log messages that got logged during that period.
On 28.03.2011 13:31, Patrick McHardy wrote:
On 27.03.2011 12:36, Johannes Graser wrote:
Yes, both phones reregister after the call drops.
Thanks, I'll have a closer look, but it will probably take until the weekend.
Mar 27 12:30:59 debian kernel: [ 546.715419] RX 2656.03.16: trx0: Q1: 0 Q2: 1 A/B: 60 carrier: 8 identities information: e: 0 class: 0 emc: 1182 fpn: 0fac3 rpn: 7 Mar 27 12:30:59 debian kernel: [ 546.715427] TBC (TBEI 21/ESTABLISHED): PMID: assigned bb600 FMID: 618: receive Mar 27 12:30:59 debian kernel: [ 546.715432] MBC (MCEI 7/ESTABLISHED): TBC_DATA-ind: TBEI: 21 LBN: 15 chan: 3 len: 40 Mar 27 12:30:59 debian kernel: [ 546.715437] TBC (TBEI 21/ESTABLISHED): PMID: assigned bb600 FMID: 618: watchdog expire
There was a bug in the identities information parsing, causing it to misparse the RPN, which in turn triggered the TBC watchdog since no correct identities information was received from the phone.
Please try again using the current -git tree. Note that you most likely have to reinstall the kernel DECT header files and recompile the userspace code due to some unrelated changes.
-
Johannes Graser -
Patrick McHardy