NPE during Aeon Smart Switch 6 inclusion

[openhab]

NPE during Aeon Smart Switch 6 inclusion

[cdjackson]

Please can you provide the unfiltered log - I need to see the received data which comes from shortly before this.

[IOOOTAlan]

Sure, here it is: zwave.log.zip

[cdjackson]

Sorry - just noticed you included a link to the full log so I’ll take a look at that - don’t bother sending anything else at this time.

[IOOOTAlan]

Whoops, I thought you missed useful bits from the first zip so I uploaded a more complete one where there are also other device nodes 😅

[cdjackson]

Unfortunately you have a very non-standard log format which makes it impossible for me to process :(. I'll process this by hand, but just to note that it would be really useful if you can use the standard format otherwise it's really a lot of work :(

[cdjackson]

I can't really see any issue here. The only strange thing I can see is the frame seems to have extra bytes, but that shouldn't cause it any major issue. I ran a test with the same data as in th frame and it worked fine.
I found an error in the converter, but I don't think that's an issue here since you have no items/channels defined. You can try the next snapshot, but otherwise I'm not sure what to do next at the moment.

[IOOOTAlan]

I'm sorry for the logs, I didn't know they would be troublesome: I've put all log appenders in the same file and then filtered the zwave messages via grep... Comparing these logs with those produced by the binding when they're put in a standalone file, I guess the | 238 - org.openhab.binding.zwave - 2.0.0.201609182202 | part in every line is the one that broke your processing tools, right? I will make sure to provide better logs next time.
Back to the issue, I'll try your fix soon!

[IOOOTAlan]

I just tried the latest SNAPSHOT build (build #113 on cloudbees) but the exception is still there:

2016-09-21 10:41:59.661 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=57 00 00 02 00 D0 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
2016-09-21 10:41:59.663 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 8: SendData Request. CallBack ID = 87, Status = Transmission complete and ACK received(0)
2016-09-21 10:41:59.665 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=8, callback=87, payload=08 02 33 01 
2016-09-21 10:41:59.667 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=57 00 00 02 00 D0 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
2016-09-21 10:41:59.669 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=87, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2016-09-21 10:41:59.670 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-09-21 10:41:59.672 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0B 00 04 00 08 04 33 02 1C 00 D0 01 
2016-09-21 10:41:59.674 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0B 00 04 00 08 04 33 02 1C 00 D0 01 
2016-09-21 10:41:59.676 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 08 04 33 02 1C 00 D0 
2016-09-21 10:41:59.678 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 8: Application Command Request (ALIVE:STATIC_VALUES)
2016-09-21 10:41:59.680 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 8: Incoming command class COLOR
2016-09-21 10:41:59.681 [DEBUG] [.commandclass.ZWaveColorCommandClass] - NODE 8: Received COMMAND_CLASS_SWITCH_COLOR V1
2016-09-21 10:41:59.683 [DEBUG] [.commandclass.ZWaveColorCommandClass] - NODE 8: Process SWITCH_COLOR_SUPPORTED_REPORT
2016-09-21 10:41:59.684 [DEBUG] [.commandclass.ZWaveColorCommandClass] - NODE 8: Color Supported = Red(2)
2016-09-21 10:41:59.686 [DEBUG] [.commandclass.ZWaveColorCommandClass] - NODE 8: Color Supported = Green(3)
2016-09-21 10:41:59.687 [DEBUG] [.commandclass.ZWaveColorCommandClass] - NODE 8: Color Supported = Blue(4)
2016-09-21 10:41:59.689 [ERROR] [ve.internal.protocol.ZWaveController] - Exception during ZWave thread: Input 2. {}
java.lang.NullPointerException
    at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveColorCommandClass.processColorSupportedReport(ZWaveColorCommandClass.java:148)[246:org.openhab.binding.zwave:2.0.0.201609202148]
    at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveColorCommandClass.handleApplicationCommandRequest(ZWaveColorCommandClass.java:96)[246:org.openhab.binding.zwave:2.0.0.201609202148]
    at org.openhab.binding.zwave.internal.protocol.serialmessage.ApplicationCommandMessageClass.handleRequest(ApplicationCommandMessageClass.java:119)[246:org.openhab.binding.zwave:2.0.0.201609202148]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:247)[246:org.openhab.binding.zwave:2.0.0.201609202148]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:213)[246:org.openhab.binding.zwave:2.0.0.201609202148]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$7(ZWaveController.java:207)[246:org.openhab.binding.zwave:2.0.0.201609202148]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1303)[246:org.openhab.binding.zwave:2.0.0.201609202148]
2016-09-21 10:42:04.616 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 8: Timeout while sending message. Requeueing - 2 attempts left!

Here's the complete (hopefully in the right format) log: aeon_smartswitch6_2.log.zip

[cdjackson]

Thanks - I didn’t really think this would be solved with the update as the bug I found was in the converter and not in the command class itself. It’s strange that I can’t replicate this with the unit tests - I’ll have another look tonight.

[cdjackson]

I will push an update tonight that I think will fix this. However, more importantly is I want to get a log so I can find out what causes it as I’ve now added some extra logging to find what is null.

[IOOOTAlan]

I think we now got the culprit:

2016-09-22 07:53:54.651 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0B 00 04 00 09 04 33 02 1C 00 CF 1F 
2016-09-22 07:53:54.657 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0B 00 04 00 09 04 33 02 1C 00 CF 1F 
2016-09-22 07:53:54.659 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 09 04 33 02 1C 00 CF 
2016-09-22 07:53:54.660 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 9: Application Command Request (ALIVE:STATIC_VALUES)
2016-09-22 07:53:54.670 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 9: Incoming command class COLOR
2016-09-22 07:53:54.671 [DEBUG] [.commandclass.ZWaveColorCommandClass] - NODE 9: Received COMMAND_CLASS_SWITCH_COLOR V1
2016-09-22 07:53:54.674 [DEBUG] [.commandclass.ZWaveColorCommandClass] - NODE 9: Process SWITCH_COLOR_SUPPORTED_REPORT
2016-09-22 07:53:54.676 [DEBUG] [.commandclass.ZWaveColorCommandClass] - NODE 9: Color Supported = Red(2)
2016-09-22 07:53:54.679 [DEBUG] [.commandclass.ZWaveColorCommandClass] - NODE 9: Color Supported = Green(3)
2016-09-22 07:53:54.683 [DEBUG] [.commandclass.ZWaveColorCommandClass] - NODE 9: Color Supported = Blue(4)
2016-09-22 07:53:54.685 [DEBUG] [.commandclass.ZWaveColorCommandClass] - NODE 9: Endpoint is null in processColorSupportedReport
2016-09-22 07:53:54.687 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=9, callback=87, payload=09 02 33 01

I'm also attaching complete logs for node 9: aeon_smartswitch6-NPE.log.zip

[cdjackson]

Hopefully this is fixed, and you should also now get a color widget if you delete and add the thing back in.

[IOOOTAlan]

I can confirm that the error is gone and that there's now a color widget in the UI, however it seems like it doesn't change the current color being displayed by the device. Maybe it's the color for a "high load" setting that I cannot test on the device ATM.