Port does not come up if xcvr is inserted after speed change

[ysmanman]

Is it platform specific

generic

Importance or Severity

Critical

Description of the bug

We applied a config patch to bring up a 400G admin-down port - Ethernet16 - to 100G admin-up before inserting xcvr. The port couldn't came up after xcvr being inserted. It came up after we flapped the admin status of the port.

This is the syslog after xcver insertion

2025 Dec  4 00:41:58.154549 cmp329-6 NOTICE pmon#xcvrd: Ethernet16: Got SFP inserted event
2025 Dec  4 00:41:58.154792 cmp329-6 NOTICE pmon#xcvrd: Ethernet16: received plug in and update port sfp status table.
2025 Dec  4 00:41:58.205526 cmp329-6 WARNING pmon#xcvrd: SFF-PORT-UPDATE: $$$ Ethernet16 handle_port_update_event() : op=SET DB:STATE_DB Table:TRANSCEIVER_INFO fvp {'application_advertisement': 'N/A', 'ext_rateselect_compliance': 'Rate Select Version 2', 'encoding': '256B/257B (transcoded FEC-enabled data)', 'nom\
inal_bit_rate': '255', 'specification_compliance': "{'10/40G Ethernet Compliance Code': 'Extended', 'SONET Compliance Codes': 'Unknown', 'SAS/SATA Compliance Codes': 'Unknown', 'Gigabit Ethernet Compliant Codes': 'Unknown', 'Fibre Channel Link Length': 'Unknown', 'Fibre Channel Transmitter Technology': 'Unknown',\
 'Fibre Channel Transmission Media': 'Unknown', 'Fibre Channel Speed': 'Unknown', 'Extended Specification Compliance': '100G PSM4 Parallel SMF'}", 'connector': 'MPO 1x12', 'cable_type': 'Length(km)', 'model': 'QSFP-100G-PSM4  ', 'type': 'QSFP28 or later', 'vendor_rev': '20', 'ext_identifier': 'Power Class 4 Modul\
e (3.5W max.), No CLEI code present in Page 02h, CDR present in TX, CDR present in RX', 'cable_length': '1.0', 'manufacturer': 'Arista Networks ', 'vendor_date': '2016-08-23   ', 'serial': 'XCK163400002    ', 'dom_capability': 'N/A', 'vendor_oui': '00-1c-73', 'is_replaceable': 'True'}
2025 Dec  4 00:41:58.205526 cmp329-6 WARNING pmon#xcvrd: SFF-PORT-UPDATE: *** ('Ethernet16', 'STATE_DB', 'TRANSCEIVER_INFO') handle_port_update_event() fvp {'type': 'QSFP28 or later', 'index': '-1', 'port_name': 'Ethernet16', 'asic_id': 0, 'op': 'SET'}
2025 Dec  4 00:41:58.205680 cmp329-6 NOTICE pmon#xcvrd: SFF-MAIN: Ethernet16: xcvr=present(inserted=True), host_tx_ready=true(changed=False), admin_status=up(changed=False)
2025 Dec  4 00:41:58.205989 cmp329-6 WARNING pmon#xcvrd: $$$ Ethernet16 handle_port_update_event() : op=SET DB:STATE_DB Table:TRANSCEIVER_INFO fvp {'application_advertisement': 'N/A', 'ext_rateselect_compliance': 'Rate Select Version 2', 'encoding': '256B/257B (transcoded FEC-enabled data)', 'nominal_bit_rate': '\
255', 'specification_compliance': "{'10/40G Ethernet Compliance Code': 'Extended', 'SONET Compliance Codes': 'Unknown', 'SAS/SATA Compliance Codes': 'Unknown', 'Gigabit Ethernet Compliant Codes': 'Unknown', 'Fibre Channel Link Length': 'Unknown', 'Fibre Channel Transmitter Technology': 'Unknown', 'Fibre Channel T\
ransmission Media': 'Unknown', 'Fibre Channel Speed': 'Unknown', 'Extended Specification Compliance': '100G PSM4 Parallel SMF'}", 'connector': 'MPO 1x12', 'cable_type': 'Length(km)', 'model': 'QSFP-100G-PSM4  ', 'type': 'QSFP28 or later', 'vendor_rev': '20', 'ext_identifier': 'Power Class 4 Module (3.5W max.), No\
 CLEI code present in Page 02h, CDR present in TX, CDR present in RX', 'cable_length': '1.0', 'manufacturer': 'Arista Networks ', 'vendor_date': '2016-08-23   ', 'serial': 'XCK163400002    ', 'dom_capability': 'N/A', 'vendor_oui': '00-1c-73', 'is_replaceable': 'True'}
2025 Dec  4 00:41:58.206034 cmp329-6 WARNING pmon#xcvrd: *** ('Ethernet16', 'STATE_DB', 'TRANSCEIVER_INFO') handle_port_update_event() fvp {'application_advertisement': 'N/A', 'ext_rateselect_compliance': 'Rate Select Version 2', 'encoding': '256B/257B (transcoded FEC-enabled data)', 'nominal_bit_rate': '255', 's\
pecification_compliance': "{'10/40G Ethernet Compliance Code': 'Extended', 'SONET Compliance Codes': 'Unknown', 'SAS/SATA Compliance Codes': 'Unknown', 'Gigabit Ethernet Compliant Codes': 'Unknown', 'Fibre Channel Link Length': 'Unknown', 'Fibre Channel Transmitter Technology': 'Unknown', 'Fibre Channel Transmiss\
ion Media': 'Unknown', 'Fibre Channel Speed': 'Unknown', 'Extended Specification Compliance': '100G PSM4 Parallel SMF'}", 'connector': 'MPO 1x12', 'cable_type': 'Length(km)', 'model': 'QSFP-100G-PSM4  ', 'type': 'QSFP28 or later', 'vendor_rev': '20', 'ext_identifier': 'Power Class 4 Module (3.5W max.), No CLEI co\
de present in Page 02h, CDR present in TX, CDR present in RX', 'cable_length': '1.0', 'manufacturer': 'Arista Networks ', 'vendor_date': '2016-08-23   ', 'serial': 'XCK163400002    ', 'dom_capability': 'N/A', 'vendor_oui': '00-1c-73', 'is_replaceable': 'True', 'index': '-1', 'port_name': 'Ethernet16', 'asic_id': \
0, 'op': 'SET'}
2025 Dec  4 00:41:58.245705 cmp329-6 ERR pmon#xcvrd: Get value by key from STATE_DB: Unable to find key NPU_SI_SETTINGS_SYNC_STATUS state_port_table_fvs_dict {'host_tx_ready': 'true', 'state': 'ok', 'netdev_oper_status': 'down', 'admin_status': 'up', 'mtu': '9100', 'supported_speeds': '40000,100000,200000', 'supp\
orted_fecs': 'none,rs'} for lport Ethernet16
2025 Dec  4 00:41:58.245961 cmp329-6 NOTICE pmon#xcvrd: Retrieving media settings for port Ethernet16 speed 100000 num_lanes 4, using key {'vendor_key': 'ARISTA NETWORKS -QSFP-100G-PSM4  ', 'media_key': 'QSFP28-100G PSM4 Parallel SMF-M', 'lane_speed_key': 'speed:25G', 'medium_lane_speed_key': 'OPTICAL25000'}
2025 Dec  4 00:41:58.246009 cmp329-6 NOTICE pmon#xcvrd: Publishing ASIC-side SI setting for port Ethernet16 in APP_DB:
2025 Dec  4 00:41:58.247086 cmp329-6 NOTICE pmon#xcvrd: Notify media setting: Published SI setting for lport Ethernet16 in APP_DB
2025 Dec  4 00:41:58.247395 cmp329-6 WARNING pmon#xcvrd: $$$ Ethernet16 handle_port_update_event() : op=SET DB:STATE_DB Table:PORT_TABLE fvp {'host_tx_ready': 'true', 'state': 'ok', 'netdev_oper_status': 'down', 'admin_status': 'up', 'mtu': '9100', 'supported_speeds': '40000,100000,200000', 'supported_fecs': 'non\
e,rs', 'NPU_SI_SETTINGS_SYNC_STATUS': 'NPU_SI_SETTINGS_NOTIFIED'}
2025 Dec  4 00:41:58.247506 cmp329-6 NOTICE swss0#orchagent: :- setHostTxReady: Setting host_tx_ready status = false, alias = Ethernet16, port_id = 0x1000000001014
2025 Dec  4 00:41:58.248076 cmp329-6 NOTICE swss0#orchagent: :- setPortAdminStatus: Set admin status DOWN host_tx_ready to false for port Ethernet16
2025 Dec  4 00:41:58.248882 cmp329-6 NOTICE pmon#xcvrd: SFF-MAIN: Ethernet16: No change is needed for tx_disable value
2025 Dec  4 00:41:58.249569 cmp329-6 WARNING pmon#xcvrd: SFF-PORT-UPDATE: $$$ Ethernet16 handle_port_update_event() : op=SET DB:STATE_DB Table:PORT_TABLE fvp {'host_tx_ready': 'false', 'state': 'ok', 'netdev_oper_status': 'down', 'admin_status': 'up', 'mtu': '9100', 'supported_speeds': '40000,100000,200000', 'sup\
ported_fecs': 'none,rs', 'NPU_SI_SETTINGS_SYNC_STATUS': 'NPU_SI_SETTINGS_NOTIFIED'}
2025 Dec  4 00:41:58.249723 cmp329-6 WARNING pmon#xcvrd: SFF-PORT-UPDATE: $$$ Ethernet16 handle_port_update_event() : op=SET DB:STATE_DB Table:PORT_TABLE fvp {'host_tx_ready': 'false', 'state': 'ok', 'netdev_oper_status': 'down', 'admin_status': 'up', 'mtu': '9100', 'supported_speeds': '40000,100000,200000', 'sup\
ported_fecs': 'none,rs', 'NPU_SI_SETTINGS_SYNC_STATUS': 'NPU_SI_SETTINGS_NOTIFIED'}
2025 Dec  4 00:41:58.249723 cmp329-6 WARNING pmon#xcvrd: SFF-PORT-UPDATE: *** ('Ethernet16', 'STATE_DB', 'PORT_TABLE') handle_port_update_event() fvp {'host_tx_ready': 'false', 'index': '-1', 'port_name': 'Ethernet16', 'asic_id': 0, 'op': 'SET'}
2025 Dec  4 00:41:58.249864 cmp329-6 NOTICE pmon#xcvrd: SFF-MAIN: Ethernet16: xcvr=present(inserted=False), host_tx_ready=false(changed=True), admin_status=up(changed=False)
2025 Dec  4 00:41:58.253511 cmp329-6 WARNING pmon#xcvrd: $$$ Ethernet16 handle_port_update_event() : op=SET DB:STATE_DB Table:PORT_TABLE fvp {'host_tx_ready': 'false', 'state': 'ok', 'netdev_oper_status': 'down', 'admin_status': 'up', 'mtu': '9100', 'supported_speeds': '40000,100000,200000', 'supported_fecs': 'no\
ne,rs', 'NPU_SI_SETTINGS_SYNC_STATUS': 'NPU_SI_SETTINGS_NOTIFIED'}
2025 Dec  4 00:41:58.253659 cmp329-6 WARNING pmon#xcvrd: *** ('Ethernet16', 'STATE_DB', 'PORT_TABLE') handle_port_update_event() fvp {'host_tx_ready': 'false', 'index': '-1', 'port_name': 'Ethernet16', 'asic_id': 0, 'op': 'SET'}
2025 Dec  4 00:41:58.259567 cmp329-6 NOTICE swss0#orchagent: :- doPortTask: Set port Ethernet16 SI settings is successful
2025 Dec  4 00:41:58.262286 cmp329-6 NOTICE pmon#xcvrd: SFF-MAIN: Ethernet16: TX was disabled with lanes mask: 0b1111
2025 Dec  4 00:41:58.271905 cmp329-6 NOTICE swss0#orchagent: :- setHostTxReady: Setting host_tx_ready status = true, alias = Ethernet16, port_id = 0x1000000001014
2025 Dec  4 00:41:58.271984 cmp329-6 NOTICE swss0#orchagent: :- setPortAdminStatus: Set admin status UP host_tx_ready to true for port Ethernet16
2025 Dec  4 00:41:58.272044 cmp329-6 NOTICE swss0#orchagent: :- doPortTask: Set port Ethernet16 admin status to
2025 Dec  4 00:41:58.272291 cmp329-6 WARNING pmon#xcvrd: $$$ Ethernet16 handle_port_update_event() : op=SET DB:STATE_DB Table:PORT_TABLE fvp {'host_tx_ready': 'true', 'state': 'ok', 'netdev_oper_status': 'down', 'admin_status': 'up', 'mtu': '9100', 'supported_speeds': '40000,100000,200000', 'supported_fecs': 'non\
e,rs', 'NPU_SI_SETTINGS_SYNC_STATUS': 'NPU_SI_SETTINGS_NOTIFIED'}
2025 Dec  4 00:41:58.272291 cmp329-6 WARNING pmon#xcvrd: SFF-PORT-UPDATE: $$$ Ethernet16 handle_port_update_event() : op=SET DB:STATE_DB Table:PORT_TABLE fvp {'host_tx_ready': 'true', 'state': 'ok', 'netdev_oper_status': 'down', 'admin_status': 'up', 'mtu': '9100', 'supported_speeds': '40000,100000,200000', 'supp\
orted_fecs': 'none,rs', 'NPU_SI_SETTINGS_SYNC_STATUS': 'NPU_SI_SETTINGS_NOTIFIED'}
2025 Dec  4 00:41:58.272310 cmp329-6 WARNING pmon#xcvrd: *** ('Ethernet16', 'STATE_DB', 'PORT_TABLE') handle_port_update_event() fvp {'host_tx_ready': 'true', 'index': '-1', 'port_name': 'Ethernet16', 'asic_id': 0, 'op': 'SET'}
2025 Dec  4 00:41:58.272456 cmp329-6 WARNING pmon#xcvrd: SFF-PORT-UPDATE: *** ('Ethernet16', 'STATE_DB', 'PORT_TABLE') handle_port_update_event() fvp {'host_tx_ready': 'true', 'index': '-1', 'port_name': 'Ethernet16', 'asic_id': 0, 'op': 'SET'}
2025 Dec  4 00:41:58.272541 cmp329-6 NOTICE pmon#xcvrd: SFF-MAIN: Ethernet16: xcvr=present(inserted=False), host_tx_ready=true(changed=True), admin_status=up(changed=False)
2025 Dec  4 00:41:58.280182 cmp329-6 NOTICE pmon#xcvrd: SFF-MAIN: Ethernet16: No change is needed for tx_disable value
2025 Dec  4 00:41:59.094048 cmp329-6 NOTICE swss0#orchagent: :- updatePortOperStatus: Port Ethernet16 oper state set from down to down
2025 Dec  4 00:41:59.446232 cmp329-6 NOTICE swss0#orchagent: :- updatePortOperStatus: Port Ethernet16 oper state set from down to down

According to syslog, tx was disabled by xcvrd after xcvr insertion:

2025 Dec  4 00:41:58.262286 cmp329-6 NOTICE pmon#xcvrd: SFF-MAIN: Ethernet16: TX was disabled with lanes mask: 0b1111
...
2025 Dec  4 00:41:58.280182 cmp329-6 NOTICE pmon#xcvrd: SFF-MAIN: Ethernet16: No change is needed for tx_disable value

Steps to Reproduce

• Apply speed change patch without inserting xcvr
• Insert xcvr
• Check if port comes up

Actual Behavior and Expected Behavior

Port should come up after xcvr is inserted. But it didn't come up in our testing.

Relevant log output

Output of show version, show techsupport

Attach files (if any)

No response

[ysmanman]

According to syslog, there are two transitions of host_tx_ready status ( true -> false -> true ) after xcvr insertion

2025 Dec  4 00:41:58.205680 cmp329-6 NOTICE pmon#xcvrd: SFF-MAIN: Ethernet16: xcvr=present(inserted=True), host_tx_ready=true(changed=False), admin_status=up(changed=False)
2025 Dec  4 00:41:58.249864 cmp329-6 NOTICE pmon#xcvrd: SFF-MAIN: Ethernet16: xcvr=present(inserted=False), host_tx_ready=false(changed=True), admin_status=up(changed=False)
2025 Dec  4 00:41:58.272541 cmp329-6 NOTICE pmon#xcvrd: SFF-MAIN: Ethernet16: xcvr=present(inserted=False), host_tx_ready=true(changed=True), admin_status=up(changed=False)

The first host_tx_ready status transition ( true -> false) caused xcvrd to disable tx as expected:

2025 Dec  4 00:41:58.249864 cmp329-6 NOTICE pmon#xcvrd: SFF-MAIN: Ethernet16: xcvr=present(inserted=False), host_tx_ready=false(changed=True), admin_status=up(changed=False)
...
2025 Dec  4 00:41:58.262286 cmp329-6 NOTICE pmon#xcvrd: SFF-MAIN: Ethernet16: TX was disabled with lanes mask: 0b1111

The 2nd transition ( false -> true ) should notify xcvrd to enable tx. However, xcvrd did nothing because it thought no change in tx_disable value. As a result, tx was disabled after xcvr insertion and thus port couldn't come up.

2025 Dec  4 00:41:58.272541 cmp329-6 NOTICE pmon#xcvrd: SFF-MAIN: Ethernet16: xcvr=present(inserted=False), host_tx_ready=true(changed=True), admin_status=up(changed=False)
2025 Dec  4 00:41:58.280182 cmp329-6 NOTICE pmon#xcvrd: SFF-MAIN: Ethernet16: No change is needed for tx_disable value

The code in question is https://github.com/Azure/sonic-platform-daemons.msft/blob/d96a07210f472be00c3f5ed9b5bc4bf80982807a/sonic-xcvrd/xcvrd/sff_mgr.py#L467. The returned cur_tx_disable_array does not reflect the actual tx_disable state if the previous tx disable/enable operation is not completed in HW yet. Detailedly, after xcvrd issued tx disable for the first host_tx_ready statue transition (true -> false), xcvrd was notified of the 2nd host_tx_ready statue transition (false ->true) before tx was actually disabled in HW. Since tx disable was not completed in HW, the returned cur_tx_disable_array was actually tx enabled. As a result, xcvrd thought tx_disable value didn't change, and thus didn't enable tx again. Essentially, the existing does not handle fast host_tx_ready status change correctly.

[ysmanman]

@prgeor @rlhui @arlakshm @deepak-singhal0408 @abohanyang @kenneth-arista

[ysmanman]

A simple workaround is to skip checking cur_tx_disable_array , i.e., deleting line https://github.com/Azure/sonic-platform-daemons.msft/blob/d96a07210f472be00c3f5ed9b5bc4bf80982807a/sonic-xcvrd/xcvrd/sff_mgr.py#L467. This will force xcvrd to always enable/disable tx based on latest host_tx_ready status. cur_tx_disable_array was added in Azure/sonic-platform-daemons.msft@8a5ca2b. But it's not clear to me that what issues cur_tx_disable_array addresses.