PowerProtect Backup Error Handler received out of order message when using synthesize

The PowerProtect Data Manager interface shows an ABV0016 failure:

The Backup Session export log shows:

YYYY-MM-DD HH:MM:SS ERROR:  [8b2482fb62c792fc;8e190eae8bf16d70] SDM Data Mover: SDM Full Sync: The vCenter task failed:  dp.vpx.fault.SnapshotTransportFault.summary
BackupVmSessions-03f56907-2053-444f-b506-52bb00aabf7f.log: 2024-10-08T14:06:04.664Z ERROR:  [8b2482fb62c792fc;8e190eae8bf16d70] SDM Data Mover: SDM Full Sync: The vCenter task for 'SDM Snapshot Sync Full' completed with state 'error'.  TSDM Error Code: <TsdmError>, TSDM Error Message: <TSDM Internal Error. Error message: Handler received out of order message when using synthesize. This is unsupported. _orderTracker: 'givenPayloadStart=248376, givenPayloadEnd=248379, expectedStart=248372'. diskId='2249991e-8283-3841-fcdb-0e3d94161051'>.
...
YYYY-MM-DD HH:MM:SS tsdm[4257053]: info TSDM[0x000000851ff7c700] [sub=Sdm]: metadata.cpp:133 DumpMetadataHandler: key='syncOpResults',value='{"errorCode":"TsdmError","errorMessage":"TSDM Internal Error. Error message: Handler received out of order message when using synthesize. This is unsupported. _orderTracker: 'givenPayloadStart=248376, givenPayloadEnd=248379, expectedStart=248320'. diskId='2249991e-8283-3841-fcdb-0e3d94161051'","isRetriable":true,"additionalFiles":[],"diskResultKeys":["6000C296-d0dd-5a8b-8f84-adb0e5f99a85","6000C298-ae32-6812-7dcd-e91caadf690d"]}'

The cause is due to a stuck/failed read request on the VMware datastore or underlying storage. The SCSI read command for the datastore failed with "LUN not ready, manual intervention required" ASC/ASCQ.

The /var/run/log/vmkernel.log on the ESXi host shows the read command "0x28" failed with the "D:0x2" check condition. The sense data code "0x2" is equivalent to "LUN not ready" and the ASC/ASCQ sense data code "0x4/0x3" is equivalent to "LOGICAL UNIT NOT READY, MANUAL INTERVENTION REQUIRED."

Interpreting SCSI sense codes in VMware ESXi

...
YYYY-MM-DD HH:MM:SS cpu32:2098548)ScsiDeviceIO: 4167: Cmd(0x45b99882ee48) 0x28, CmdSN 0x4318880045b0 from world 4230637 to dev "naa.6000144000000010603d33b9e7201a2f" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x2 0x4 0x3
YYYY-MM-DD HH:MM:SS cpu36:2098548)ScsiDeviceIO: 4167: Cmd(0x45b99897a748) 0x28, CmdSN 0x431888002d00 from world 4230637 to dev "naa.6000144000000010603d33b9e7201a2f" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x2 0x4 0x3
YYYY-MM-DD HH:MM:SS cpu1:2098254)WARNING: ScsiDeviceIO: 1513: Device naa.6000144000000010603d33b9e7201a2f performance has deteriorated. I/O latency increased from average value of 987 microseconds to 24247 microseconds.
YYYY-MM-DD HH:MM:SS cpu46:2098548)ScsiDeviceIO: 4167: Cmd(0x45b98d35f488) 0x28, CmdSN 0x431888002d00 from world 4230637 to dev "naa.6000144000000010603d33b9e7201a2f" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x2 0x4 0x3
YYYY-MM-DD HH:MM:SS cpu7:2098245)WARNING: ScsiDeviceIO: 1513: Device naa.6000144000000010603d33b9e7201a2f performance has deteriorated. I/O latency increased from average value of 987 microseconds to 50906 microseconds.
YYYY-MM-DD HH:MM:SS cpu58:2098548)ScsiDeviceIO: 4167: Cmd(0x45b9611b63c8) 0x28, CmdSN 0x4318880045b0 from world 4230637 to dev "naa.6000144000000010603d33b9e7201a2f" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x2 0x4 0x3
YYYY-MM-DD HH:MM:SS cpu9:2098249)WARNING: ScsiDeviceIO: 1513: Device naa.6000144000000010603d33b9e7201a2f performance has deteriorated. I/O latency increased from average value of 987 microseconds to 149989 microseconds.
YYYY-MM-DD HH:MM:SS cpu55:2098548)ScsiDeviceIO: 4167: Cmd(0x45b9988f5a48) 0x28, CmdSN 0x4318880045b0 from world 4230637 to dev "naa.6000144000000010603d33b9e7201a2f" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x2 0x4 0x3
YYYY-MM-DD HH:MM:SS cpu55:2098548)ScsiDeviceIO: 4167: Cmd(0x45b9611046c8) 0x28, CmdSN 0x431888002d00 from world 4230637 to dev "naa.6000144000000010603d33b9e7201a2f" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x2 0x4 0x3
...

The /vmfs/volumes/[MY-DATASTORE]/[MY-VM]/vmware.log file shows:
 

...
YYYY-MM-DD HH:MM:SS Er(02) Upcall-cc0207f - LWD: Failed to read extent range [248372,248375], offset range [65109229568, 1048576], from disk 5991B43E0 (capacity 214748364800), readTxn 61960. Error: 22: IO error
YYYY-MM-DD HH:MM:SS Er(02) Upcall-cc0207f - LWD: Failed to read extent range [248372,248375], offset range [65109229568, 1048576], from disk 5991B43E0 (capacity 214748364800), readTxn 61960. Error: 22: IO error
YYYY-MM-DD HH:MM:SS Er(02) Upcall-cc0207f - LWD: Failed to read extent range [248372,248375], offset range [65109229568, 1048576], from disk 5991B43E0 (capacity 214748364800), readTxn 61960. Error: 22: IO error
YYYY-MM-DD HH:MM:SS Er(02) Upcall-cc0207f - LWD: Failed to read extent range [248372,248375], offset range [65109229568, 1048576], from disk 5991B43E0 (capacity 214748364800), readTxn 61960. Error: 22: IO error
YYYY-MM-DD HH:MM:SS Er(02) Upcall-cc0207f - LWD: Failed to read extent range [248372,248375], offset range [65109229568, 1048576], from disk 5991B43E0 (capacity 214748364800), readTxn 61960. Error: 22: IO error
YYYY-MM-DD HH:MM:SS Er(02) Upcall-cc0207f - LWD: Failed to read extent range [248372,248375], offset range [65109229568, 1048576], from disk 5991B43E0 (capacity 214748364800), readTxn 61960. Error: 22: IO error
...

Workaround: 

Perform a Storage vMotion of the affected VMs to a stable datastore and retry the TSDM backups. 

Permanent Fix:

1. Have the local storage team investigate the SCSI read command failures with the affected LUN.
2. Contact VMware Support to confirm if this issue is fixed in later releases.