santonio
Goto Top

VDSL Controller bei C886VA und C896VA einmalig für acht Sekunden UP

Hallo,

das Thema Cisco und VDSL wurde ja bereits umfangreich in zahlreichen Posts diskutiert. Ich bin diese auch durchgegangen, komme aber dennoch nicht weiter (vielleicht hab ich' aber auch übersehen).

Ich habe hier zwei Cisco ISR (C886VA und C896VA). Beide jeweils mit aktuellster VDSL-Controller-Firmware B2pvC038v.d24m mit Unterstützung für Vectoring. Bei beiden Geräten geht nach der ersten Einwahl der VDSL0 Controller für wenige Sekunden UP ("Controller VDSL 0 is UP") und in den "Modem Status: TC Sync (Showtime!)", danach fällt er aber in DOWN und in den Handshake zurück. Bin für jede Idee dankbar.

Mein ISP ist easybell, die Einwahl über Fritzbox 7590 funktioniert und liefert folgende Werte:
Verbindungstyp: VDSL2 17a G. Vector (ITU G.993.5)
DSL-Vermittlungsstelle: Adtran Broadcom: 11.4.18

Hier nun Auszüge aus dem C896VA, beim C886VA ist das Problem aber identisch. Die IOS-Image ist "c800-universalk9-mz.SPA.156-3.M6a.bin". Das Telefonkabel RJ11<>TAE-F habe ich schon gewechselt (nur um Layer 1 im CPE auszuschließen).

Hier zunächst die einfachen Syslog-Meldungen (Debugging weiter unten):
*Jan 23 17:28:47: %CONTROLLER-5-UPDOWN: Controller VDSL 0, changed state to up
*Jan 23 17:28:50: %LINEPROTO-5-UPDOWN: Line protocol on Interface Ethernet0, changed state to up
*Jan 23 17:28:55: %CONTROLLER-5-UPDOWN: Controller VDSL 0, changed state to down
*Jan 23 17:28:56: %LINEPROTO-5-UPDOWN: Line protocol on Interface Ethernet0, changed state to down
*Jan 23 17:28:57: %LINK-3-UPDOWN: Interface Ethernet0, changed state to down

Hier der temporäre UP-Status des VDSL Controllers nach der ersten Einwahl. Die Gegenstelle und das VDSL Profil "G.993.2 (VDSL2) Profile 17a" wird erkannt.
#show controllers VDSL 0
Controller VDSL 0 is UP

Daemon Status:           Up

                        XTU-R (DS)              XTU-C (US)
Chip Vendor ID:         'BDCM'                   'BDCM'  
Chip Vendor Specific:   0x0000                   0xB212
Chip Vendor Country:    0xB500                   0xB500
Modem Vendor ID:        'CSCO'                   '    '  
Modem Vendor Specific:  0x4602                   0x0000
Modem Vendor Country:   0xB500                   0x0000
Serial Number Near:    FCZXXXXXXXX C896VA-K 15.6(3)M6a
Serial Number Far:     eq nr port:13  oemid softwarerev
Modem Version Near:    15.6(3)M6a
Modem Version Far:     0xb212

Modem Status:            TC Sync (Showtime!)

DSL Config Mode:         AUTO
Trained Mode:   G.993.2 (VDSL2) Profile 17a
TC Mode:                 PTM
Selftest Result:         0x00
DELT configuration:      disabled
DELT state:              not running

Full inits:             1
Failed full inits:      34
Short inits:            0
Failed short inits:     3

Firmware        Source          File Name
--------        ------          ----------
VDSL            user config     flash:VA_B_38V_d24m.bin

Modem FW  Version:      170321_1253-4.02L.03.B2pvC038v.d24m
Modem PHY Version:      B2pvC038v.d24m
Trellis:                 ON                       ON
SRA:                     disabled                disabled
 SRA count:              0                       0
Bit swap:                enabled                 enabled
 Bit swap count:         0                       0
Line Attenuation:        25.0 dB                  0.0 dB
Signal Attenuation:       0.0 dB                  0.0 dB
Noise Margin:             6.3 dB                 13.6 dB
Attainable Rate:        88188 kbits/s            39728 kbits/s
Actual Power:            12.5 dBm                 1.1 dBm
Per Band Status:        D1      D2      D3      U0      U1      U2      U3
Line Attenuation(dB):   24.0    21.5    42.1    38.5    15.9    19.4    N/A
Signal Attenuation(dB): 22.3    21.5    42.1    38.5    15.9    19.4    N/A
Noise Margin(dB):       0.0     0.0     0.0     N/A     13.6    13.6    N/A
Total FECC:             0                        0
Total ES:               0                        0
Total SES:              0                        0
Total LOSS:             0                        0
Total UAS:              7831                     7831
Total LPRS:             0                        0
Total LOFS:             0                        0
Total LOLS:             0                        0

                  DS Channel1     DS Channel0   US Channel1       US Channel0
Speed (kbps):             0            88804             0             32000
SRA Previous Speed:       0                0             0                 0
Previous Speed:           0                0             0                 0
Reed-Solomon EC:          0                0             0                 0
CRC Errors:               0                0             0                 0
Header Errors:            0                0             0                 0
Interleave (ms):       3.00             0.00          0.00              0.00
Actual INP:            4.00            76.00          4.00             44.00

Training Log :  Stopped
Training Log Filename : flash:vdsllog.bin

Nach wenigen Sekunden fällt er zurück zu "Controller VDSL 0 is DOWN" und zum "Modem Status: Unknown", bzw. "Handshake" und es bleibt dabei. "Failed full inits" zählt fortlaufend hoch:
#show controllers VDSL 0
Controller VDSL 0 is DOWN

Daemon Status:           Establishing Link

                        XTU-R (DS)              XTU-C (US)
Chip Vendor ID:         'BDCM'                   'BDCM'  
Chip Vendor Specific:   0x0000                   0xB212
Chip Vendor Country:    0xB500                   0xB500
Modem Vendor ID:        'CSCO'                   '    '  
Modem Vendor Specific:  0x4602                   0x0000
Modem Vendor Country:   0xB500                   0x0000
Serial Number Near:    FCZXXXXXXXX C896VA-K 15.6(3)M6a
Serial Number Far:
Modem Version Near:    15.6(3)M6a
Modem Version Far:     0xb212

Modem Status:            Handshake

DSL Config Mode:         AUTO
Trained Mode:
TC Mode:                 PTM
Selftest Result:         0x00
DELT configuration:      disabled
DELT state:              not running

Full inits:             1
Failed full inits:      46
Short inits:            0
Failed short inits:     3

Firmware        Source          File Name
--------        ------          ----------
VDSL            user config     flash:VA_B_38V_d24m.bin

Modem FW  Version:      170321_1253-4.02L.03.B2pvC038v.d24m
Modem PHY Version:      B2pvC038v.d24m
Trellis:                 ON                       ON
SRA:                     disabled                disabled
 SRA count:              0                       0
Bit swap:                enabled                 enabled

Training Log :  Stopped
Training Log Filename : flash:vdsllog.bin

Hier die gekürzte und in vielen Details noch unvollständige Konfiguration, für die Einwahl sollte es allerdings reichen:
#show running-config
!
controller VDSL 0
 operating mode { auto | vdsl2 }     < beide Parameter ausprobiert
 firmware filename flash:VA_B_38V_d24m.bin
!
!
interface ATM0
 no ip address
 shutdown
 no atm ilmi-keepalive
!
!
interface Ethernet0
 no ip address
!
interface Ethernet0.7
 encapsulation dot1Q 7
 ip virtual-reassembly in
 pppoe enable group global
 pppoe-client dial-pool-number 1
!
!
interface Dialer0
 mtu 1488
 bandwidth 10000
 bandwidth receive 50000
 ip address negotiated
 no ip redirects
 no ip unreachables
 no ip proxy-arp
 ip virtual-reassembly in
 encapsulation ppp
 dialer pool 1
 dialer-group 1
 no cdp enable
 ppp authentication pap callin
 ppp pap sent-username XXXXXXX/XXXXXXX password 7 XXXXXXX
 ppp ipcp dns request
 ppp ipcp mask request
 ppp ipcp route default
!

Hier noch ein Command auf dem VDSL-Chipset. Das VDSL2 profile 17a wird unterstützt:
(config)#service internal
(config)#end
#test vdsl 0 modem exec adsl profile --show
The output of the command is :

Modulations:
        G.Dmt   Disabled
        G.lite  Disabled
        T1.413  Disabled
        ADSL2   Disabled
        AnnexL  Enabled
        ADSL2+  Disabled
        AnnexM  Enabled
        VDSL2   Enabled
VDSL2 profiles:
        8a      Enabled
        8b      Enabled
        8c      Enabled
        8d      Enabled
        12a     Enabled
        12b     Enabled
        17a     Enabled
        30a     Disabled
        US0     Enabled
Phone line pair:
        Inner pair
Capability:
        bitswap         On
        sra             Off
        trellis         On
        sesdrop         Off
        CoMinMgn        Off
        24k             On
        phyReXmt(Us/Ds) Off/On
        TpsTc           AvPvAa
        monitorTone:    On
        dynamicD:       On
        dynamicF:       Off
        SOS:            On
        Training Margin(Q4 in dB):      -1(DEFAULT)

Beim Debugging blicke ich nicht so ganz durch. Mir fallen die regelmäßigen Meldung "ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE" auf, aber ich habe bislang noch nichts im Netz hierzu gefunden. Vermutlich bekommt er der Router kein Keepalive vom DSLAM? Hab in den Standards G.993.2 und G.993.5 nach keepalive gesucht, aber nichts gefunden. Bin nicht sehr erfahren, was die Konfiguration von DSL über IOS angeht und versuche das mal nächste Woche mit dem ISP zu klären, aber vielleicht hat ja jemand einen kleinen Hinweis für mich... vielleicht liege ich aber auch komplett falsch...
# debug vdsl 0 all
<189>8037: *Jan 23 17:01:00: %SYS-5-CONFIG_I: Configured from console by console
<191>8038: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=67, seq = 0, len=16, tx buf @0x1DD199C0, rx buf @0x1DD199C0
<191>8039: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 16 @0x1DD199C0, rx_len = 16 @0x1DD199C0
<191>8040: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
<191>8041: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 67x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8042: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 000A: hdr= E382, 
<191>8043:                 total len= 16, msg len= 16, @28
<191>8044: ipc VDSL 0: vdsl_ipc_send, 
<191>8045: TX: Msg for opcode(67)...waiting for Response from Mailbox!
<191>8046: mbx VDSL 0: vdsl_msg_rcv_isr, 
<191>8047: Desc@ 5F0 : hdr= E002, total len= 16, msg len= 16, @618
<191>8048: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD199C0, len= 16 00x 02x 67x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8049: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD199D0, len= 16
<191>8050: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 16, 0x1DD199C0
<191>8051: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=67
<191>8052: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x1118C89C opcode=67 to caller
<191>8053: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 67
<191>8054: ipc VDSL 0: vdsl_msg_rcv_handler, 
<191>8055: KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
<191>8056: ipc VDSL 0: vdsl_ipc_send, 
<191>8057: TX: Call for opcode 67 Success!
<191>8058: ipc VDSL 0: vdsl_diag_start, 
<191>8059: vdsl_diag_start: Successful Return !
<191>8060: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
<191>8061: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
<191>8062: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
<191>8063: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5FA : hdr= E004, total len= 28, msg len= 28, @618
<191>8064: mbx VDSL 0: vdsl_msg_rcv_isr, Notification msg type 4, len= 28
<191>8065: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1E93A140, len= 28 00x 04x 11x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 42x
<191>8066:  4294967242x 55x 16x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8067: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1E93A15C, len= 28
<191>8068: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 4 rx handler, err= 0, len= 28, 0x1E93A140
<191>8069: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
<191>8070: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=16, seq = 0, len=28, tx buf @0x1DD199C0, rx buf @0x1DD199C0
<191>8071: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD199C0, rx_len = 244 @0x1DD199C0
<191>8072: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
<191>8073: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 16x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8074:  00x 00x 00x 00x 00x 00x 02x 00x 00x 00x 00x
<191>8075: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0014: hdr= E382, 
<191>8076:                 total len= 28, msg len= 28, @28
<191>8077: ipc VDSL 0: vdsl_ipc_send, 
<191>8078: TX: Msg for opcode(16)...waiting for Response from Mailbox!
<191>8079: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 604 : hdr= E002, total len= 244, msg len= 244, @618
<191>8080: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD199C0, len= 244 00x 02x 16x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8081:  00x 00x 00x 00x 00x 00x 02x 00x 00x 00x 00x 4294967221x 00x 66x 68x 67x
<191>8082:  77x 4294967218x 18x 00x 00x 32x 32x 32x 32x 00x 00x 48x 120x 98x 50x 49x
<191>8083:  50x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8084:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8085:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8086:  00x 00x 00x
<191>8087: mbx VDSL 0: vdsl_process_msg_rcv, 
<191>8088: Last message (2) : addr= 0x618, dest= 0x1DD19AB4, len= 244
<191>8089: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 244, 0x1DD199C0
<191>8090: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=16
<191>8091: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x1118C8A8 opcode=16 to caller
<191>8092: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 16
<191>8093: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
<191>8094: ipc VDSL 0: vdsl_ipc_send, 
<191>8095: TX: Call for opcode 16 Success!
<191>8096: ipc VDSL 0: vdsl_g997_line_inventory_get, 
<191>8097: vdsl_g997_line_inventory_get: Successful Return msg->inv.selftest_result = 0 
<191>8098:  msg->inv.delt_progress_state = 0 
<191>8099:  msg->inv.phyVerStr =  
<191>8100:  msg->inv.drvVerStr =  !
<191>8101: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=16, seq = 0, len=28, tx buf @0x1DD199C0, rx buf @0x1DD199C0
<191>8102: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD199C0, rx_len = 244 @0x1DD199C0
<191>8103: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
<191>8104: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 16x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8105:  00x 00x 00x 00x 00x 00x 01x 00x 00x 00x 00x
<191>8106: mbx VDSL 0: vdsl_mbx_send_direct, 
<191>8107: Writing to msg descriptor: 001E: hdr= E382, 
<191>8108:                 total len= 28, msg len= 28, @28
<191>8109: ipc VDSL 0: vdsl_ipc_send, 
<191>8110: TX: Msg for opcode(16)...waiting for Response from Mailbox!
<191>8111: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 60E : hdr= E002, total len= 244, msg len= 244, @618
<191>8112: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD199C0, len= 244 00x 02x 16x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8113:  00x 00x 00x 00x 00x 00x 01x 00x 00x 00x 00x 4294967221x 00x 66x 68x 67x
<191>8114:  77x 00x 00x 4294967221x 00x 67x 83x 67x 79x 70x 02x 49x 53x 46x 54x 40x
<191>8115:  51x 41x 77x 54x 97x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8116:  00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8117:  00x 00x 70x 67x 90x 49x 56x
<191>8118:  51x 52x 57x 51x 56x 50x 32x 67x 56x 57x 54x 86x 65x 45x 75x 32x
<191>8119:  49x 53x 46x
<191>8120: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD19AB4, len= 244
<191>8121: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 244, 0x1DD199C0
<191>8122: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=16
<191>8123: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x1118C89C opcode=16 to caller
<191>8124: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 16
<191>8125: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
<191>8126: ipc VDSL 0: vdsl_ipc_send, 
<191>8127: TX: Call for opcode 16 Success!
<191>8128: ipc VDSL 0: vdsl_g997_line_inventory_get, 
<191>8129: vdsl_g997_line_inventory_get: Successful Return msg->inv.selftest_result = 0 
<191>8130:  msg->inv.delt_progress_state = 0 
<191>8131:  msg->inv.phyVerStr = B2pvC038v.d24m 
<191>8132:  msg->inv.drvVerStr = 170321_1253-4.02L.03.B2pvC038v.d24m !
<191>8133: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=17, seq = 0, len=28, tx buf @0x1DD199C0, rx buf @0x1DD199C0
<191>8134: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD199C0, rx_len = 36 @0x1DD199C0
<191>8135: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
<191>8136: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 17x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8137:  00x 00x
<191>8138:  00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8139: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0000: hdr= E382, 
<191>8140:                 total len= 28, msg len= 28, @28
<191>8141: ipc VDSL 0: vdsl_ipc_send, 
<191>8142: TX: Msg for opcode(17)...waiting for Response from Mailbox!
<191>8143: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5F0 : hdr= E002, total len= 36, msg len= 36, @618
<191>8144: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD199C0, len= 36 00x 02x 17x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8145:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8146:  00x 00x 01x
<191>8147: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD199E4, len= 36
<191>8148: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 36, 0x1DD199C0
<191>8149: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=17
<191>8150: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x1118C8A8 opcode=17 to caller
<191>8151: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 17
<191>8152: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
<191>8153: ipc VDSL 0: vdsl_ipc_send, 
<191>8154: TX: Call for opcode 17 Success!
<191>8155: ipc VDSL 0: vdsl_g997_atu_systemenabling_status_get, 
<191>8156: vdsl_g997_atu_systemenabling_status_get: Successful Return !
<191>8157: ipc VDSL 0: vdsl_ipc_send, 
<191>8158: IPC Send: msg_type = 2, opcode=20, seq = 0, len=28, tx buf @0x1DD199C0, rx buf @0x1DD199C0
<191>8159: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD199C0, rx_len = 32 @0x1DD199C0
<191>8160: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
<191>8161: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 20x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8162:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8163: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 000A: hdr= E382, 
<191>8164:                 total len= 28, msg len= 28, @28
<191>8165: ipc VDSL 0: vdsl_ipc_send, 
<191>8166: TX: Msg for opcode(20)...waiting for Response from Mailbox!
<191>8167: mbx VDSL 0: vdsl_msg_rcv_isr, 
<191>8168: Desc@ 5FA : hdr= E002, total len= 32, msg len= 32, @618
<191>8169: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD199C0, len= 32 00x 02x 20x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8170:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 03x
<191>8171: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD199E0, len= 32
<191>8172: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 32, 0x1DD199C0
<191>8173: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=20
<191>8174: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x1118C89C opcode=20 to caller
<191>8175: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 20
<191>8176: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
<191>8177: ipc VDSL 0: vdsl_ipc_send, 
<191>8178: TX: Call for opcode 20 Success!
<191>8179: ipc VDSL 0: vdsl_get_line_state, 
<191>8180: vdsl_get_line_state: Successful Return !
<191>8181: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=79, seq = 0, len=28, tx buf @0x1DD199C0, rx buf @0x1DD199C0
<191>8182: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD199C0, rx_len = 56 @0x1DD199C0
<191>8183: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
<191>8184: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 79x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8185:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8186:  00x
<191>8187: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0014: hdr= E382, 
<191>8188:                 total len= 28, msg len= 28, @28
<191>8189: ipc VDSL 0: vdsl_ipc_send, 
<191>8190: TX: Msg for opcode(79)...waiting for Response from Mailbox!
<191>8191: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 604 : hdr= E002, total len= 56, msg len= 56, @618
<191>8192: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD199C0, len= 56 00x 02x 79x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8193:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8194:  00x 00x 00x 00x 00x 00x 01x 67x 79x 70x 02x 07x 00x 46x 54x 40x
<191>8195:  51x 41x 77x 54x 97x 00x 00x
<191>8196: mbx VDSL 0: vdsl_process_msg_rcv, 
<191>8197: Last message (2) : addr= 0x618, dest= 0x1DD199F8, len= 56
<191>8198: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 56, 0x1DD199C0
<191>8199: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=79
<191>8200: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x1118C8A8 opcode=79 to caller
<191>8201: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 79
<191>8202: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
<191>8203: ipc VDSL 0: vdsl_ipc_send, 
<191>8204: TX: Call for opcode 79 Success!
<191>8205: ipc VDSL 0: vdsl_line_status_get, 
<191>8206: vdsl_line_status_get: Successful Return !
<191>8207: ipc VDSL 0: vdsl_ipc_send, 
<191>8208: IPC Send: msg_type = 2, opcode=24, seq = 0, len=28, tx buf @0x1DD199C0, rx buf @0x1DD199C0
<191>8209: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD199C0, rx_len = 64 @0x1DD199C0
<191>8210: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
<191>8211: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 24x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8212:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8213: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 001E: hdr= E382, 
<191>8214:                 total len= 28, msg len= 28, @28
<191>8215: ipc VDSL 0: vdsl_ipc_send, 
<191>8216: TX: Msg for opcode(24)...waiting for Response from Mailbox!
<191>8217: mbx VDSL 0: vdsl_msg_rcv_isr, 
<191>8218: Desc@ 60E : hdr= E002, total len= 64, msg len= 64, @618
<191>8219: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD199C0, len= 64 00x 02x 24x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8220:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 04x 00x
<191>8221:  00x 00x 00x 00x 00x 24x 27x 00x 00x 00x 00x 00x 00x 00x 01x 00x
<191>8222:  00x 00x 00x 00x 00x 00x 29x 00x 00x 00x 00x 00x 00x 00x 03x
<191>8223: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD19A00, len= 64
<191>8224: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 64, 0x1DD199C0
<191>8225: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=24
<191>8226: ipc VDSL 0: vdsl_msg_rcv_handler, 
<191>8227: Rx DSL Msg: enqueue 0x1118C89C opcode=24 to caller
<191>8228: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 24
<191>8229: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
<191>8230: ipc VDSL 0: vdsl_ipc_send, 
<191>8231: TX: Call for opcode 24 Success!
<191>8232: ipc VDSL 0: vdsl_pm_lineinit_counters_total_get, 
<191>8233: vdsl_pm_lineinit_counters_total_get: Successful Return !
<191>8234: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=34, seq = 0, len=28, tx buf @0x1DD199C0, rx buf @0x1DD199C0
<191>8235: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD199C0, rx_len = 36 @0x1DD199C0
<191>8236: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
<191>8237: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 34x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8238:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8239: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0000: hdr= E382, 
<191>8240:                 total len= 28, msg len= 28, @28
<191>8241: ipc VDSL 0: vdsl_ipc_send, 
<191>8242: TX: Msg for opcode(34)...waiting for Response from Mailbox!
<191>8243: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5F0 : hdr= E002, total len= 36, msg len= 36, @618
<191>8244: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD199C0, len= 36 00x 02x 34x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8245:  00x 00x 00x 00x 00x 00x
<191>8246:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8247:  00x 00x 00x
<191>8248: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD199E4, len= 36
<191>8249: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 36, 0x1DD199C0
<191>8250: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=34
<191>8251: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x1118C8A8 opcode=34 to caller
<191>8252: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 34
<191>8253: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
<191>8254: ipc VDSL 0: vdsl_ipc_send, 
<191>8255: TX: Call for opcode 34 Success!
<191>8256: ipc VDSL 0: vdsl_trellis_config_get, 
<191>8257: vdsl_trellis_config_get: Successful Return !
<191>8258: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
<191>8259: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
<191>8260: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
<191>8261: VDSL 0: SM_DSL_NO_SHUT boolean event
<191>8262: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5FA : hdr= E004, total len= 28, msg len= 28, @618
<191>8263: mbx VDSL 0: vdsl_msg_rcv_isr, Notification msg type 4, len= 28
<191>8264: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1E93A140, len= 28 00x 04x 11x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 42x
<191>8265:  4294967242x 55x 16x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8266: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1E93A15C, len= 28
<191>8267: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 4 rx handler, err= 0, len= 28, 0x1E93A140
<191>8268: VDSL 0: Firmare file (flash:VA_B_38V_d24m.bin) header and first 20 payload bytes: 
<191>8269: VDSL 0: 0 
<191>8270: VDSL 0: 
<191>8271: 68 
<191>8272: VDSL 0: 0 
<191>8273: VDSL 0: 1 
<191>8274: VDSL 0: 1 
<191>8275: VDSL 0: A 
<191>8276: VDSL 0: AE 
<191>8277: VDSL 0: 92 
<191>8278: VDSL 0: 0 
<191>8279: VDSL 0: 23 
<191>8280: VDSL 0: 42 
<191>8281: VDSL 0: EA 
<191>8282: VDSL 0: 0 
<191>8283: VDSL 0: 0 
<191>8284: VDSL 0: 0 
<191>8285: VDSL 0: 0 
<191>8286: VDSL 0: 0 
<191>8287: VDSL 0: 0 
<191>8288: VDSL 0: 0 
<191>8289: VDSL 0: 0 
<191>8290: VDSL 0: 80 
<191>8291: VDSL 0: 1 
<191>8292: VDSL 0: 0 
<191>8293: VDSL 0: 0 
<191>8294: VDSL 0: 80 
<191>8295: VDSL 0: 3E 
<191>8296: VDSL 0: 90 
<191>8297: VDSL 0: 0 
<191>8298: VDSL 0: 0 
<191>8299: VDSL 0: 23 
<191>8300: VDSL 0: 42 
<191>8301: VDSL 0: DE 
<191>8302: VDSL 0: 6D 
<191>8303: VDSL 0: 0 
<191>8304: VDSL 0: 0 
<191>8305: VDSL 0: 40 
<191>8306: VDSL 0: 0 
<191>8307: VDSL 0: 14 
<191>8308: VDSL 0: B8 
<191>8309: VDSL 0: 3E 
<191>8310: VDSL 0: firmware file checksum AE92, calculated AE92, len 2342EAfirmware file checksum AE92, calculated AE92, len 2342EA data ptr 0x1285FE58
<191>8311: VDSL 0: fw bin 0x1285FE44 payload 0x1285FE58
<191>8312: VDSL 0: No Fw Mismatch.
<191>8313:     vdsl_daemon_sm VDSL 0: during state adminstate, got event 12(no_shut)
<191>8314: @@@ vdsl_daemon_sm VDSL 0: adminstate -> config
<191>8315: VDSL 0: cfg set mode option dt mode (0)
<191>8316: VDSL 0: cfg set (0 0 0 0 0 0 0 7)
<191>8317: VDSL 0: cfg set sync itu (0)
<191>8318:     vdsl_daemon_sm VDSL 0: during state config, got event 15(ll_cfg)
<191>8319: @@@ vdsl_daemon_sm VDSL 0: config -> config
<191>8320: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=56, seq = 0, len=168, tx buf @0x1DD199C0, rx buf @0x1DD199C0
<191>8321: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 168 @0x1DD199C0, rx_len = 168 @0x1DD199C0
<191>8322: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
<191>8323: mbx VDSL 0: vdsl_mbx_find_free_buf, 
<191>8324: Free len 1480, Addr 00000028, Max size 2960 00x 02x 56x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8325:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 4294967221x 00x 67x 83x 67x
<191>8326:  79x 70x 02x 49x 53x 46x 54x 40x 51x 41x 77x 54x 97x 00x 00x 00x
<191>8327:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8328:  00x 00x 00x 70x 67x 90x 49x 56x 51x 52x 57x 51x 56x 50x 32x 67x
<191>8329:  56x 57x 54x 86x 65x 45x 75x 32x 49x 53x 46x 54x 40x 51x 41x 77x
<191>8330:  54x 97x 00x
<191>8331: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 000A: hdr= E382, 
<191>8332:                 total len= 168, msg len= 168, @28
<191>8333: ipc VDSL 0: vdsl_ipc_send, 
<191>8334: TX: Msg for opcode(56)...waiting for Response from Mailbox!
<191>8335: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 604 : hdr= E002, total len= 168, msg len= 168, @618
<191>8336: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD199C0, len= 168 00x 02x 56x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8337:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 4294967221x 00x 67x 83x 67x
<191>8338:  79x 70x 02x 49x 53x 46x 54x 40x 51x 41x 77x 54x 97x 00x 00x 00x
<191>8339:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8340:  00x 00x 00x 70x 67x 90x 49x 56x 51x 52x 57x 51x 56x 50x 32x 67x
<191>8341:  56x 57x 54x 86x 65x 45x 75x 32x 49x 53x 46x 54x 40x 51x 41x 77x
<191>8342:  54x 97x 00x
<191>8343: mbx VDSL 0: vdsl_process_msg_rcv, 
<191>8344: Last message (2) : addr= 0x618, dest= 0x1DD19A68, len= 168
<191>8345: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 168, 0x1DD199C0
<191>8346: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=56
<191>8347: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x1118C89C opcode=56 to caller
<191>8348: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 56
<191>8349: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
<191>8350: ipc VDSL 0: vdsl_ipc_send, 
<191>8351: TX: Call for opcode 56 Success!
<191>8352: ipc VDSL 0: vdsl_g997_line_inventory_set, 
<191>8353: vdsl_g997_line_inventory_set: Successful Return !
<191>8354: VDSL 0: SM_CFG_SET boolean event
<191>8355: ipc VDSL 0: vdsl_ipc_send, 
<191>8356: IPC Send: msg_type = 2, opcode=80, seq = 0, len=16, tx buf @0x1DD199C0, rx buf @0x1DD199C0
<191>8357: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 16 @0x1DD199C0, rx_len = 16 @0x1DD199C0
<191>8358: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
<191>8359: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 80x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8360: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0014: hdr= E382, 
<191>8361:                 total len= 16, msg len= 16, @28
<191>8362: ipc VDSL 0: vdsl_ipc_send, 
<191>8363: TX: Msg for opcode(80)...waiting for Response from Mailbox!
<191>8364: mbx VDSL 0: vdsl_msg_rcv_isr, 
<191>8365: Desc@ 60E : hdr= E002, total len= 16, msg len= 16, @618
<191>8366: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD199C0, len= 16 00x 02x 80x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8367: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD199D0, len= 16
<191>8368: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 16, 0x1DD199C0
<191>8369: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=80
<191>8370: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x1118C8A8 opcode=80 to caller
<191>8371: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 80
<191>8372: ipc VDSL 0: vdsl_msg_rcv_handler, 
<191>8373: KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
<191>8374: ipc VDSL 0: vdsl_ipc_send, 
<191>8375: TX: Call for opcode 80 Success!
<191>8376: ipc VDSL 0: vdsl_dt_mode_set, 
<191>8377: vdsl_dt_mode_set: Successful Return !
<191>8378: VDSL 0: api (mode option) ret = 0
<191>8379: VDSL 0: SM_CFG_SET boolean event
<191>8380: VDSL 0: system enabling (0 0 0 0 0 0 0 7)
<191>8381: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=54, seq = 0, len=36, tx buf @0x1DD199C0, rx buf @0x1DD199C0
<191>8382: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 36 @0x1DD199C0, rx_len = 36 @0x1DD199C0
<191>8383: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
<191>8384: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 54x 01x 00x 00x 00x 00x 00x 00x
<191>8385:  00x 00x 00x 00x 00x 00x 00x
<191>8386:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8387:  00x 00x 07x
<191>8388: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 001E: hdr= E382, 
<191>8389:                 total len= 36, msg len= 36, @28
<191>8390: ipc VDSL 0: vdsl_ipc_send, 
<191>8391: TX: Msg for opcode(54)...waiting for Response from Mailbox!
<191>8392: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5F0 : hdr= E002, total len= 36, msg len= 36, @618
<191>8393: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD199C0, len= 36 00x 02x 54x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8394:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8395:  00x 00x 07x
<191>8396: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD199E4, len= 36
<191>8397: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 36, 0x1DD199C0
<191>8398: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=54
<191>8399: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x1118C89C opcode=54 to caller
<191>8400: ipc VDSL 0: vdsl_msg_rcv_handler, RX: Notify Waiting Process for opcode = 54
<191>8401: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
<191>8402: ipc VDSL 0: vdsl_ipc_send, 
<191>8403: TX: Call for opcode 54 Success!
<191>8404: ipc VDSL 0: vdsl_g997_atu_systemenabling_config_set, 
<191>8405: vdsl_g997_atu_systemenabling_config_set: Successful Return !
<191>8406: VDSL 0: 
<191>8407: api (sys enabling) ret = 0
<191>8408: VDSL 0: SM_CFG_SET boolean event
<191>8409: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=81, seq = 0, len=20, tx buf @0x1DD199C0, rx buf @0x1DD199C0
<191>8410: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 20 @0x1DD199C0, rx_len = 20 @0x1DD199C0
<191>8411: mbx VDSL 0: vdsl_mbx_find_free_buf, Used Start 0028, Used End 0028
<191>8412: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 81x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8413:  00x 00x 00x
<191>8414: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 0000: hdr= E382, 
<191>8415:                 total len= 20, msg len= 20, @28
<191>8416: ipc VDSL 0: vdsl_ipc_send, 
<191>8417: TX: Msg for opcode(81)...waiting for Response from Mailbox!
<191>8418: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5FA : hdr= E002, total len= 20, msg len= 20, @618
<191>8419: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD199C0, len= 20 00x 02x 81x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8420:  00x 00x 00x
<191>8421: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD199D4, len= 20
<191>8422: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 20, 0x1DD199C0
<191>8423: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=81
<191>8424: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x1118C8A8 opcode=81 to caller
<191>8425: ipc VDSL 0: vdsl_msg_rcv_handler, 
<191>8426: RX: Notify Waiting Process for opcode = 81
<191>8427: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
<191>8428: ipc VDSL 0: vdsl_ipc_send, 
<191>8429: TX: Call for opcode 81 Success!
<191>8430: ipc VDSL 0: vdsl_sync_cmd_set, 
<191>8431: vdsl_sync_cmd_set: Successful Return !
<191>8432: VDSL 0: api (sync set) ret = 0
<191>8433:     vdsl_daemon_sm VDSL 0: during state config, got event 16(line_activation)
<191>8434: @@@ vdsl_daemon_sm VDSL 0: config -> training
<191>8435: ipc VDSL 0: vdsl_ipc_send, IPC Send: msg_type = 2, opcode=8, seq = 0, len=28, tx buf @0x1DD199C0, rx buf @0x1DD199C0
<191>8436: mbx VDSL 0: vdsl_msg_send, type= 2, tx_len= 28 @0x1DD199C0, rx_len = 28 @0x1DD199C0
<191>8437: mbx VDSL 0: vdsl_mbx_find_free_buf, 
<191>8438: Used Start 0028, Used End 0028
<191>8439: mbx VDSL 0: vdsl_mbx_find_free_buf, Free len 1480, Addr 00000028, Max size 2960 00x 02x 08x 01x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8440:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8441: mbx VDSL 0: vdsl_mbx_send_direct, Writing to msg descriptor: 000A: hdr= E382, 
<191>8442:                 total len= 28, msg len= 28, @28
<191>8443: ipc VDSL 0: vdsl_ipc_send, 
<191>8444: TX: Msg for opcode(8)...waiting for Response from Mailbox!
<191>8445: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 604 : hdr= E002, total len= 28, msg len= 28, @618
<191>8446: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1DD199C0, len= 28 00x 02x 08x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8447:  00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8448: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1DD199DC, len= 28
<191>8449: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 2 rx handler, err= 0, len= 28, 0x1DD199C0
<191>8450: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Type Msg: opcode=8
<191>8451: ipc VDSL 0: vdsl_msg_rcv_handler, Rx DSL Msg: enqueue 0x1118C89C opcode=8 to caller
<191>8452: ipc VDSL 0: vdsl_msg_rcv_handler, 
<191>8453: RX: Notify Waiting Process for opcode = 8
<191>8454: ipc VDSL 0: vdsl_msg_rcv_handler, KEEPALIVE Msg to VDSL Daemon from DSL Msg Handler
<191>8455: ipc VDSL 0: vdsl_ipc_send, 
<191>8456: TX: Call for opcode 8 Success!
<191>8457: ipc VDSL 0: vdsl_line_activate, 
<191>8458: vdsl_line_activate: Successful Return !
<191>8459: VDSL 0: api (line activation) ret = 0
<191>8460: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
<191>8461: ipc VDSL 0: vdsl_notif_interrupt, Sending LINE_STATE to VDSL Daemon, state = 8
<191>8462: VDSL 0: vdsl line state : discovery
<191>8463: VDSL 0: SM_LINE_TRAIN boolean event
<191>8464:     vdsl_daemon_sm VDSL 0: during state training, got event 17(line_training)
<191>8465: @@@ vdsl_daemon_sm VDSL 0: training -> training
<191>8466: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
<191>8467: ipc VDSL 0: vdsl_notif_interrupt, Sending LINE_STATE to VDSL Daemon, state = 7
<191>8468: VDSL 0: vdsl line state : fullinit
<191>8469: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
<191>8470: VDSL 0: SM_LINE_DOWN boolean event
<191>8471: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 60E : hdr= E004, total len= 28, msg len= 28, @618
<191>8472: mbx VDSL 0: vdsl_msg_rcv_isr, Notification msg type 4, len= 28
<191>8473: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1E93A140, len= 28 00x 04x 11x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 42x
<191>8474:  4294967242x 55x 16x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8475: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1E93A15C, len= 28
<191>8476: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 4 rx handler, err= 0, len= 28, 0x1E93A140
<191>8477: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
<191>8478: ipc VDSL 0: vdsl_notif_interrupt, Sending LINE_STATE to VDSL Daemon, state = 8
<191>8479: VDSL 0: vdsl line state : discovery
<191>8480: VDSL 0: SM_LINE_TRAIN boolean event
<191>8481:     vdsl_daemon_sm VDSL 0: during state training, got event 17(line_training)
<191>8482: @@@ vdsl_daemon_sm VDSL 0: training -> training
<191>8483: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
<191>8484: ipc VDSL 0: vdsl_notif_interrupt, Sending LINE_STATE to VDSL Daemon, state = 7
<191>8485: VDSL 0: vdsl line state : fullinit
<191>8486: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
<191>8487: VDSL 0: SM_LINE_DOWN boolean event
<191>8488: ipc VDSL 0: vdsl_notif_interrupt, Sending LINE_STATE to VDSL Daemon, state = 8
<191>8489: VDSL 0: vdsl line state : discovery
<191>8490: VDSL 0: SM_LINE_TRAIN boolean event
<191>8491:     vdsl_daemon_sm VDSL 0: during state training, got event 17(line_training)
<191>8492: @@@ vdsl_daemon_sm VDSL 0: training -> training
<191>8493: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5F0 : hdr= E004, total len= 28, msg len= 28, @618
<191>8494: mbx VDSL 0: vdsl_msg_rcv_isr, Notification msg type 4, len= 28
<191>8495: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1E93A140, len= 28 00x 04x 11x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 42x
<191>8496:  4294967242x 55x 16x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8497: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1E93A15C, len= 28
<191>8498: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 4 rx handler, err= 0, len= 28, 0x1E93A140
<191>8499: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
<191>8500: ipc VDSL 0: vdsl_notif_interrupt, Sending LINE_STATE to VDSL Daemon, state = 7
<191>8501: VDSL 0: vdsl line state : fullinit
<191>8502: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
<191>8503: VDSL 0: SM_LINE_DOWN boolean event
<191>8504: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
<191>8505: ipc VDSL 0: vdsl_notif_interrupt, Sending LINE_STATE to VDSL Daemon, state = 8
<191>8506: VDSL 0: vdsl line state : discovery
<191>8507: VDSL 0: SM_LINE_TRAIN boolean event
<191>8508:     vdsl_daemon_sm VDSL 0: during state training, got event 17(line_training)
<191>8509: @@@ vdsl_daemon_sm VDSL 0: training -> training
<191>8510: mbx VDSL 0: vdsl_msg_rcv_isr, Desc@ 5FA : hdr= E004, total len= 28, msg len= 28, @618
<191>8511: mbx VDSL 0: vdsl_msg_rcv_isr, Notification msg type 4, len= 28
<191>8512: mbx VDSL 0: vdsl_process_msg_rcv, First message (1) : addr= 0x618, dest= 0x0x1E93A140, len= 28 00x 04x 11x 02x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 00x 42x
<191>8513:  4294967242x 55x 16x 00x 00x 00x 00x 00x 00x 00x 00x
<191>8514: mbx VDSL 0: vdsl_process_msg_rcv, Last message (2) : addr= 0x618, dest= 0x1E93A15C, len= 28
<191>8515: mbx VDSL 0: vdsl_msg_rcv_complete, call msg 4 rx handler, err= 0, len= 28, 0x1E93A140
<191>8516: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
<191>8517: ipc VDSL 0: vdsl_notif_interrupt, Sending LINE_STATE to VDSL Daemon, state = 7
<191>8518: VDSL 0: vdsl line state : fullinit
<191>8519: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE
<191>8520: VDSL 0: SM_LINE_DOWN boolean event
<191>8521: ipc VDSL 0: vdsl_notif_interrupt, Sending LINE_STATE to VDSL Daemon, state = 8
<191>8522: VDSL 0: vdsl line state : discovery
<191>8523: VDSL 0: SM_LINE_TRAIN boolean event
<191>8524:     vdsl_daemon_sm VDSL 0: during state training, got event 17(line_training)
<191>8525: @@@ vdsl_daemon_sm VDSL 0: training -> training
<191>8526: ipc VDSL 0: vdsl_mbx_interrupt_handler, Interrupt: KEEP_ALIVE 

Schon mal danke im Voraus für Hinweise.

Content-ID: 643969

Url: https://administrator.de/contentid/643969

Ausgedruckt am: 21.11.2024 um 16:11 Uhr

tikayevent
tikayevent 23.01.2021 aktualisiert um 19:47:25 Uhr
Goto Top
Kommt er gar nicht hoch oder braucht es einfach nur mehrere Versuche? Kommt ein non-Cisco-Gerät am Anschluss hoch und online, wenn ja, in wie vielen Versuchen?
santonio
santonio 23.01.2021 aktualisiert um 19:48:08 Uhr
Goto Top
Die Fritzbox 7590 wählt sich ohne Probleme ein. Bei beiden Cisco Routern dauert es vielleicht 30 Sekunden nach Einstecken des Kabels, beide wählen sich nur einmal kurz ein (kurz auf UP) und fallen dann dauerhaft zurück zu DOWN.
tikayevent
tikayevent 23.01.2021 um 19:51:02 Uhr
Goto Top
Bei der Fritzbox ist es ja ein anderes Kabel, weil am Cisco braucht man ja einen 6P4C (vulgo RJ11) oder 6P2C, bei der Fritzbox ist der DSL-Anschluss ja ein 8P8C (vulgo RJ45). Bist du dir sicher, dass das Kabel die richtige Belegung hat? Weil der Cisco macht laut Debug ein fullinit und danach ist die Leitung wieder down.

Normal wird von Cisco ja ein lavendelfarbenes Kabel von 8P2C auf 6P2C mitgeliefert.
santonio
santonio 23.01.2021 um 19:59:20 Uhr
Goto Top
Ja, irgendwie hab ich das auch in Verdacht... Ich hab zwei ältere Telefonkabel angeschlossen, könnte auch sein, dass beide die falsche Belegung haben...

Dumm nur, ich hab das original Cisco-Kabel irgendwo in meinem S**stall verlegt, meinen Kabelprüfer auch... Da hilft wohl nur suchen und aufräumen...;) schon mal Danke für den Hinweis!
aqui
aqui 23.01.2021, aktualisiert am 24.01.2021 um 10:33:14 Uhr
Goto Top
und in den "Modem Status: TC Sync (Showtime!)"
Zeigt ja das physisch auf dem Layer 1 alles OK ist und Router und DSLAM sich "sehen".

Vermutlich scheitert danach die PPPoE Negotiation an 2 möglichen Dingen:
  • Defektes Anschlusskabel
  • Falsches oder fehlerhaftes VLAN Tagging auf dem VDSL Interface
  • Falsche oder fehlerhafte PPPoE Credentials
Gut möglich das Easybell auch wie Vodafone CHAP statt PAP nutzt dann musst du die Dialer Konfig anpassen. (Siehe Cisco_Tutorial):
!
interface Dialer0
description xDSL Einwahl Interface Vodafone
ip address negotiated
...
ppp authentication chap pap callin
ppp chap hostname vodafone-vdsl.komplett/vb123543
ppp chap password Geheim123
ppp pap sent-username vodafone-vdsl.komplett/vb123543 password Geheim123
...
!

Musst du checken mit dem Debugger.
Auf alle Fälle gilt: Was die FritzBox kann, kann der Cisco schon lange... face-wink

Gut, fehlerhafte Kabel wären auch ein möglicher Grund. Der Cisco nutzt Center Pinnig auf dem RJ-11 Stecker, also die beiden mittleren Pins. Darauf musst du achten.
Aber ein fehlerhaftes Kabel würde schon den Layer 1 scheitern lassen das es meist dann gar nicht erst zum "Modem Status: TC Sync (Showtime!)" kommt.
tikayevent
Lösung tikayevent 23.01.2021 um 20:08:52 Uhr
Goto Top
Wenn der TAE-Stecker in der Dose steckt, müssen es links die beiden unteren Pins sein und auf anderen Seite die beiden mittleren Pins. Wenn der TAE-Stecker mehr Kontakte hat, schau dir die Farben des RJ11 an, die mittleren beiden brauchst du, dann öffnest du den TAE-Stecker (das Steckergehäuse hinten festhalten und den Kontakteinsatz vorne etwas verdrehen, dann springt das Gehäuse fast immer auf). Und dann einfach die Kontakte aus dem Kontakteinsatz rausziehen und die beiden Kontakte mit den passenden Farben auf die oben genannten Positionen packen, die anderen Kontakte weglassen.

Alte Telefonkabel sind immer Mist. Heute passt es halbwegs, aber früher gabs da ein Chaos. Bei den von der Telekom vertriebenen Geräten musste man immer aufpassen, dass man das passende Kabel dazu hatte, weil die Belegung auf dem RJ11 fast immer herstellerspezifisch war. Aber es gab auch bei Karstadt früher Telefone, die nur mit dem beiliegenden Kabel funktionierten. Da musste das Telefonsigal auf dem Stecker zweimal vorhanden sein.
tikayevent
Lösung tikayevent 23.01.2021 aktualisiert um 20:12:31 Uhr
Goto Top
Aber ein fehlerhaftes Kabel würde schon den Layer 1 scheitern lassen das es meist dann gar nicht erst zum "Modem Status: TC Sync (Showtime!)" kommt.
Falsch: Du brauchst für DSL keinen geschlossenen Stromkreis. DSL ist effektiv ein Funksignal, was dem Kabel folgt. Ich hatte schon Anschlüsse, die im Amt falsch beschaltet waren (ein Pin verrutscht in der Leiste) und die kamen hoch. Ein ISDNer dagegen nicht, weil die einen geschlossenen Stromkreis brauchen. Aus dem Grund auch niemals 3M Scotchlok für VDSL-Leitungen verwenden, das Kabel muss so geradlinig wie möglich laufen, mit der 180°-Wende in einem Scotchlok holt man sich massive Verluste in die Leitung.

Genau aus dem Grund funktioniert ja auch Vectoring. Es wird ja ein Gegensignal berechnet, um die Störungen zu minimieren.
santonio
santonio 23.01.2021 aktualisiert um 23:02:49 Uhr
Goto Top
Hi,
erstmal vielen Dank an Euch beide. Es war tatsächlich das Kabel bzw. die Steckerbelegung im TAE. Ich hab auf Deine Empfehlung etwas rumgebastelt und den TAE neu belegt... et voila es läuft!

Ich hatte schon die ganze Zeit Layer 1 in Verdacht und tatsächlich drei Telefonkabel bereits ausprobiert aber an die Belegung hatte ich nicht gedacht. Ich hatte mehr so Inkompatibilitäten mit dem DSLAM in Verdacht... Am Ende ist es halt das Kabel (banal wie so meist).

PPP hab ich vorab ausgeschlossen, da über einen debug auch nichts gesehen hab (hierzu hatte ich allerdings nichts beschrieben). Und ja, auch wenn die PPP-Authentifizierung fehlschlägt, dann bleibt der VDSL0 UP (hab es ausprobiert). Schön nach Lehrplan wie im OSI-Modell ;)

Wünsche allerseits ein schönes Wochenende ;)
aqui
Lösung aqui 24.01.2021 um 10:31:41 Uhr
Goto Top
Oder gleich zur Sicherheit ein paar neue Kabel auf Halde legen !! face-wink
https://www.reichelt.de/tae-anschlusskabel-f-stecker-modular-stecker-3-m ...
support-m
support-m 25.01.2021 um 13:03:35 Uhr
Goto Top
Zitat von @tikayevent:

Aus dem Grund auch niemals 3M Scotchlok für VDSL-Leitungen verwenden, das Kabel muss so geradlinig wie möglich laufen, mit der 180°-Wende in einem Scotchlok holt man sich massive Verluste in die Leitung.

Ich muss hiermit kurz den Thread entführen und wollte mich nur kurz für deinen Kommentar bedanken. Das erklärt vermutlich ein Problem bei einem Kunden, das ich seit Monaten nicht gelöst bekommen habe...
Im einem Hotel habe ich den Standort des Modemrouters geändert und ein vorhandenes Netzwerkkabel dafür "missbraucht". Die Einwahl hat auch funktioniert, aber die DSL-Geschinwidigkeit war nur etwa 60% der vertraglichen Geschwindigkeit.

Die Telefonleitung endet in einem Telefonverteiler in einem kleinen Nebenschrank. Von dort lag eben das vorkonfektioniertes Netzwerkkabel zum eigentlichen Zielort. Ich weiß leider nicht mehr warum, aber ich musste das Netzwerkkabel durchtrennen und mit einer Telefonleitung eben mit einem Scotchlok verbinden.

Hast du mir einen Tipp, wie ich das dann korrekt verbinden könnte? Gibt es dafür irgendetwas "gutes"? Oder muss dafür extra eine neue Leitung gezogen werden?

Vielen Dank
tikayevent
tikayevent 25.01.2021 aktualisiert um 14:34:43 Uhr
Goto Top
Die Leitung einfach nach alter Väter Sitte spleißen

https://de.wikipedia.org/wiki/Splei%C3%9Fen_(Fernmeldetechnik)

Zur Sicherheit noch zusammenlöten.

Das Problem bei dir dürfte aber eher sein, dass du die Leitungart wechselst. Telekommunikation wird für den Betrieb auf J2Y(St)Y ausgelegt, jede andere Kabelart, egal ob das Baumarkt-Telefonkabel oder ein Netzwerkkabel hat andere Werte, die tödlich sein könnten.
Bei VDSL hast du auch noch das Längenproblem. Wir reden hier nur von wenigen hundert Metern, die zwischen MSAN und Modem sein dürfen. Ab 300m Leitungslänge ist jeder Meter mehr zuviel.
aqui
aqui 25.01.2021 aktualisiert um 16:20:18 Uhr
Goto Top
Du kannst einen Lötkolben nehmen und Schrumpfschlauch um die beiden Telefon Klingeldrähte zu verbinden. Das wäre (spleiß)technisch gesehen das Beste. Ansonsten einen Klemmverbinder oder ganz böse...Lüsterklemmen. Zum Rest hat Kollege @tikayevent oben ja schon alles gesagt.