Zigbee2mqtt: OTA fails with size mismatch error for TRADFRI control outlet
What happened
Z2M shows an update is available, confirmed manually by looking at the Ikea json. Update fails with size mismatch error.
What did you expect to happen
Update happens, unicorns descend.
How to reproduce it (minimal and precise)
- Check for update
- Attempt to update
- Check logs
Debug info
Zigbee2MQTT version: 1.14.4
Adapter hardware: Conbee II
Adapter firmware version: 26580700
Log from update check and attempt
Zigbee2MQTT:info 2020-09-14 09:41:47: Switching log level to 'debug'
Zigbee2MQTT:info 2020-09-14 09:41:47: MQTT publish: topic 'zigbee2mqtt/bridge/config', payload '{"commit":"654817a","coordinator":{"meta":{"maintrel":0,"majorrel":38,"minorrel":88,"product":0,"revision":"0x26580700","transportrev":0},"type":"ConBee2"},"log_level":"debug","network":{"channel":15,"extendedPanID":"0xdddddddddddddddd","panID":6754},"permit_join":false,"version":"1.14.4"}'
Zigbee2MQTT:debug 2020-09-14 09:41:50: Received Zigbee message from 'Den Plug', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":1,"fileVersion":335676944,"imageType":4353,"manufacturerCode":4476}' from endpoint 1 with groupID null
Zigbee2MQTT:debug 2020-09-14 09:41:53: Received MQTT message on 'zigbee2mqtt/bridge/ota_update/check' with data 'Den Plug'
Zigbee2MQTT:info 2020-09-14 09:41:53: Checking if update available for 'Den Plug'
Zigbee2MQTT:info 2020-09-14 09:41:53: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"Checking if update available for 'Den Plug'","meta":{"device":"Den Plug","status":"checking_if_available"},"type":"ota_update"}'
Zigbee2MQTT:debug 2020-09-14 09:41:53: Check if update available for '0x90fd9ffffe33f912' (TRADFRI control outlet)
Zigbee2MQTT:debug 2020-09-14 09:41:53: Using endpoint '1'
Zigbee2MQTT:debug 2020-09-14 09:41:53: Received Zigbee message from 'Den Plug', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":1,"fileVersion":335676944,"imageType":4353,"manufacturerCode":4476}' from endpoint 1 with groupID null
Zigbee2MQTT:debug 2020-09-14 09:41:53: Got OTA request '{"fieldControl":1,"manufacturerCode":4476,"imageType":4353,"fileVersion":335676944}'
Zigbee2MQTT:debug 2020-09-14 09:41:53: Is new image available for '0x90fd9ffffe33f912', current '{"fieldControl":1,"manufacturerCode":4476,"imageType":4353,"fileVersion":335676944}', latest meta '{"fileVersion":537019939,"fileSize":202110,"url":"https://fw.ota.homesmart.ikea.net/Tradfri_OTA_release_signed_2020_09_08_141305/bin/10005777-6.1-TRADFRI-control-outlet-2.0.024.ota.ota.signed"}'
Zigbee2MQTT:debug 2020-09-14 09:41:53: Update available for '0x90fd9ffffe33f912': YES
Zigbee2MQTT:info 2020-09-14 09:41:53: Update available for 'Den Plug'
Zigbee2MQTT:info 2020-09-14 09:41:53: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"Update available for 'Den Plug'","meta":{"device":"Den Plug","status":"available"},"type":"ota_update"}'
Zigbee2MQTT:info 2020-09-14 09:41:53: MQTT publish: topic 'zigbee2mqtt/Den Plug', payload '{"device":{"applicationVersion":20,"dateCode":"20180528","friendlyName":"Den Plug","hardwareVersion":1,"ieeeAddr":"0x90fd9ffffe33f912","manufacturerID":4476,"manufacturerName":"IKEA of Sweden","model":"E1603/E1702","networkAddress":8161,"powerSource":"Mains (single phase)","softwareBuildID":"1.4.020","stackVersion":97,"type":"Router","zclVersion":3},"last_seen":"2020-09-14T13:41:53.281Z","linkquality":217,"state":"ON","update_available":true}'
Zigbee2MQTT:debug 2020-09-14 09:41:56: Received Zigbee message from 'Den Plug', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":1,"fileVersion":335676944,"imageType":4353,"manufacturerCode":4476}' from endpoint 1 with groupID null
Zigbee2MQTT:debug 2020-09-14 09:41:59: Received Zigbee message from 'Den Plug', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":1,"fileVersion":335676944,"imageType":4353,"manufacturerCode":4476}' from endpoint 1 with groupID null
Zigbee2MQTT:debug 2020-09-14 09:42:02: Received Zigbee message from 'Den Plug', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":1,"fileVersion":335676944,"imageType":4353,"manufacturerCode":4476}' from endpoint 1 with groupID null
Zigbee2MQTT:debug 2020-09-14 09:42:03: Received MQTT message on 'zigbee2mqtt/bridge/ota_update/update' with data 'Den Plug'
Zigbee2MQTT:info 2020-09-14 09:42:03: Updating 'Den Plug' to latest firmware
Zigbee2MQTT:info 2020-09-14 09:42:03: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"meta":{"device":"Den Plug","status":"update_in_progress"},"msg":"Updating 'Den Plug' to latest firmware","type":"ota_update"}'
Zigbee2MQTT:debug 2020-09-14 09:42:03: Received Zigbee message from 'Den Plug', type 'readResponse', cluster 'genBasic', data '{"dateCode":"20180528","swBuildId":"1.4.020"}' from endpoint 1 with groupID null
Zigbee2MQTT:debug 2020-09-14 09:42:03: Updating to latest '0x90fd9ffffe33f912' (TRADFRI control outlet)
Zigbee2MQTT:debug 2020-09-14 09:42:03: Using endpoint '1'
Zigbee2MQTT:debug 2020-09-14 09:42:03: Received Zigbee message from 'Den Plug', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":1,"fileVersion":335676944,"imageType":4353,"manufacturerCode":4476}' from endpoint 1 with groupID null
Zigbee2MQTT:debug 2020-09-14 09:42:03: Got OTA request '{"fieldControl":1,"manufacturerCode":4476,"imageType":4353,"fileVersion":335676944}'
Zigbee2MQTT:debug 2020-09-14 09:42:03: getNewImage for '0x90fd9ffffe33f912', meta {"fileVersion":537019939,"fileSize":202110,"url":"https://fw.ota.homesmart.ikea.net/Tradfri_OTA_release_signed_2020_09_08_141305/bin/10005777-6.1-TRADFRI-control-outlet-2.0.024.ota.ota.signed"}
Zigbee2MQTT:debug 2020-09-14 09:42:04: getNewImage for '0x90fd9ffffe33f912', image header {"otaUpgradeFileIdentifier":{"type":"Buffer","data":[30,241,238,11]},"otaHeaderVersion":256,"otaHeaderLength":56,"otaHeaderFieldControl":0,"manufacturerCode":4476,"imageType":4353,"fileVersion":537019939,"zigbeeStackVersion":2,"otaHeaderString":"GBL GBL_tradfri_control_outlet\u0000\u0000","totalImageSize":201030}
Zigbee2MQTT:info 2020-09-14 09:42:04: MQTT publish: topic 'zigbee2mqtt/Den Plug', payload '{"device":{"applicationVersion":20,"dateCode":"20180528","friendlyName":"Den Plug","hardwareVersion":1,"ieeeAddr":"0x90fd9ffffe33f912","manufacturerID":4476,"manufacturerName":"IKEA of Sweden","model":"E1603/E1702","networkAddress":8161,"powerSource":"Mains (single phase)","softwareBuildID":"1.4.020","stackVersion":97,"type":"Router","zclVersion":3},"last_seen":"2020-09-14T13:42:03.796Z","linkquality":217,"state":"ON","update_available":true}'
Zigbee2MQTT:info 2020-09-14 09:42:04: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"Update of 'Den Plug' failed (Image size mismatch)","meta":{"device":"Den Plug","status":"update_failed"},"type":"ota_update"}'
Zigbee2MQTT:error 2020-09-14 09:42:04: Update of 'Den Plug' failed (Image size mismatch)
Zigbee2MQTT:debug 2020-09-14 09:42:06: Received Zigbee message from 'Den Plug', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":1,"fileVersion":335676944,"imageType":4353,"manufacturerCode":4476}' from endpoint 1 with groupID null
Zigbee2MQTT:debug 2020-09-14 09:42:09: Received Zigbee message from 'Den Plug', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":1,"fileVersion":335676944,"imageType":4353,"manufacturerCode":4476}' from endpoint 1 with groupID null
Zigbee2MQTT:debug 2020-09-14 09:42:12: Received Zigbee message from 'Den Plug', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":1,"fileVersion":335676944,"imageType":4353,"manufacturerCode":4476}' from endpoint 1 with groupID null
Zigbee2MQTT:debug 2020-09-14 09:42:15: Received Zigbee message from 'Den Plug', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":1,"fileVersion":335676944,"imageType":4353,"manufacturerCode":4476}' from endpoint 1 with groupID null
Grabbed the file manually and checked the size, it does differ from the 201030 shown in the logs and json file:
203078 Sep 10 10:52 10005777-6.1-TRADFRI-control-outlet-2.0.024.ota.ota.signed
mattsch
All 29 comments
Could you provide the herdsman debug logging of this?
To enable herdsman debug logging, see https://www.zigbee2mqtt.io/information/debug.html#zigbee-herdsman-debug-logging
Koenkk
on 15 Sep 2020
sorry for the messy logs,
getting https://fw.ota.homesmart.ikea.net/Tradfri_OTA_release_signed_2020_09_08_141305/bin/10046695-1.1-TRADFRI-light-unified-w-2.3.050.ota.ota.signed
expecting 204478 bytes
getting 205446 bytes
Sep 15 17:00:57 Zigbee2MQTT:debug 2020-09-15 17:00:57: Received MQTT message on zigbee2mqtt/bridge/ota_update/check' with data 'led1836g9_01'
Sep 15 17:00:57 Zigbee2MQTT:info 2020-09-15 17:00:57: Checking if update available for 'led1836g9_01'
Sep 15 17:00:57 Zigbee2MQTT:info 2020-09-15 17:00:57: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"Checking if update available for 'led1836g9_01'","meta":"device":"led1836g9_01","status":"checking_if_available"},"type":"ota_update"}'
Sep 15 17:00:57 Zigbee2MQTT:debug 2020-09-15 17:00:57: Check if update available for '0xled1836g9_01' (TRADFRI bulb E27 WW 806lm)
Sep 15 17:00:57 Zigbee2MQTT:debug 2020-09-15 17:00:57: Using endpoint '1'
Sep 15 17:00:57 zigbee-herdsman:controller:endpoint CommandResponse 0xled1836g9_01/1 genOta.imageNotify({"payloadType":0,"queryJitter":100}, {"timeout"$
10000,"disableResponse":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNum$
er":null}) +6s
Sep 15 17:00:57 zigbee-herdsman:adapter:zStack:adapter sendZclFrameToEndpointInternal 0xled1836g9_01:8782/1 (0,0) +6s
Sep 15 17:00:57 zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequest - {"dstaddr":8782,"destendpoint":1,"srcendpoint":1,"clusterid":25,"transid":21$
,"options":0,"radius":30,"len":5,"data":{"type":"Buffer","data":[25,179,0,0,100]}} +6s
Sep 15 17:00:57 zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,15,36,1,78,34,1,1,25,0,215,0,30,5,25,179,0,0,100,93] +5s
Sep 15 17:00:57 zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequest - {"status":0} +6s
Sep 15 17:00:57 zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":0,"endpoint":1,"transid":215} +5s
Sep 15 17:00:57 zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - srcRtgInd - {"dstaddr":8782,"relaycount":0,"relaylist":[]} +52ms
Sep 15 17:00:58 zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - srcRtgInd - {"dstaddr":8782,"relaycount":0,"relaylist":[]} +1s
Sep 15 17:00:58 zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":6,"srcaddr":8782,"srcendpoint":1,"dstendpoint":1,"w$sbroadcast":0,"linkquality":72,"securityuse":0,"timestamp":6890200,"transseqnumber":0,"len":7,"data":{"type":"Buffer","data":[8,20,10,0,0,16,1]}} +52ms
Sep 15 17:00:58 zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"directi$n":1,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":20,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":0,"$
ataType":16,"attrData":1}]},"address":8782,"endpoint":1,"linkquality":72,"groupID":0}' +7s
Sep 15 17:00:58 Zigbee2MQTT:debug 2020-09-15 17:00:58: Received Zigbee message from 'led1836g9_01', type 'attributeReport', cluster 'genOnOff', data '{"onOff$
:1}' from endpoint 1 with groupID 0
Sep 15 17:00:58 Zigbee2MQTT:info 2020-09-15 17:00:58: MQTT publish: topic 'zigbee2mqtt/led1836g9_01', payload '{"elapsed":297093,"last_seen":1600182058536,"$
inkquality":72,"state":"ON"}'
Sep 15 17:00:58 zigbee-herdsman:controller:endpoint DefaultResponse 0xled1836g9_01/1 6(10, {"timeout":10000,"disableResponse":false,"disableDefaultResp$
nse":true,"direction":1,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null}) +1s
Sep 15 17:00:58 zigbee-herdsman:adapter:zStack:adapter sendZclFrameToEndpointInternal 0xled1836g9_01:8782/1 (0,0) +1s
Sep 15 17:00:58 zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequest - {"dstaddr":8782,"destendpoint":1,"srcendpoint":1,"clusterid":6,"transid":216$
"options":0,"radius":30,"len":5,"data":{"type":"Buffer","data":[24,20,11,10,0]}} +1s
Sep 15 17:00:58 zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,15,36,1,78,34,1,1,6,0,216,0,30,5,24,20,11,10,0,142] +1s
Sep 15 17:00:58 zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequest - {"status":0} +1s
Sep 15 17:00:58 zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":0,"endpoint":1,"transid":216} +31ms
Sep 15 17:00:59 zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - srcRtgInd - {"dstaddr":8782,"relaycount":0,"relaylist":[]} +657ms
Sep 15 17:00:59 zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":25,"srcaddr":8782,"srcendpoint":1,"dstendpoint":13,$wasbroadcast":0,"linkquality":69,"securityuse":0,"timestamp":6936756,"transseqnumber":0,"len":14,"data":{"type":"Buffer","data":[1,21,1,1,124,17,3,65,49,38,2$
33,1,0]}} +62ms
Sep 15 17:00:59 zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":1,"manufacturerSpecific":false,"directi$n":0,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":21,"manufacturerCode":null,"commandIdentifier":1},"Payload":{"fieldControl"$
1,"manufacturerCode":4476,"imageType":16643,"fileVersion":553788977}},"address":8782,"endpoint":1,"linkquality":69,"groupID":0}' +750ms
Sep 15 17:00:59 Zigbee2MQTT:debug 2020-09-15 17:00:59: Received Zigbee message from 'led1836g9_01', type 'commandQueryNextImageRequest', cluster 'genOta', da$a '{"fieldControl":1,"fileVersion":553788977,"imageType":16643,"manufacturerCode":4476}' from endpoint 1 with groupID 0
Sep 15 17:00:59 Zigbee2MQTT:debug 2020-09-15 17:00:59: Got OTA request '{"fieldControl":1,"manufacturerCode":4476,"imageType":16643,"fileVersion":553788977}'
Sep 15 17:00:59 Zigbee2MQTT:debug 2020-09-15 17:00:59: Is new image available for '0xled1836g9_01', current '{"fieldControl":1,"manufacturerCode":4476,"im
ageType":16643,"fileVersion":553788977}', latest meta '{"fileVersion":587531825,"fileSize":204478,"url":"https://fw.ota.homesmart.ikea.net/Tradfri_OTA_release
_signed_2020_09_08_141305/bin/10046695-1.1-TRADFRI-light-unified-w-2.3.050.ota.ota.signed"}'
Sep 15 17:00:59 Zigbee2MQTT:debug 2020-09-15 17:00:59: Update available for '0xled1836g9_01': YES
Sep 15 17:00:59 Zigbee2MQTT:info 2020-09-15 17:00:59: Update available for 'led1836g9_01'
Sep 15 17:00:59 Zigbee2MQTT:info 2020-09-15 17:00:59: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"Update available for 'led1836g9_01'"
,"meta":{"device":"led1836g9_01","status":"available"},"type":"ota_update"}'
Sep 15 17:00:59 Zigbee2MQTT:info 2020-09-15 17:00:59: MQTT publish: topic 'zigbee2mqtt/led1836g9_01', payload '{"last_seen":1600182059287,"update":{"state":"
available"},"update_available":true}'
Sep 15 17:01:01 zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - srcRtgInd - {"dstaddr":8782,"relaycount":0,"relaylist":[]} +2s
Sep 15 17:01:01 zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":8,"srcaddr":8782,"srcendpoint":1,"dstendpoint":1,"wa
sbroadcast":0,"linkquality":69,"securityuse":0,"timestamp":7072171,"transseqnumber":0,"len":7,"data":{"type":"Buffer","data":[8,22,10,0,0,32,1]}} +54ms
Sep 15 17:01:01 zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"directio
n":1,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":22,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":0,"d
ataType":32,"attrData":1}]},"address":8782,"endpoint":1,"linkquality":69,"groupID":0}' +2s
Sep 15 17:01:01 Zigbee2MQTT:debug 2020-09-15 17:01:01: Received Zigbee message from 'led1836g9_01', type 'attributeReport', cluster 'genLevelCtrl', data '{"cu
rrentLevel":1}' from endpoint 1 with groupID 0
Sep 15 17:01:01 Zigbee2MQTT:info 2020-09-15 17:01:01: MQTT publish: topic 'zigbee2mqtt/led1836g9_01', payload '{"brightness":1,"elapsed":2908,"last_seen":160
0182061446,"linkquality":69}'
Sep 15 17:01:01 zigbee-herdsman:controller:endpoint DefaultResponse 0xled1836g9_01/1 8(10, {"timeout":10000,"disableResponse":false,"disableDefaultRespo
nse":true,"direction":1,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null}) +3s
Sep 15 17:01:01 zigbee-herdsman:adapter:zStack:adapter sendZclFrameToEndpointInternal 0xled1836g9_01:8782/1 (0,0) +3s
Sep 15 17:01:01 zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequest - {"dstaddr":8782,"destendpoint":1,"srcendpoint":1,"clusterid":8,"transid":217,
"options":0,"radius":30,"len":5,"data":{"type":"Buffer","data":[24,22,11,10,0]}} +3s
Sep 15 17:01:01 zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,15,36,1,78,34,1,1,8,0,217,0,30,5,24,22,11,10,0,131] +3s
Sep 15 17:01:01 zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequest - {"status":0} +3s
Sep 15 17:01:01 zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":0,"endpoint":1,"transid":217} +23ms
Sep 15 17:01:01 Zigbee2MQTT:debug 2020-09-15 17:01:01: Received MQTT message on 'zigbee2mqtt/bridge/ota_update/update' with data 'led1836g9_01'
Sep 15 17:01:01 Zigbee2MQTT:info 2020-09-15 17:01:01: Updating 'led1836g9_01' to latest firmware
Sep 15 17:01:01 Zigbee2MQTT:info 2020-09-15 17:01:01: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"meta":{"device":"led1836g9_01","status":"updat
e_in_progress"},"msg":"Updating 'led1836g9_01' to latest firmware","type":"ota_update"}'
Sep 15 17:01:01 zigbee-herdsman:controller:endpoint Read 0xled1836g9_01/1 genBasic(["dateCode","swBuildId"], {"timeout":10000,"disableResponse":false,"d
isableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null}) +431ms
Sep 15 17:01:01 zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequest - {"dstaddr":8782,"destendpoint":1,"srcendpoint":1,"clusterid":0,"transid":218$
"options":0,"radius":30,"len":7,"data":{"type":"Buffer","data":[16,180,0,6,0,0,64]}} +431ms
Sep 15 17:01:01 zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,17,36,1,78,34,1,1,0,0,218,0,30,7,16,180,0,6,0,0,64,121] +431ms Sep 15 17:01:01 zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequest - {"status":0} +431ms
Sep 15 17:01:01 zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":0,"endpoint":1,"transid":218} +432ms Sep 15 17:01:01 zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - srcRtgInd - {"dstaddr":8782,"relaycount":0,"relaylist":[]} +14ms
Sep 15 17:01:01 zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":0,"srcaddr":8782,"srcendpoint":1,"dstendpoint":1,"w$
sbroadcast":0,"linkquality":63,"securityuse":0,"timestamp":7104905,"transseqnumber":0,"len":28,"data":{"type":"Buffer","data":[24,180,1,6,0,0,66,8,50,48,49,5$
,49,50,48,51,0,64,0,66,7,50,46,49,46,48,50,50]}} +62ms
Sep 15 17:01:01 zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"directi$
n":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":180,"manufacturerCode":null,"commandIdentifier":1},"Payload":[{"attrId":6,"s$atus":0,"dataType":66,"attrData":"20181203"},{"attrId":16384,"status":0,"dataType":66,"attrData":"2.1.022"}]},"address":8782,"endpoint":1,"linkquality":63,"g$
oupID":0}' +532ms
Sep 15 17:01:01 Zigbee2MQTT:debug 2020-09-15 17:01:01: Received Zigbee message from 'led1836g9_01', type 'readResponse', cluster 'genBasic', data '{"dateCode$:"20181203","swBuildId":"2.1.022"}' from endpoint 1 with groupID 0
Sep 15 17:01:01 Zigbee2MQTT:debug 2020-09-15 17:01:01: Updating to latest '0xled1836g9_01' (TRADFRI bulb E27 WW 806lm)
Sep 15 17:01:01 Zigbee2MQTT:debug 2020-09-15 17:01:01: Using endpoint '1'
Sep 15 17:01:01 zigbee-herdsman:controller:endpoint CommandResponse 0xled1836g9_01/1 genOta.imageNotify({"payloadType":0,"queryJitter":100}, {"timeout"$
10000,"disableResponse":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNum$
er":null}) +102ms
Sep 15 17:01:01 zigbee-herdsman:adapter:zStack:adapter sendZclFrameToEndpointInternal 0xled1836g9_01:8782/1 (0,0) +101ms
Sep 15 17:01:01 zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequest - {"dstaddr":8782,"destendpoint":1,"srcendpoint":1,"clusterid":25,"transid":21$
,"options":0,"radius":30,"len":5,"data":{"type":"Buffer","data":[25,181,0,0,100]}} +101ms
Sep 15 17:01:01 zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,15,36,1,78,34,1,1,25,0,219,0,30,5,25,181,0,0,100,87] +101ms
Sep 15 17:01:01 zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequest - {"status":0} +100ms Sep 15 17:01:02 zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":0,"endpoint":1,"transid":219} +25ms
Sep 15 17:01:02 zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - srcRtgInd - {"dstaddr":8782,"relaycount":0,"relaylist":[]} +21ms
Sep 15 17:01:02 zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":25,"srcaddr":8782,"srcendpoint":1,"dstendpoint":13,$
wasbroadcast":0,"linkquality":66,"securityuse":0,"timestamp":7111663,"transseqnumber":0,"len":14,"data":{"type":"Buffer","data":[1,23,1,1,124,17,3,65,49,38,2$
33,1,0]}} +61ms
Sep 15 17:01:02 zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":1,"manufacturerSpecific":false,"directi$
n":0,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":23,"manufacturerCode":null,"commandIdentifier":1},"Payload":{"fieldControl"$
1,"manufacturerCode":4476,"imageType":16643,"fileVersion":553788977}},"address":8782,"endpoint":1,"linkquality":66,"groupID":0}' +110ms
Sep 15 17:01:02 Zigbee2MQTT:debug 2020-09-15 17:01:02: Received Zigbee message from 'led1836g9_01', type 'commandQueryNextImageRequest', cluster 'genOta', da$
a '{"fieldControl":1,"fileVersion":553788977,"imageType":16643,"manufacturerCode":4476}' from endpoint 1 with groupID 0
Sep 15 17:01:02 Zigbee2MQTT:debug 2020-09-15 17:01:02: Got OTA request '{"fieldControl":1,"manufacturerCode":4476,"imageType":16643,"fileVersion":553788977}'
Sep 15 17:01:02 Zigbee2MQTT:debug 2020-09-15 17:01:02: getNewImage for '0xled1836g9_01', meta {"fileVersion":587531825,"fileSize":204478,"url":"https://fw.ota.homesmart.ikea.net/Tradfri_OTA_release_signed_2020_09_08_141305/bin/10046695-1.1-TRADFRI-light-unified-w-2.3.050.ota.ota.signed"}
Sep 15 17:01:02 Zigbee2MQTT:debug 2020-09-15 17:01:02: getNewImage for '0xled1836g9_01', image header {"otaUpgradeFileIdentifier":{"type":"Buffer","data":[30,241,238,11]},"otaHeaderVersion":256,"otaHeaderLength":56,"otaHeaderFieldControl":0,"manufacturerCode":4476,"imageType":16643,"fileVersion":587531825,"zigbeeStackVersion":2,"otaHeaderString":"GBLGBL_tradfri_light_unified_w\u0000","totalImageSize":203378}
Sep 15 17:01:02 Zigbee2MQTT:info 2020-09-15 17:01:02: MQTT publish: topic 'zigbee2mqtt/led1836g9_01', payload '{"last_seen":1600182062088,"update":{"state":"available"},"update_available":true}'
Sep 15 17:01:02 Zigbee2MQTT:info 2020-09-15 17:01:02: MQTT publish: topic 'zigbee2mqtt/bridge/log', payload '{"message":"Update of 'led1836g9_01' failed (Image size mismatch)","meta":{"device":"led1836g9_01","status":"update_failed"},"type":"ota_update"}'
Sep 15 17:01:02 Zigbee2MQTT:error 2020-09-15 17:01:02: Update of 'led1836g9_01' failed (Image size mismatch)
lolorc
on 15 Sep 2020
I'm getting the same error just now. Updated one Tradfri control outlet without problems with zigbee2mqtt version 1.11.0. Then updated to version 1.14.4 and tried to update my second Tradfri control outlet and failed with size mismatch error.
ruudyn
on 15 Sep 2020
Fixed! (successfully updated my TRADFRI GU10 bulb with the fix).
Changes will be available in the latest dev branch in a few hours (https://www.zigbee2mqtt.io/how_tos/how-to-switch-to-dev-branch.html)
Koenkk
on 15 Sep 2020
it's working, but what's happening if for some reason you flash an uncompleted firmware file ?
lolorc
on 16 Sep 2020
@lolorc I expect the bulb to do an integrity check before flashing
Koenkk
on 16 Sep 2020
that might explain why I flashed 4 bulbs yesterday, and the four of them still need an update :-)
Sep 15 23:56:04 Zigbee2MQTT:info 2020-09-15 23:56:04: Finished update of 'led1733g7_02', from '{"dateCode":"20190308","softwareBuildID":"2.0.022"}' to '{"dateCode":"20190308","softwareBuildID":"2.0.022"}'
Sep 15 23:57:49 Zigbee2MQTT:info 2020-09-15 23:57:49: Finished update of 'led1836g9_01', from '{"dateCode":"20181203","softwareBuildID":"2.1.022"}' to '{"dateCode":"20181203","softwareBuildID":"2.1.022"}'
Sep 16 00:21:26 Zigbee2MQTT:info 2020-09-16 00:21:26: Finished update of 'led1836g9_02', from '{"dateCode":"20181203","softwareBuildID":"2.1.022"}' to '{"dateCode":"20181203","softwareBuildID":"2.1.022"}'
Sep 16 00:27:23 Zigbee2MQTT:info 2020-09-16 00:27:23: Finished update of 'led1733g7_01', from '{"dateCode":"20190308","softwareBuildID":"2.0.022"}' to '{"dateCode":"20190308","softwareBuildID":"2.0.022"}'
Sep 15 22:56:35 Zigbee2MQTT:debug 2020-09-15 22:56:35: Received Zigbee message from 'led1836g9_01', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":1,"fileVersion":553788977,"imageType":16643,"manufacturerCode":4476}' from endpoint 1 with groupID 0 │
│Sep 15 22:56:35 Zigbee2MQTT:debug 2020-09-15 22:56:35: Got OTA request '{"fieldControl":1,"manufacturerCode":4476,"imageType":16643,"fileVersion":553788977}' │
│Sep 15 22:56:36 Zigbee2MQTT:debug 2020-09-15 22:56:36: getNewImage for '0xled1836g9_01', meta {"fileVersion":587531825,"url":"https://fw.ota.homesmart.ikea.net/Tradfri_OTA_release_signed_2020_09_08_141305/bin/10046695-1.1-TRADFRI-light-unified-w-2.3.050.ota.ota.signed"} │
│Sep 15 22:56:36 Zigbee2MQTT:debug 2020-09-15 22:56:36: getNewImage for '0xled1836g9_01', image header {"otaUpgradeFileIdentifier":{"type":"Buffer","data":[30,241,238,11]},"otaHeaderVersion":256,"otaHeaderLength":56,"otaHeaderFieldControl":0,"manufacturerCode":4476,"imageType":16643,"fileVersion":587531825,"zigbeeStackVersion":2,"otaHeaderString":"GBL GBL_tradfri_light_unified_w\u0000","totalImageSize":203378} │
│Sep 15 22:56:36 Zigbee2MQTT:debug 2020-09-15 22:56:36: Received Zigbee message from 'led1836g9_01', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":1,"fileVersion":553788977,"imageType":16643,"manufacturerCode":4476}' from endpoint 1 with groupID 0 │
│Sep 15 22:56:44 Zigbee2MQTT:debug 2020-09-15 22:56:44: OTA update at 0%, remaining Infinity seconds │
│Sep 15 22:56:44 Zigbee2MQTT:info 2020-09-15 22:56:44: Update of 'led1836g9_01' at 0.00%
Sep 15 22:56:44 Zigbee2MQTT:info 2020-09-15 22:56:44: MQTT publish: topic 'zigbee2mqtt/led1836g9_01', payload '{"last_seen":1600203404690,"update":{"progress":0,"state":"updating"},"update_available":false}' │
│Sep 15 22:57:14 Zigbee2MQTT:debug 2020-09-15 22:57:14: OTA update at 1.43%, remaining 2648.8674227586207 seconds │
│Sep 15 22:57:14 Zigbee2MQTT:info 2020-09-15 22:57:14: Update of 'led1836g9_01' at 1.43%, +- 44 minutes remaining │
│Sep 15 22:57:14 Zigbee2MQTT:info 2020-09-15 22:57:14: MQTT publish: topic 'zigbee2mqtt/led1836g9_01', payload '{"last_seen":1600203434829,"update":{"progress":1.43,"remaining":2649,"state":"updating"},"update_available":false}'
Sep 15 23:57:49 Zigbee2MQTT:info 2020-09-15 23:57:49: Update of 'led1836g9_01' at 100.00% │
│Sep 15 23:57:49 Zigbee2MQTT:info 2020-09-15 23:57:49: MQTT publish: topic 'zigbee2mqtt/led1836g9_01', payload '{"last_seen":1600206992958,"update":{"progress":100,"state":"updating"},"update_available":false}' │
│Sep 15 23:57:49 Zigbee2MQTT:info 2020-09-15 23:57:49: Finished update of 'led1836g9_01', from '{"dateCode":"20181203","softwareBuildID":"2.1.022"}' to '{"dateCode":"20181203","softwareBuildID":"2.1.022"}' │
│Sep 15 23:57:49 Zigbee2MQTT:info 2020-09-15 23:57:49: MQTT publish: topic 'zigbee2mqtt/led1836g9_01', payload '{"last_seen":1600207069285,"update":{"state":"idle"},"update_available":false}' │
│Sep 15 23:57:50 Zigbee2MQTT:debug 2020-09-15 23:57:50: Received Zigbee message from 'led1836g9_01', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":1,"fileVersion":553788977,"imageType":16643,"manufacturerCode":4476}' from endpoint 1 with groupID 0 │
│Sep 15 23:57:50 Zigbee2MQTT:debug 2020-09-15 23:57:50: Check if update available for '0xled1836g9_01' (TRADFRI bulb E27 WW 806lm) │
│Sep 15 23:57:50 Zigbee2MQTT:debug 2020-09-15 23:57:50: Is new image available for '0xled1836g9_01', current '{"fieldControl":1,"manufacturerCode":4476,"imageType":16643,"fileVersion":553788977}', latest meta '{"fileVersion":587531825,"url":"https://fw.ota.homesmart.ikea.net/Tradfri_OTA_release_signed_2020_09_08_141305/bin/10046695-1.1-TRADFRI-light-unified-w-2.3.050.ota.ota.signed"}' │
│Sep 15 23:57:50 Zigbee2MQTT:debug 2020-09-15 23:57:50: Update available for '0xled1836g9_01': YES │
│Sep 15 23:57:50 Zigbee2MQTT:info 2020-09-15 23:57:50: MQTT publish: topic 'zigbee2mqtt/led1836g9_01', payload '{"last_seen":1600207070541,"update":{"state":"available"},"update_available":true}' │
│Sep 15 23:57:50 Zigbee2MQTT:info 2020-09-15 23:57:50: Update available for 'led1836g9_01'
Yup, I'm seeing the same behavior with both of my control outlets. Logs show the update is successful, but it stays the same version. Tried moving them to right next to the hub, also tried plugging/unplugging just in case that helped trigger the update.
mattsch
on 16 Sep 2020
@mattsch I'm seeing the same for my control outlet, but my GU10 spot updated fine. I'm not sure what the root cause, maybe something is wrong with the control outlet firmware file.
Koenkk
on 16 Sep 2020
@Koenkk Could very well be. I just got these in and the firmware they arrived with is showing 1.4.020. Hopefully there's not some intermediate firmware needed or something, the upstream json file only seems to have the latest.
mattsch
on 16 Sep 2020
I just added 8 new control outlets to my network and am stuffering the same issues. They all go through a full update but report an update available soon after.
timstanley1985
on 25 Sep 2020
@Koenkk Pleas reopen this issue then its not fixes in Z2M.
From Release Version: 1.14.0
FLOALT NA (V-2.0.029).
TRÃ…DFRI Control Outlet (V-2.0.024).
TRÃ…DFRI WS2.0 Opal(E27,E14,GU10) (v-2.0.029).
GUNNARP (IP44) EU (V-2.3.050).
SYMFONISK Sound Remote (V-2.1.024).
LEPTITER,TRÃ…DFRI E14 Chandelier, WS2.0 Clear E27/E26, GUNNARP NA (v-2.3.050).
TRÃ…DFRI WW2.0 2700K E27, 2700K GU10, 2200K Deco Bulb (V-2.3.50).
TRÃ…DFRI Open/Close Remote,TRÃ…DFRI On/Off Button (v-2.2.010).
All this "New" firmware is not new as there was released before.
If using the HTTPS json you is getting the "new" one that have broken container and also falce CRC-32 but with real "metadata" in the container heads.
Then Z2M is not checking the container and OTA-file CRC integrity the device is happy downloading it and then throwing it then the CRC and the signing is not OK (thats is very OK in zigbee then its only one transparent transport and dont need being protected then its signed and CRC protected files).
If downloading the HTTP or the test json you is getting the latest version that is not broken and its working for all devices.
The strange is that the release page was forbidden for some weeks ago and after that is the HTPPS cert was updated.
Can being that the server storage have crashed and corrupted the "new" file or some have hacking the servers or one virus have doing it (or just some crazy swedes have doing something).
Also strange IKEA is normally releasing new firmware on the test url for some weeks and then putting them on the normal release Json but My tradfri GW have getting the latest FW for the NCP and host and is working.
Zigpy / ZHA have implantating container integrity and CRC check and using the HTTP Json for updates for some days now and its working well.
MattWestb
on 28 Sep 2020
@MattWestb zigbee2mqtt is also using http, do you know how to implement such crc check? If so it would be great if you could contribute with such check (can be implemented here: https://github.com/Koenkk/zigbee-herdsman-converters/blob/master/ota/common.js#L333)
Koenkk
on 28 Sep 2020
Im sorry but im not one software programmer only hardware and sheeting little on the softside and java i only drinking not coding :-(((
Have being diagnosing, testing and brainstorming with the implanting the EZSP new protocol on Tasmota Zigbee gateway and HA / ZHA / Zigpy / belloes.
Zigpy have making one commit Reject invalid SiLabs upgrade images (#500) ater mutsch deep diving in the Silabs OTA protocol and bootloader / firmware funktions.
MattWestb
on 28 Sep 2020
@Koenkk I believe one will need to implement both the EBL parsing and GBL parsing.
I have a working EBL parser here though it is currently missing the CRC check, and I can work on the GBL if I can find such an image to test it with!
pedrolamas
on 1 Oct 2020
The OTA file in GLB format have 3 CRC checks UG103.6: Bootloader Fundamentals 5.1.2 Data Verification.
And one verified working OTA file in GBL format 10046695-1.1-TRADFRI-light-unified-w-2.1.022.ota.ota (1).zip that i have updating devices with for some month ago.
Need more ?
MattWestb
on 1 Oct 2020
If that is a GBL image, then we are good as my parser works with it! 🙂
All it needs now is the CRC validation and we are good to go!
pedrolamas
on 1 Oct 2020
Im 99% sure its is but i can testing it with Simplicity commander and trying extracting the info in EBL mode in it.
If its one EBL file its working and if one GBL its complaining.
MattWestb
on 1 Oct 2020
@MattWestb that looks to me like an EBL format, not GBL, as the first bytes of the OTA data block is 0x0000008C thus matching EBL!
I believe GBL has a different magic number here, like this shows: https://github.com/puddly/zigpy/blob/44ecfbf813d75a5de321fd869f6eb644b583709d/zigpy/ota/validators.py#L87
pedrolamas
on 1 Oct 2020
I think its one GBL because its cant being read as one EBL from commander.
PS C:\Users\Mattias\Documents\ICCA1\Simplicity Commander> .\commander.exe ebl print '.\10046695-1.1-TRADFRI-light-unified-w-2.1.022.ota.ota (1).signed'
QObject::connect: No such signal EblHandler::warning(QString)
ERROR: Unknown tag ID 0x4E47. Can't validate length.
DONE
The EBL files is outputting the info from the meta data but the GBL is complaining of the certificate (that we dont have) is not present.
Look at OTA fails and loops, size mismatch?
There you have both EBL and GBL files tested.
MattWestb
on 1 Oct 2020
Trying your parcer on all the OTA files that IKEA have and you knowing if there is OK or not.
The list of broken one is known (The "fake" new file and mented before).
MattWestb
on 1 Oct 2020
ok, now I know why my parser works: herdsman codebase has this bit to ensure we read from the correct place: https://github.com/Koenkk/zigbee-herdsman-converters/blob/7c53df8f2576bc66f81420a660c188029ec079b4/ota/common.js#L331
Which on that image matches this:
I use a similar approach: https://github.com/PedroLamas/ebl-parser/blob/985067b1fb509d5c99162e8b10b0eb8e7b464f46/index.js#L24
pedrolamas
on 1 Oct 2020
IKEA files have some secondary packaging/signature, which is visible by that "NGIS" signature on the start of the file.
@MattWestb, to test these files with commander, you will need to remove any bytes before the 1E F1 EE 0B magic bytes (highlighted on the picture I sent) and only then you can test the file.
pedrolamas
on 1 Oct 2020
The signing its not needed then the last CRC is made after the signing and if the CRC is not OK then the file is broken. Its the same for the structure then parsed and being OK its no need of the signing header only finding the rest CRCs and validating them the integrity of the firmware image.
MattWestb
on 1 Oct 2020
The "NGIS" is in little endian and normal you is writing it like "SIGN" (big endian) = the firmware is signed and have one CRC appended in the end of the file after the compleet signed firmware file.
MattWestb
on 1 Oct 2020
I'm still having this problem. Today I updated to the zigbee2mqtt dev branch and then I tried to do an ota_upgrade to a Tradfri E1743 rocker switch. It apparently acquired the file http://fw.ota.homesmart.ikea.net/global/GW1.0/01.11.051/bin/10005778-10.1-TRADFRI-onoff-shortcut-control-2.2.010.ota.ota.signed, looked at the file, noticed among other things a totalImageSize of 178838, and then failed with the comment "(Image is truncated: not long enough to contain a valid tag)".
When I "wget" that URL, the file is 180742 bytes long, which probably includes a validation signature, so an inner payload length of 178838 would be plausible.
Do the zigbee2mqtt developers know what's going on, and if so, is there a timeline to fix it?
emccreigh
on 4 Nov 2020
Its one of the not working firmware on production servers.
Patch the update to the test feed and its working well as written here https://github.com/Koenkk/zigbee2mqtt/issues/4559#issuecomment-720391106
MattWestb
on 4 Nov 2020
Bingo, that seems to have done the trick. Might it make sense to put that test URL into the tradfri.js module in zigbee2mqtt's development branch until IKEA has a complete set of zigbee2mqtt-compatible Tradfri firmware images on their production server?
emccreigh
on 4 Nov 2020
Great that is was working for you !!
I have asking but the devs have responded with no response = ?
ZHA you can putting one alternate in the config and its working without problem or downloading the OTA file and putting in the OTA directory and its using the local file ;-)))
Glad to helping you :-))
MattWestb
on 4 Nov 2020
Related issues
Underknowledge
·
4Comments
jwilling
·
4Comments
mpuff
·
3Comments
Koenkk
·
3Comments
CodeFinder2
·
4Comments
Most helpful comment
Its one of the not working firmware on production servers.
Patch the update to the test feed and its working well as written here https://github.com/Koenkk/zigbee2mqtt/issues/4559#issuecomment-720391106