On slow machines we experience constantly failing updates of the controller. After analyzing the code we found that EmberFirmwareUpdateHandler does not entirely follow the XModem protocol. And furthermore there is a bug in the retry logic when a data chunk can not be processed.
This is the logging of EmberFirmwareUpdateHandler when failing
2021-08-02T15:05:47.501+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Starting.
2021-08-02T15:05:49.005+0200 141 DEBUG [EmberFirmwareUpdateHandler,com.xxx.binding.zigbee.handler.ZigBeeSerialPort] Connecting to serial port [/dev/ttyUSB0] at 115200 baud, flow control FLOWCONTROL_OUT_NONE.
2021-08-02T15:05:49.016+0200 141 DEBUG [EmberFirmwareUpdateHandler,com.xxx.binding.zigbee.handler.ZigBeeSerialPort] Serial port [/dev/ttyUSB0] is initialized.
2021-08-02T15:05:49.017+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Serial port opened.
2021-08-02T15:05:50.543+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Got bootloader prompt.
2021-08-02T15:05:52.046+0200 205 DEBUG [EmberFirmwareUpdateHandler,com.xxx.binding.zigbee.ember.handler.EmberHandler] Ember dongle firmware status: FIRMWARE_TRANSFER_STARTED
2021-08-02T15:05:52.057+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Clearing input stream...
2021-08-02T15:05:52.058+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Starting transfer.
2021-08-02T15:05:52.058+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Transfer frame 1, attempt 0.
2021-08-02T15:05:53.417+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Transfer frame 1, attempt 1.
2021-08-02T15:05:53.444+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Transfer frame 1, attempt 2.
2021-08-02T15:05:53.466+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Transfer frame 1, attempt 3.
2021-08-02T15:05:53.487+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Transfer frame 1, attempt 4.
2021-08-02T15:05:53.509+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Transfer frame 1, attempt 5.
2021-08-02T15:05:53.522+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Transfer frame 1, attempt 6.
2021-08-02T15:05:53.536+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Transfer frame 1, attempt 7.
2021-08-02T15:05:53.564+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Transfer frame 1, attempt 8.
2021-08-02T15:05:53.620+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Transfer frame 1, attempt 9.
2021-08-02T15:05:53.638+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Transfer frame 1, attempt 10.
2021-08-02T15:05:53.652+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Transfer frame 1, attempt 11.
2021-08-02T15:05:53.655+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Transfer failed.
2021-08-02T15:05:58.658+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Waiting for menu.
2021-08-02T15:06:07.412+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Unable to get bootloader prompt.
2021-08-02T15:06:07.430+0200 141 INFO [EmberFirmwareUpdateHandler,com.xxx.binding.zigbee.handler.ZigBeeSerialPort] Finished closing of serial port '/dev/ttyUSB0'.
2021-08-02T15:06:07.431+0200 205 DEBUG [EmberFirmwareUpdateHandler,com.xxx.binding.zigbee.ember.handler.EmberHandler] Ember dongle firmware status: FIRMWARE_UPDATE_FAILED
2021-08-02T15:06:07.444+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Failed waiting for menu after transfer.
2021-08-02T15:06:07.445+0200 141 INFO [EmberFirmwareUpdateHandler,com.xxx.binding.zigbee.handler.ZigBeeSerialPort] Skipping closing of serial port, because serial port field is null
2021-08-02T15:06:07.445+0200 205 DEBUG [EmberFirmwareUpdateHandler,com.xxx.binding.zigbee.ember.handler.EmberHandler] Ember dongle firmware status: FIRMWARE_UPDATE_FAILED
2021-08-02T15:17:03.866+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Starting.
2021-08-02T15:17:05.367+0200 141 DEBUG [EmberFirmwareUpdateHandler,com.xxx.binding.zigbee.handler.ZigBeeSerialPort] Connecting to serial port [/dev/ttyUSB0] at 115200 baud, flow control FLOWCONTROL_OUT_NONE.
2021-08-02T15:17:05.378+0200 141 DEBUG [EmberFirmwareUpdateHandler,com.xxx.binding.zigbee.handler.ZigBeeSerialPort] Serial port [/dev/ttyUSB0] is initialized.
2021-08-02T15:17:05.378+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Serial port opened.
2021-08-02T15:17:14.131+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Unable to get bootloader prompt.
2021-08-02T15:17:14.157+0200 141 INFO [EmberFirmwareUpdateHandler,com.xxx.binding.zigbee.handler.ZigBeeSerialPort] Finished closing of serial port '/dev/ttyUSB0'.
2021-08-02T15:17:14.157+0200 205 DEBUG [EmberFirmwareUpdateHandler,com.xxx.binding.zigbee.ember.handler.EmberHandler] Ember dongle firmware status: FIRMWARE_UPDATE_FAILED
2021-08-02T15:17:14.167+0200 204 DEBUG [EmberFirmwareUpdateHandler,com.zsmartsystems.zigbee.dongle.ember.internal.EmberFirmwareUpdateHandler] Ember bootloader: Failed waiting for menu before transfer.
2021-08-02T15:17:14.167+0200 141 INFO [EmberFirmwareUpdateHandler,com.xxx.binding.zigbee.handler.ZigBeeSerialPort] Skipping closing of serial port, because serial port field is null
2021-08-02T15:17:14.167+0200 205 DEBUG [EmberFirmwareUpdateHandler,com.xxx.binding.zigbee.ember.handler.EmberHandler] Ember dongle firmware status: FIRMWARE_UPDATE_FAILED
We did a few changes to the handler which resolved the issues. These are the main ones:
When selecting option 1 (transfer file) from the bootloader menu, the update handler now waits until it receives a '0x43' (XModem ready) before starting the transfer. In the previous solution, there was only one sleep (1500) before the transfer was started.
In the transferFile method, the readChunk method is now called outside the inner do-while loop. The reason for this is that the inner do-while loop repeats sending the chunk data until it receives an ACK for it. In the current solution, the retry logic also calls readChunk again, which then reads the next chunk and makes 'forget' that the previous chunk was not acknowledged. With the new solution, you re-send the same data as long as it is not acknowledged.
After transferring the data of a single chunk, we now wait until we get a transfer response != '0x43' (XModem ready).
At the end of the file transfer we now repeat sending an ETO (End of Transfer) until we get an ACK.
This changes were made in collaboration with @kolkoo
On slow machines we experience constantly failing updates of the controller. After analyzing the code we found that EmberFirmwareUpdateHandler does not entirely follow the XModem protocol. And furthermore there is a bug in the retry logic when a data chunk can not be processed.
This is the logging of
EmberFirmwareUpdateHandlerwhen failingWe did a few changes to the handler which resolved the issues. These are the main ones:
This changes were made in collaboration with @kolkoo
Please check the PR