search

mycontroller-org / mycontroller-v1-legacy

The Open Source Controller
http://www.MyController.org
Apache License 2.0
148 stars 90 forks source link

(FOTA) java.lang.IllegalArgumentException:null value #443

Closed adulovic closed 6 years ago

adulovic commented 6 years ago

Hi, not sure what is causing this error but it seems to prohibit FOTA from happening on my system...

Server log

2018-03-12 19:10:45,625 ERROR [Thread-5] [org.mycontroller.standalone.message.MessageMonitorThread:119] Throws exception while processing!, [RawMessage(gatewayId=1, data=010002003F03, subData=AD_gw_out/111/255/4/0/2, isTxMessage=false, networkType=MY_SENSORS, timestamp=1520896245570)]
java.lang.IllegalArgumentException: null value
    at org.mapdb.HTreeMap.put(HTreeMap.java:481)
    at org.mycontroller.standalone.firmware.FirmwareUtils.getFirmwareDataFromOfflineMap(FirmwareUtils.java:281)
    at org.mycontroller.standalone.message.McMessageEngine.procressFirmwareRequestMySensors(McMessageEngine.java:550)
    at org.mycontroller.standalone.message.McMessageEngine.streamSubMessageTypeSelector(McMessageEngine.java:504)
    at org.mycontroller.standalone.message.McMessageEngine.execute(McMessageEngine.java:125)
    at org.mycontroller.standalone.message.McMessageEngine.run(McMessageEngine.java:1117)
    at org.mycontroller.standalone.message.McMessageUtils.sendToMcMessageEngine(McMessageUtils.java:677)
    at org.mycontroller.standalone.provider.mysensors.MySensorsProviderBridge.executeRawMessage(MySensorsProviderBridge.java:59)
    at org.mycontroller.standalone.message.McMessageUtils.sendToProviderBridge(McMessageUtils.java:579)
    at org.mycontroller.standalone.message.MessageMonitorThread.processRawMessage(MessageMonitorThread.java:107)
    at org.mycontroller.standalone.message.MessageMonitorThread.run(MessageMonitorThread.java:182)
    at java.lang.Thread.run(Thread.java:748)

Resources logs detail

Mar 12, 2018 19:34:33 | Notice | Node | AD_gateway   111:000 Battery, RSSI, FOTA | Sent | Stream | [Firmware config response] 010002004003A795
Mar 12, 2018 19:34:32 | Notice | Node | AD_gateway   111:000 Battery, RSSI, FOTA | Received | Stream | [Firmware config request] 010002004003429D0102
Mar 12, 2018 19:34:30 | Notice | Node | AD_gateway   111:000 Battery, RSSI, FOTA | Sent | Stream | [Firmware config response] 010002004003A795
Mar 12, 2018 19:34:29 | Notice | Node | AD_gateway   111:000 Battery, RSSI, FOTA | Received | Stream | [Firmware config request] 010002004003429D0102

The above two lines just keep on repeating every couple of seconds. Not sure if that means the node is in a reboot loop...

Typos ?

procressFirmwareRequestMySensors -> processFirmwareRequestMySensors Discover respone -> Discover response

Node info

Using MySensorsBootloaderRF24: v1.3.0-rc.1 Using MySensors: v2.2.0 Arduino: Nano (chinese clone) with 8 analog pins Radio: NRF24L-01

define MY_NODE_ID 111

MyController

Version 1.1.0.Final Database schema revision 1.04.01 - 2017 Oct 25 Database type MySQL Database version 10.1.23-MariaDB-9+deb9u1 Git commit:branch 2bd938160d42fb36e8b47b4e9c62cad446773a5b:master Built on 2017-12-28T07:46:41+0530 Build JDK 1.8.0_151 Build tool Apache Maven 3.5.0 VM vendor Oracle Corporation VM name Java HotSpot(TM) Client VM VM version 1.8.0_162-b12 Java home /opt/jdk1.8.0_162/jre Operating system Linux Architecture arm Version/Kernel 4.9.59+

jkandasa commented 6 years ago

@adulovic Thanks for reporting this issue. I have reformated your comment to easily read.

We have changed a lot about internal design to communicate with the gateway. Can you try the version 1.2.0.Final? Kindly report back.

Thanks for the typos finding. I have updated it.

adulovic commented 6 years ago

Updated MyController to Version 1.2.0.Final

Rebooting the test node, I get the same behavior on Resources logs detail, but a slightly different error message on the server log...

This one actually says "properties=null" but I have no idea what that means in this context. Also, I notice the payload= 010003003F03 does not coincide with the resources log where I have [Firmware config request] 010003004003B7040102 and [Firmware config response] 010003004003E669

Server Log

2018-03-13 16:17:13,203 ERROR [mc-th-pool-0] [org.mycontroller.standalone.provider.EngineAbstract:261] Throws exception while processing!, [MessageImpl(gatewayId=1, nodeEui=111, sensorId=SENSOR_BC, type=Stream, subType=Firmware request, ack=0, payload=010003003F03, isTxMessage=false, timestamp=1520972232973, properties=null)]
java.lang.IllegalArgumentException: null value
    at org.mapdb.HTreeMap.put(HTreeMap.java:481)
    at org.mycontroller.standalone.firmware.FirmwareUtils.getFirmwareDataFromOfflineMap(FirmwareUtils.java:281)
    at org.mycontroller.standalone.provider.mysensors.MySensorsExecutor.executeFirmwareRequest(MySensorsExecutor.java:70)
    at org.mycontroller.standalone.provider.ExecuterAbstract.executeStream(ExecuterAbstract.java:416)
    at org.mycontroller.standalone.provider.ExecuterAbstract.execute(ExecuterAbstract.java:107)
    at org.mycontroller.standalone.provider.EngineAbstract.auditQueue(EngineAbstract.java:256)
    at org.mycontroller.standalone.provider.EngineAbstract.run(EngineAbstract.java:131)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)`
jkandasa commented 6 years ago

@adulovic Thanks for reporting back. I did minor update and change is available in SNAPSHOT version. Could you please try with SNAPSHOT version?

If you see a warning message something like this Requested firmware is not available in MyController server... kindly upload your firmware once again to MyController server and check again.

I see you are using MySQL/MariaDB, for all firmware are you getting this issue or only for this particular node?

adulovic commented 6 years ago

Updated MyController to Version 1.3.0 snapshot

Actions and findings as follows

I get a lot of these errors... makes debugging a little more difficult. Notice it still says "Discover respone" here instead of "Discover response"

2018-03-14 10:39:22,670 ERROR [mc-th-pool-0] [org.mycontroller.standalone.provider.EngineAbstract:261] Throws exception while processing!, [MessageImpl(gatewayId=1, nodeEui=4, sensorId=SENSOR_BC, type=Internal, subType=Discover respone, ack=0, payload=0, isTxMessage=false, timestamp=1521038358021, properties=null)]
java.lang.NullPointerException: null
    at org.mycontroller.standalone.provider.ExecuterAbstract.executeInternal(ExecuterAbstract.java:138)
    at org.mycontroller.standalone.provider.ExecuterAbstract.execute(ExecuterAbstract.java:86)
    at org.mycontroller.standalone.provider.EngineAbstract.auditQueue(EngineAbstract.java:256)
    at org.mycontroller.standalone.provider.EngineAbstract.run(EngineAbstract.java:131)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

After rebooting node 111 with firmware 222, I got a warning:

2018-03-14 10:45:25,771 WARN [mc-th-pool-0] [org.mycontroller.standalone.provider.mysensors.MySensorsExecutor:73] Requested firmware is not available in MyController server. FirmwareRequest[typeId:1, versionId:3, block:831]

I then tried to edit the firmwares and re-upload the hex files, which gave the following error

2018-03-14 10:48:19,833 ERROR [Acme.Utils.ThreadPool(1)-PooledThread: Acme.Serve.Serve$ServeConnection@f93ea5] [org.mycontroller.standalone.api.jaxrs.exception.mappers.ApplicationExceptionMapper:42] ApplicationException,
org.jboss.resteasy.spi.ApplicationException: java.lang.NullPointerException
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:152)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:295)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:249)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:236)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:395)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:202)
    at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:221)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
    at org.jboss.resteasy.plugins.server.tjws.TJWSServletDispatcher.service(TJWSServletDispatcher.java:40)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
    at Acme.Serve.Serve$ServeConnection.runServlet(Serve.java:2328)
    at Acme.Serve.Serve$ServeConnection.parseRequest(Serve.java:2282)
    at Acme.Serve.Serve$ServeConnection.run(Serve.java:2054)
    at Acme.Utils$ThreadPool$PooledThread.run(Utils.java:1402)
    at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.NullPointerException: null
    at org.mycontroller.standalone.firmware.FirmwareUtils.updateFirmwareHex(FirmwareUtils.java:172)
    at org.mycontroller.standalone.firmware.FirmwareUtils.createUpdateFirmware(FirmwareUtils.java:226)
    at org.mycontroller.standalone.api.jaxrs.FirmwareHandler.updateFirmware(FirmwareHandler.java:226)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:139)
    ... 15 common frames omitted

I then deleted the 3 existing firmwares from mycontroller and tried to add them again:

2018-03-14 10:51:00,492 ERROR [Acme.Utils.ThreadPool(2)-PooledThread: Acme.Serve.Serve$ServeConnection@165475c] [org.mycontroller.standalone.db.dao.BaseAbstractDaoImpl:247] unable to add new item:[FirmwareData(id=null, firmware=Firmware(id=12, type=FirmwareType(id=1, name=FOTA test node, newId=null), version=FirmwareVersion(id=1, version=v.001, newId=null), timestamp=1521039058145, properties={crc=13661, blocks=832, type=Hex, blockSize=16}, fileString=null, fileBytes=null, fileType=null, blockSize=null))]
java.sql.SQLException: Unable to run insert stmt on object FirmwareData(id=null, firmware=Firmware(id=12, type=FirmwareType(id=1, name=FOTA test node, newId=null), version=FirmwareVersion(id=1, version=v.001, newId=null), timestamp=1521039058145, properties={crc=13661, blocks=832, type=Hex, blockSize=16}, fileString=null, fileBytes=null, fileType=null, blockSize=null)): INSERT INTO `firmware_data` (`id` ,`firmwareId` ,`data` ) VALUES (?,?,?)
    at com.j256.ormlite.misc.SqlExceptionUtil.create(SqlExceptionUtil.java:25)
    at com.j256.ormlite.stmt.mapped.MappedCreate.insert(MappedCreate.java:137)
    at com.j256.ormlite.stmt.StatementExecutor.create(StatementExecutor.java:458)
    at com.j256.ormlite.dao.BaseDaoImpl.create(BaseDaoImpl.java:328)
    at org.mycontroller.standalone.db.dao.BaseAbstractDaoImpl.create(BaseAbstractDaoImpl.java:244)
    at org.mycontroller.standalone.firmware.FirmwareUtils.createUpdateFirmware(FirmwareUtils.java:243)
    at org.mycontroller.standalone.api.jaxrs.FirmwareHandler.createFirmware(FirmwareHandler.java:237)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:139)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:295)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:249)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:236)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:395)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:202)
    at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:221)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
    at org.jboss.resteasy.plugins.server.tjws.TJWSServletDispatcher.service(TJWSServletDispatcher.java:40)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
    at Acme.Serve.Serve$ServeConnection.runServlet(Serve.java:2328)
    at Acme.Serve.Serve$ServeConnection.parseRequest(Serve.java:2282)
    at Acme.Serve.Serve$ServeConnection.run(Serve.java:2054)
    at Acme.Utils$ThreadPool$PooledThread.run(Utils.java:1402)
    at java.lang.Thread.run(Thread.java:748)
Caused by: java.sql.SQLDataException: Data too long for column 'data' at row 1

So, I opened up phpMyAdmin and changed the table structure for the data field from BLOB to LONGBLOB:

ALTER TABLE `firmware_data` CHANGE `data` `data` LONGBLOB NOT NULL;

Then I tried to edit the firmware again, and got the same error as before. ...see error above...

Then I deleted the 3 firmwares and added them again, this time there was no error. .. guess we will need to use LONGBLOB :)

So I edited the node 111 again, assigned firmware 222, and rebooted the node. No errors were reported in the server log and this is what came up in the Resources logs detail:

Mar 14, 2018 11:04:32 | Notice | Node | AD_gateway   111:111 Battery, RSSI, FOTA | Sent | Stream | [Firmware config response] 010002004003790A
  | Mar 14, 2018 11:04:32 | Notice | Node | AD_gateway   111:111 Battery, RSSI, FOTA | Received | Stream | [Firmware config request] 01000200400316510102
  | Mar 14, 2018 11:04:29 | Notice | Node | AD_gateway   111:111 Battery, RSSI, FOTA | Sent | Stream | [Firmware config response] 010002004003790A
  | Mar 14, 2018 11:04:28 | Notice | Node | AD_gateway   111:111 Battery, RSSI, FOTA | Received | Stream | [Firmware config request] 01000200400316510102
  | Mar 14, 2018 11:04:24 | Notice | Node | AD_gateway   111:111 Battery, RSSI, FOTA | Sent | Internal | [Reboot]

The node came back up again but with the old version (111) still showing. I also tried refreshing the node, but still got the same version.

Then I edited node 111 again, changed firmware to version 333, issued a reboot command. ... this time there were no firmware config requests or responses in the Resources logs detail and no errors in the Server log. I will give it an hour to see if something is happening.

Additional Info

adulovic commented 6 years ago

One hour later:

jkandasa commented 6 years ago

@adulovic Thank you to narrow down the issue. I will fix it soon.

Most of my other nodes are now reported offline, but that might be unrelated.

this is the root cause: "Discover respone" here instead of "Discover response"

I have fixed this and update on SNAPSHOT build.

NOTE: This time snapshot version contains major change for REST clients. Not tested fully.

adulovic commented 6 years ago

Uploaded snapshot... Progress: Nodes are properly associating and reporting online again. No change for Node 111 - rebooted from MyController, it exchanges 4-7 firmware config requests and responses, then boots up reporting the same version.

jkandasa commented 6 years ago

@adulovic

No change for Node 111 - rebooted from MyController, it exchanges 4-7 firmware config requests and responses, then boots up reporting the same version.

I guess the problem on node side for this case. MyController just responds to node's request. Maybe communication issue(RF).

adulovic commented 6 years ago

The node is in the same room as the gateway, and it reports battery and rssi properly and consistently. What I'm wondering about is this:

Mar 15, 2018 11:33:18 | Notice | Node | AD_gateway   111:111 Battery, RSSI, FOTA | Sent | Stream | [Firmware config response] 010003004003D4F4
  | Mar 15, 2018 11:33:18 | Notice | Node | AD_gateway   111:111 Battery, RSSI, FOTA | Received | Stream | [Firmware config request] 01000300400316510102
  | Mar 15, 2018 11:33:10 | Notice | Node | AD_gateway   111:111 Battery, RSSI, FOTA | Sent | Internal | [Reboot]

If this number is a hash of the hex file, seems like they are not matching after 010003004003...

Would you like me to send you the ino and hex files?

adulovic commented 6 years ago

I edited the node just now, and changed the firmware version to v.222. After rebooting, I get:

  | Mar 15, 2018 11:39:51 | Notice | Node | AD_gateway   111:111 Battery, RSSI, FOTA | Sent | Stream | [Firmware config response] 010002004003790A
  | Mar 15, 2018 11:39:51 | Notice | Node | AD_gateway   111:111 Battery, RSSI, FOTA | Received | Stream | [Firmware config request] 01000300400316510102
  | Mar 15, 2018 11:39:44 | Notice | Node | AD_gateway   111:111 Battery, RSSI, FOTA | Sent | Internal | [Reboot]

It is clearly showing same config request with different config response, so I guess the issue lies elsewhere.

This is what the node shows after rebooting:

AD_gateway [MQTT] | MySensors | Registered | 111 | 111 Battery, RSSI, FOTA | Repeater node | -29 dBm | 34 % | 2.2.0 | 111 | FOTA test node:v.002 | 4 minutes ago

It should be showing

AD_gateway [MQTT] | MySensors | Registered | 111 | 222 Battery, RSSI, FOTA | Repeater node | -29 dBm | 34 % | 2.2.0 | 222 | FOTA test node:v.002 | 4 minutes ago

What else could I check?

jkandasa commented 6 years ago

@adulovic looks like Node not taking MyController's response and repeatedly asking firmware request.

Arduino: Nano (chinese clone) with 8 analog pins

I see that you are using a cloned version of Arduino. I too have this issue on clone board. If I re-burn bootloader everything works for some time or few days. I believe it is painful to burn a bootloader. You need to go with ISP wirings. You should give a try.

What is the power source are you using for this node and are you using 10uf capacitor for NRF24L01+ board?

adulovic commented 6 years ago

The bootloader was burned (a few times) using USBasp. http://a.co/j2UVEEK Burning the bootloader is not an issue at this (testing) stage.

The Arduino Nano is a V3.0 ATmega328P 5V 16MHz http://a.co/3I88Epp It is powered via usb cable, stable 5.0V.

The NRF24L01+ http://a.co/6mtYr0Q is powered by 3.3V from the arduino itself, and the radio power is set to HIGH (also tried with LOW, MID and MAX). I also have a 4.7uF capacitor http://a.co/d0BhhyZ connected.

I don't think it is a radio issue at all. My (uneducated) guess would be it's something to do with acknowledgement of message or stream sizing.

Looking at the gateway now.. Should the "ack enabled" be on or off? What are the values that work for you on a MQTT Gateway?

adulovic commented 6 years ago

found: (in ...\libraries\MySensors/drivers/PubSubClient/PubSubClient.h)

define MQTT_MAX_PACKET_SIZE 128

trying to override it with:

define MQTT_MAX_PACKET_SIZE 512 in the sketch

seeing progress now...

...and it worked, finally!

jkandasa commented 6 years ago

@adulovic Great finding. But firmware request/response should be less than 128 bytes. We need to check with MySensors community. MyController supports native device via MQTT, There I am using 512 bytes. As MyController sends more than 128 bytes there.

Looking at the gateway now.. Should the "ack enabled" be on or off? What are the values that work for you on a MQTT Gateway?

When you enable(checked) ack, MyController expects an acknowledgment from the node.If the node fails to send within the expected time, MyController resends the data again. This will happen till the maximum retry count.

NOTE: When we enable ack for a gateway firmware update will take more time. as it doubles the data rate.

Example:

image

Here ack enabled with 5 retry counts. And MyController waits for 1 second(1000 milliseconds) for ack from the node, if the node fails to send ack within 1 second, MyController resends the data again.

adulovic commented 6 years ago

You're right... It only worked the first time. The second test failed. I will experiment with different radio powers and packet sizes over the weekend (if time permits) and let you know what I find. Thanks for the support, it's appreciated!

jkandasa commented 6 years ago

@adulovic I have moved firmware data from DB to disk in this fix. can you verify it in SNAPSHOT version?

adulovic commented 6 years ago

Sorry man, was away from home for a few months... Will probably find some time for the home automation this weekend. What needs to be checked/verified?

Cheers, Aleksandar Dulović

On Tue, Jun 12, 2018 at 9:55 AM Jeeva Kandasamy notifications@github.com wrote:

@adulovic https://github.com/adulovic I have moved firmware data from DB to disk in this fix. can you verify it in SNAPSHOT https://drive.google.com/drive/u/0/folders/0BzuumrtRA7p6Z0hCX2V6cVh2ckU version?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/mycontroller-org/mycontroller/issues/443#issuecomment-396597731, or mute the thread https://github.com/notifications/unsubscribe-auth/ABUwlujkOrnvvdHRnj2-P7RnPHJubbtcks5t78hDgaJpZM4Sn3DU .

jkandasa commented 6 years ago

@adulovic I have moved firmware data from database to disk. Hope this time firmware update(OTA) will work properly for you in SNAPSHOT version.