Some INNOLIGHT 800G QSFP-DDs get stuck in CMIS DP_INIT intermittently

[dgodwin-nokia]

Some INNOLIGHT 800G QSFP-DDs get stuck in CMIS DP_INIT intermittently. After DP_INIT timeout happens, the transceiver will be permanently DOWN. This happens about half of the time on these QSFP-DDs. Found that these transceivers seem to have an issue with the current implementation of decommission_all_datapaths() in cmis.py.

decommission_all_datapaths() is called when the current application does not match to target application for the transceiver. Currently, it will call DEINIT, set the app ID to 0 (unused), and call INIT in one function without waiting for success. I am not sure if this is good as per the CMIS specificattion, but these transceivers do not behave well in this case:

'
def decommission_all_datapaths(self):
'''
Return True if all datapaths are successfully de-commissioned, False otherwise
'''
# De-init all datpaths
self.set_datapath_deinit((1 << self.NUM_CHANNELS) - 1)
# Decommision all lanes by apply AppSel=0
self.set_application(((1 << self.NUM_CHANNELS) - 1), 0, 0)
# Start with AppSel=0 i.e undo any default AppSel
self.scs_apply_datapath_init((1 << self.NUM_CHANNELS) - 1)

    dp_state = self.get_datapath_state()
    config_state = self.get_config_datapath_hostlane_status()

    for lane in range(self.NUM_CHANNELS):
        name = "DP{}State".format(lane + 1)
        if dp_state[name] != 'DataPathDeactivated':
            return False
        
        name = "ConfigStatusLane{}".format(lane + 1)
        if config_state[name] != 'ConfigSuccess':
            return False

    return True

'

These INNOLIGHT 800G QSFP-DDs will always succeed INIT and come up if the above function is modified so that a delay is added after DEINIT and INIT to wait for success. However, since this function is called inline in the CMIS state machine in xcvrd, a blocking wait should not be added here.
 
An example log from pmon when the issue occurs:

2024 Dec 7 03:50:57.965147 uber NOTICE pmon#xcvrd[34]: CMIS: Ethernet184: 800G, lanemask=0xff, CMIS state=INSERTED, Module state=ModuleReady, DP state={'DP1State': 'DataPathDeactivated', 'DP2State': 'DataPathDeactivated', 'DP3State': 'DataPathDeactivated', 'DP4State': 'DataPathDeactivated', 'DP5State': 'DataPathDeactivated', 'DP6State': 'DataPathDeactivated', 'DP7State': 'DataPathDeactivated', 'DP8State': 'DataPathDeactivated'}, appl 3 host_lane_count 8 retries=3
2024 Dec 7 03:50:57.976291 uber NOTICE pmon#xcvrd[34]: CMIS: Ethernet184: Setting appl=3
2024 Dec 7 03:50:57.986922 uber NOTICE pmon#xcvrd[34]: CMIS: Ethernet184: Setting host_lanemask=0xff
2024 Dec 7 03:50:58.008685 uber NOTICE pmon#xcvrd[34]: CMIS: Ethernet184: Setting media_lanemask=0xff
2024 Dec 7 03:50:58.062208 uber NOTICE pmon#xcvrd[34]: CMIS: Ethernet184: force Datapath reinit
2024 Dec 7 03:50:59.102274 uber NOTICE pmon#xcvrd[34]: CMIS: Ethernet184: 800G, lanemask=0xff, CMIS state=DP_DEINIT, Module state=ModuleReady, DP state={'DP1State': 'DataPathDeactivated', 'DP2State': 'DataPathDeactivated', 'DP3State': 'DataPathDeactivated', 'DP4State': 'DataPathDeactivated', 'DP5State': 'DataPathDeactivated', 'DP6State': 'DataPathDeactivated', 'DP7State': 'DataPathDeactivated', 'DP8State': 'DataPathDeactivated'}, appl 3 host_lane_count 8 retries=3
2024 Dec 7 03:50:59.126514 uber NOTICE pmon#xcvrd[34]: CMIS: Ethernet184: DpDeinit duration 1.0 secs, modulePwrUp duration 10.0 secs
2024 Dec 7 03:51:00.166925 uber NOTICE pmon#xcvrd[34]: CMIS: Ethernet184: 800G, lanemask=0xff, CMIS state=AP_CONFIGURED, Module state=ModuleReady, DP state={'DP1State': 'DataPathDeactivated', 'DP2State': 'DataPathDeactivated', 'DP3State': 'DataPathDeactivated', 'DP4State': 'DataPathDeactivated', 'DP5State': 'DataPathDeactivated', 'DP6State': 'DataPathDeactivated', 'DP7State': 'DataPathDeactivated', 'DP8State': 'DataPathDeactivated'}, appl 3 host_lane_count 8 retries=3
...
...
...
2024 Dec 7 03:51:09.654936 uber NOTICE pmon#xcvrd[34]: CMIS: Ethernet184: 800G, lanemask=0xff, CMIS state=DP_INIT, Module state=ModuleReady, DP state={'DP1State': 'DataPathDeactivated', 'DP2State': 'DataPathDeactivated', 'DP3State': 'DataPathDeactivated', 'DP4State': 'DataPathDeactivated', 'DP5State': 'DataPathDeactivated', 'DP6State': 'DataPathDeactivated', 'DP7State': 'DataPathDeactivated', 'DP8State': 'DataPathDeactivated'}, appl 3 host_lane_count 8 retries=3
2024 Dec 7 03:51:09.657384 uber NOTICE pmon#xcvrd[34]: CMIS: Ethernet184: timeout for 'ConfigSuccess'
2024 Dec 7 03:51:10.687747 uber NOTICE pmon#xcvrd[34]: CMIS: Ethernet184: 800G, lanemask=0xff, CMIS state=INSERTED, Module state=ModuleReady, DP state={'DP1State': 'DataPathDeactivated', 'DP2State': 'DataPathDeactivated', 'DP3State': 'DataPathDeactivated', 'DP4State': 'DataPathDeactivated', 'DP5State': 'DataPathDeactivated', 'DP6State': 'DataPathDeactivated', 'DP7State': 'DataPathDeactivated', 'DP8State': 'DataPathDeactivated'}, appl 3 host_lane_count 8 retries=4
2024 Dec 7 03:51:10.687747 uber ERR pmon#xcvrd[34]: CMIS: Ethernet184: FAILED

 
Observed this behavior on the following PNs:

Vendor PN: T-DP8CNH-NNO
Vendor PN: T-DP8CNT-NNO

[dgodwin-nokia]

@prgeor @vdahiya12 I saw this code was originally added for sonic-net/sonic-platform-common#471.

Was wondering if you had any ideas on whether this should be seen as a transceiver bug or decommission_all_datapaths() bug?

[bingwang-ms]

@prgeor Can you help take a look?

[dgodwin-nokia]

I added some code to wait inline for datapathdeactivated/configsuccess. After these changes, I no longer see the issue. Note that for these transceivers it takes ~150-200ms to exit with success in decommission_all_datapaths.

This is a syncronous wait. It might be better to add additional waits inside the CMIS state machine in xcvrd directly, but this is a smaller change.
 
dgodwin-nokia/sonic-platform-common@8b7f267

[vivekrnv]

Issue is also observed on following NVIDIA cable: MMS4X00-NS-T and this fix solves the problem

<Before the WA>
2025 Mar 11 16:45:52.078630 sonic NOTICE pmon#xcvrd[80]: CMIS: Ethernet482: Decommissioning all lanes/datapaths to default AppSel=0
2025 Mar 11 16:45:52.111026 sonic NOTICE pmon#xcvrd[80]: CMIS: Ethernet482: Failed to default to AppSel=0
2025 Mar 11 16:48:27.700188 sonic NOTICE pmon#xcvrd[80]: CMIS: Ethernet482: timeout for 'ConfigSuccess'
2025 Mar 11 16:48:31.135982 sonic ERR pmon#xcvrd[80]: CMIS: Ethernet482: FAILED

<After the WA>
2025 Mar 11 17:54:48.477836 sonic NOTICE pmon#xcvrd[80]: CMIS: Ethernet480: Decommissioning all lanes/datapaths to default AppSel=0
2025 Mar 11 17:54:48.974644 sonic NOTICE pmon#xcvrd[80]: CMIS: Ethernet480: force Datapath reinit

[prgeor]

ack. I am looking into this.

[prgeor]

@vivekrnv @dgodwin-nokia can you tell me how much is the advertised DP deinit time for your module?

[dgodwin-nokia]

@vivekrnv @dgodwin-nokia can you tell me how much is the advertised DP deinit time for your module?

Hi Prince, the advertised deinit/init values for the INNOLIGHT PNs that have this issue are:

    Upper page 1h

....
00000090 68 e1 46 00 00 00 9d 18 00 fc 77 3a 06 06 06 0f |h.F.......w:....|
....

DPDeinit: 0x6 = 500 ms <= Tstate < 1 s
DPInit: 0x8 = 5 s <= Tstate < 10 s

[vivekrnv]

@vivekrnv @dgodwin-nokia can you tell me how much is the advertised DP deinit time for your module?

Hi @prgeor,

Upper page 1h
00000080 2e 96 a1 00 01 00 00 00  00 00 66 6c 05 14 24 00 |..........fl..$.|
00000090 79 20 46 00 00 00 9d 18  00 20 74 12 02 0e 06 03 |y F...... t.....|

DPDeinit: 0x7: 1 s <= Tstate < 5 s
DPInit: 0x9: 10 s <= Tstate < 1 min

[AnoopKamath]

Started working on this.

[liat-grozovik]

@AnoopKamath can you please share status or ETA for the fix to be avaialble?

[AnoopKamath]

@AnoopKamath can you please share status or ETA for the fix to be avaialble?

@liat-grozovik : I have changes ready and UT done. Will create a PR by 04/22.

[AnoopKamath]

Draft PR link : sonic-net/sonic-platform-daemons#608