search

tlaukkan / zigbee4java

Zigbee API for Java provides simple Java interface to ZigBee network.
Apache License 2.0
144 stars 68 forks source link

Timeout issue #31

Closed cdjackson closed 8 years ago

cdjackson commented 9 years ago

This is an example of the timeouts I'm currently seeing. This isn't the only error, but it's one I captured in the console and will try and investigate -:

on 0
17:41:46 291  DEBUG  Sending EmptyPayloadCommand command to 00:17:88:01:00:DC:88:0B/11 (#19281).
17:41:46 291  DEBUG  Skipped to registered 00:17:88:01:00:DC:88:0B/11 as org.bubblecloud.zigbee.network.ApplicationFrameworkMessageListener
17:41:46 292  DEBUG  -> AF_DATA_REQUEST (Packet: length = 13, apiId = 0x24 0x01, full data = 0xfe 0x0d 0x24 0x01 0x51 0x4b 0x0b 0x01 0x06 0x00 0x07 0x00 0x00 0x03 0x01 0x06 0x01 0x3c, checksum = 0x3c, error = false, errorMessage = null) 
17:41:46 303  DEBUG  <- AF_DATA_SRSP (AF_DATA_SRSP{Status=SUCCESS(0)})
17:41:46 309  DEBUG  <-- AF_DATA_CONFIRM (AF_DATA_CONFIRM{Endpoint=1, Status=SUCCESS(0), TransID=158})
17:41:46 326  DEBUG  <-- AF_INCOMING_MSG (Packet: length = 25, apiId = 0x44 0x81, full data = 0xfe 0x19 0x44 0x81 0x00 0x00 0x06 0x00 0x51 0x4b 0x0b 0x01 0x00 0x17 0x00 0xfd 0xa9 0xa6 0x00 0x00 0x05 0x18 0x06 0x0b 0x01 0x00 0x51 0x4b 0x1d 0x39, checksum = 0x39, error = false, errorMessage = null)
17:41:46 326  DEBUG  Received AF_INCOMING_MSG from 19281 and cluster 6 to end point 1. Data: Packet: length = 25, apiId = 0x44 0x81, full data = 0xfe 0x19 0x44 0x81 0x00 0x00 0x06 0x00 0x51 0x4b 0x0b 0x01 0x00 0x17 0x00 0xfd 0xa9 0xa6 0x00 0x00 0x05 0x18 0x06 0x0b 0x01 0x00 0x51 0x4b 0x1d 0x39, checksum = 0x39, error = false, errorMessage = null
17:41:46 326  DEBUG  AF_INCOMING_MSG arrived for 00:17:88:01:00:DC:88:0B/11 message is Packet: length = 25, apiId = 0x44 0x81, full data = 0xfe 0x19 0x44 0x81 0x00 0x00 0x06 0x00 0x51 0x4b 0x0b 0x01 0x00 0x17 0x00 0xfd 0xa9 0xa6 0x00 0x00 0x05 0x18 0x06 0x0b 0x01 0x00 0x51 0x4b 0x1d 0x39, checksum = 0x39, error = false, errorMessage = null
17:41:46 327  DEBUG  Skipped unregistration of 00:17:88:01:00:DC:88:0B/11 as org.bubblecloud.zigbee.network.ApplicationFrameworkMessageListener
17:41:46 328  DEBUG  Received response [ ZCL Header: 0x18 0x06 0x0b, ZCL Payload: 0x01 0x00] to request [ ZCL Header: 0x01 0x06 0x01, ZCL Payload: ]

I think this is the end of the transaction - the interesting thing (I think) is that it skipped the unregistration of the message listener - why?

Next it does what I assume is a routine network inspection - I don't think this is relevant, but I've left it in to complete the log...

> 17:41:47 024  DEBUG  Network browsing completed, waiting until 1428943307011
17:41:47 024  DEBUG  Inspecting ZigBee network for new nodes.
17:41:47 025  DEBUG  -> ZDO_IEEE_ADDR_REQ (Packet: length = 4, apiId = 0x25 0x01, full data = 0xfe 0x04 0x25 0x01 0x00 0x00 0x00 0x00 0x20, checksum = 0x20, error = false, errorMessage = null) 
17:41:47 031  DEBUG  <- ZDO_IEEE_ADDR_REQ_SRSP (ZDO_IEEE_ADDR_REQ_SRSP{Status=SUCCESS(0)})
17:41:47 040  DEBUG  <-- ZDO_IEEE_ADDR_RSP (ZDO_IEEE_ADDR_RSP{AssocDevList=[], assocDevList=[], IEEEAddr=0x00 0x12 0x4b 0x00 0x02 0xf1 0xdb 0x5b, nwkAddr=0x00 0x00, NumAssocDev=0, SrcAddress=null, SrcAddrMode=0, StartIndex=0, Status=SUCCESS(0)})
17:41:47 040  DEBUG  ZDO_IEEE_ADDR_RSP from 0x00 0x12 0x4b 0x00 0x02 0xf1 0xdb 0x5b with 0 associated
17:41:47 040  DEBUG  -> ZB_GET_DEVICE_INFO (Packet: length = 1, apiId = 0x26 0x06, full data = 0xfe 0x01 0x26 0x06 0x06 0x27, checksum = 0x27, error = false, errorMessage = null) 
17:41:47 044  DEBUG  <- ZB_GET_DEVICE_INFO_RSP (Packet: length = 9, apiId = 0x66 0x06, full data = 0xfe 0x09 0x66 0x06 0x06 0x01 0x00 0x01 0x80 0x00 0xeb 0x00 0x00 0x04, checksum = 0x04, error = false, errorMessage = null)
17:41:47 044  DEBUG  ZDO_MGMT_LQI_REQ to 0 from index 0
17:41:47 044  DEBUG  Inspecting device 00:12:4B:00:02:F1:DB:5B.
17:41:47 044  DEBUG  Endpoint inspection completed, next inspection slot in 0
17:41:47 045  DEBUG  -> ZDO_MGMT_LQI_REQ (Packet: length = 3, apiId = 0x25 0x31, full data = 0xfe 0x03 0x25 0x31 0x00 0x00 0x00 0x17, checksum = 0x17, error = false, errorMessage = null) 
17:41:47 051  DEBUG  <- ZDO_MGMT_LQI_REQ_SRSP (ZDO_MGMT_LQI_REQ_SRSP{Status=SUCCESS(0)})
17:41:47 059  DEBUG  <-- ZDO_MGMT_LQI_RSP (ZDO_MGMT_LQI_RSP{NeighborLQICount=1, NeighborLQIEntries=1, NeighborLqiList=[org.bubblecloud.zigbee.network.packet.zdo.ZDO_MGMT_LQI_RSP$NeighborLqiListItemClass@7f861456], SrcAddress=0x00 0x00, StartIndex=0, Status=SUCCESS(0)})
17:41:47 059  DEBUG  Found 1 neighbors on node 0
17:41:47 059  DEBUG  Node #19281 visible from node #0 with LQI value 24
17:41:47 059  DEBUG  -> ZDO_IEEE_ADDR_REQ (Packet: length = 4, apiId = 0x25 0x01, full data = 0xfe 0x04 0x25 0x01 0x51 0x4b 0x00 0x00 0x3a, checksum = 0x3a, error = false, errorMessage = null) 
17:41:47 069  DEBUG  <- ZDO_IEEE_ADDR_REQ_SRSP (ZDO_IEEE_ADDR_REQ_SRSP{Status=SUCCESS(0)})
17:41:47 104  DEBUG  <-- ZDO_IEEE_ADDR_RSP (ZDO_IEEE_ADDR_RSP{AssocDevList=[], assocDevList=[], IEEEAddr=0x00 0x17 0x88 0x01 0x00 0xdc 0x88 0x0b, nwkAddr=0x4b 0x51, NumAssocDev=0, SrcAddress=null, SrcAddrMode=0, StartIndex=0, Status=SUCCESS(0)})
17:41:47 104  DEBUG  ZDO_IEEE_ADDR_RSP from 0x00 0x17 0x88 0x01 0x00 0xdc 0x88 0x0b with 0 associated
17:41:47 106  DEBUG  -> ZB_GET_DEVICE_INFO (Packet: length = 1, apiId = 0x26 0x06, full data = 0xfe 0x01 0x26 0x06 0x06 0x27, checksum = 0x27, error = false, errorMessage = null) 
17:41:47 109  DEBUG  <- ZB_GET_DEVICE_INFO_RSP (Packet: length = 9, apiId = 0x66 0x06, full data = 0xfe 0x09 0x66 0x06 0x06 0x01 0x00 0x00 0x00 0x00 0x80 0x00 0x2b 0xc5, checksum = 0xc5, error = false, errorMessage = null)
17:41:47 109  DEBUG  Node #19281 is 00:17:88:01:00:DC:88:0B
17:41:47 109  DEBUG  Inspecting device 00:17:88:01:00:DC:88:0B.
17:41:47 109  DEBUG  ZDO_MGMT_LQI_REQ to 19281 from index 0
17:41:47 110  DEBUG  Endpoint inspection completed, next inspection slot in 0
17:41:47 110  DEBUG  -> ZDO_MGMT_LQI_REQ (Packet: length = 3, apiId = 0x25 0x31, full data = 0xfe 0x03 0x25 0x31 0x51 0x4b 0x00 0x0d, checksum = 0x0d, error = false, errorMessage = null) 
17:41:47 120  DEBUG  <- ZDO_MGMT_LQI_REQ_SRSP (ZDO_MGMT_LQI_REQ_SRSP{Status=SUCCESS(0)})
17:41:47 152  DEBUG  <-- ZDO_MGMT_LQI_RSP (ZDO_MGMT_LQI_RSP{NeighborLQICount=1, NeighborLQIEntries=2, NeighborLqiList=[org.bubblecloud.zigbee.network.packet.zdo.ZDO_MGMT_LQI_RSP$NeighborLqiListItemClass@4c0147e3], SrcAddress=0x4b 0x51, StartIndex=0, Status=SUCCESS(0)})
17:41:47 153  DEBUG  Found 1 neighbors on node 19281
17:41:47 153  DEBUG  Node #0 visible from node #19281 with LQI value 247
17:41:47 154  DEBUG  -> ZDO_IEEE_ADDR_REQ (Packet: length = 4, apiId = 0x25 0x01, full data = 0xfe 0x04 0x25 0x01 0x00 0x00 0x00 0x00 0x20, checksum = 0x20, error = false, errorMessage = null) 
17:41:47 160  DEBUG  <- ZDO_IEEE_ADDR_REQ_SRSP (ZDO_IEEE_ADDR_REQ_SRSP{Status=SUCCESS(0)})
17:41:47 168  DEBUG  <-- ZDO_IEEE_ADDR_RSP (ZDO_IEEE_ADDR_RSP{AssocDevList=[], assocDevList=[], IEEEAddr=0x00 0x12 0x4b 0x00 0x02 0xf1 0xdb 0x5b, nwkAddr=0x00 0x00, NumAssocDev=0, SrcAddress=null, SrcAddrMode=0, StartIndex=0, Status=SUCCESS(0)})
17:41:47 168  DEBUG  ZDO_IEEE_ADDR_RSP from 0x00 0x12 0x4b 0x00 0x02 0xf1 0xdb 0x5b with 0 associated
17:41:47 168  DEBUG  -> ZB_GET_DEVICE_INFO (Packet: length = 1, apiId = 0x26 0x06, full data = 0xfe 0x01 0x26 0x06 0x06 0x27, checksum = 0x27, error = false, errorMessage = null) 
17:41:47 171  DEBUG  <- ZB_GET_DEVICE_INFO_RSP (Packet: length = 9, apiId = 0x66 0x06, full data = 0xfe 0x09 0x66 0x06 0x06 0x01 0x00 0x01 0x80 0x00 0xef 0x00 0x00 0x00, checksum = 0x00, error = false, errorMessage = null)
17:41:47 172  DEBUG  Node #0 is 00:12:4B:00:02:F1:DB:5B
17:41:47 172  DEBUG  Node 0 inspected few seconds ago, request delayed

And then I turn the light off...

off 0
17:41:54 421  DEBUG  Sending EmptyPayloadCommand command to 00:17:88:01:00:DC:88:0B/11 (#19281).
17:41:54 421  DEBUG  Skipped to registered 00:17:88:01:00:DC:88:0B/11 as org.bubblecloud.zigbee.network.ApplicationFrameworkMessageListener
17:41:54 423  DEBUG  -> AF_DATA_REQUEST (Packet: length = 13, apiId = 0x24 0x01, full data = 0xfe 0x0d 0x24 0x01 0x51 0x4b 0x0b 0x01 0x06 0x00 0x08 0x00 0x00 0x03 0x01 0x07 0x00 0x33, checksum = 0x33, error = false, errorMessage = null) 
17:41:54 434  DEBUG  <- AF_DATA_SRSP (AF_DATA_SRSP{Status=SUCCESS(0)})
17:41:54 442  DEBUG  <-- AF_DATA_CONFIRM (AF_DATA_CONFIRM{Endpoint=1, Status=SUCCESS(0), TransID=167})
17:41:54 458  DEBUG  <-- AF_INCOMING_MSG (Packet: length = 25, apiId = 0x44 0x81, full data = 0xfe 0x19 0x44 0x81 0x00 0x00 0x06 0x00 0x51 0x4b 0x0b 0x01 0x00 0x17 0x00 0x42 0x0d 0xa7 0x00 0x00 0x05 0x18 0x07 0x0b 0x00 0x00 0x51 0x4b 0x1d 0x23, checksum = 0x23, error = false, errorMessage = null)
17:41:54 458  DEBUG  Received AF_INCOMING_MSG from 19281 and cluster 6 to end point 1. Data: Packet: length = 25, apiId = 0x44 0x81, full data = 0xfe 0x19 0x44 0x81 0x00 0x00 0x06 0x00 0x51 0x4b 0x0b 0x01 0x00 0x17 0x00 0x42 0x0d 0xa7 0x00 0x00 0x05 0x18 0x07 0x0b 0x00 0x00 0x51 0x4b 0x1d 0x23, checksum = 0x23, error = false, errorMessage = null
17:41:54 460  DEBUG  AF_INCOMING_MSG arrived for 00:17:88:01:00:DC:88:0B/11 message is Packet: length = 25, apiId = 0x44 0x81, full data = 0xfe 0x19 0x44 0x81 0x00 0x00 0x06 0x00 0x51 0x4b 0x0b 0x01 0x00 0x17 0x00 0x42 0x0d 0xa7 0x00 0x00 0x05 0x18 0x07 0x0b 0x00 0x00 0x51 0x4b 0x1d 0x23, checksum = 0x23, error = false, errorMessage = null
17:41:59 445  DEBUG  Unregistered 00:17:88:01:00:DC:88:0B/11 as org.bubblecloud.zigbee.network.ApplicationFrameworkMessageListener

> org.bubblecloud.zigbee.api.ZigBeeDeviceException: org.bubblecloud.zigbee.api.cluster.impl.api.core.ZigBeeClusterException: org.bubblecloud.zigbee.network.impl.ZigBeeBasedriverTimeOutException: Timeout expired before receiving any data
    at org.bubblecloud.zigbee.api.cluster.impl.OnOffImpl.off(OnOffImpl.java:82)
    at org.bubblecloud.zigbee.ZigBeeConsole$OffCommand.process(ZigBeeConsole.java:777)
    at org.bubblecloud.zigbee.ZigBeeConsole.executeCommand(ZigBeeConsole.java:215)
    at org.bubblecloud.zigbee.ZigBeeConsole.processInputLine(ZigBeeConsole.java:190)
    at org.bubblecloud.zigbee.ZigBeeConsole.start(ZigBeeConsole.java:166)
    at org.bubblecloud.zigbee.ZigBeeConsoleJavaSE.main(ZigBeeConsoleJavaSE.java:34)
Caused by: org.bubblecloud.zigbee.api.cluster.impl.api.core.ZigBeeClusterException: org.bubblecloud.zigbee.network.impl.ZigBeeBasedriverTimeOutException: Timeout expired before receiving any data
    at org.bubblecloud.zigbee.api.cluster.impl.core.ZCLClusterBase.invoke(ZCLClusterBase.java:119)
    at org.bubblecloud.zigbee.api.cluster.impl.core.ZCLClusterBase.invoke(ZCLClusterBase.java:96)
    at org.bubblecloud.zigbee.api.cluster.impl.general.OnOffCluster.off(OnOffCluster.java:94)
    at org.bubblecloud.zigbee.api.cluster.impl.OnOffImpl.off(OnOffImpl.java:78)
    ... 5 more
Caused by: org.bubblecloud.zigbee.network.impl.ZigBeeBasedriverTimeOutException: Timeout expired before receiving any data
    at org.bubblecloud.zigbee.network.impl.ZigBeeEndpointImpl.invoke(ZigBeeEndpointImpl.java:379)
    at org.bubblecloud.zigbee.api.cluster.impl.core.ZCLClusterBase.invoke(ZCLClusterBase.java:114)
    ... 8 more

Here I get a timeout, even though the response is received ok (apparently). I suspect that this is because there are now two message listeners since the first one wasn't unregistered. One of the two listeners is receiving the response (presumably the first one that wasn't unregistered), and the other (presumably the second) times out!

smulikHakipod commented 9 years ago

You get this timeouts constantly? are you running on the main thread? if not, can you run the commands on the main thread just for testing?

cdjackson commented 9 years ago

I get the timeouts regularly - not every time, but quite often. Not just timeouts, but other errors as well that I’ve not had the time to look into yet.

What do you mean exactly by running it on the main thread? This error was when running in the console - I’ve not looked too closely at what threads get spawned in the stack...

smulikHakipod commented 9 years ago

The console is running on the main thread, commands invoked from the console should be run on the main thread, so it may be a different issue from #32 All those issues are really strange..

tlaukkan commented 9 years ago

This code is originating from zigbee4osgi so take my analysis with a grain of salt.

I think the AF message listener part is working correctly and even if you had two AF message listeners for the ZigBeeEndpointImpl it should not cause this kind of problems as they would still process the response message the same way for the ZigBeeEndpointImpl and pass the message to consumers (WaitForClusterResponse) or listeners (ClusterListener).

One culprit could be that the consume method in WaitForClusterResponse does not seem to match request and response pairs properly. I am not sure if there is mechanism for 100% matching in the AF_DATA_REQUEST and AF_INCOMING_MESSAGE as transaction sequence numbers seem to be used to number the messages in downstream and upstream separately for AF_DATA_REQUEST and AF_DATA_CONFIRM where as AF_INCOMING_MESSAGE always has 0.

Could it be that when switching between applications you are receiving incoming AF messages intended to your application to the console application? Does the problem occur if you run console after plugging in and out the dongle?

Do you see any errors in the serial interface layer? If not then it is questionable whether port speed is causing or affecting this problem.

tlaukkan commented 8 years ago

The AF_DATA_REQUEST and AF_INCOMING_MESSAGE pairing is now fixed by using transaction IDs in ZCL message headers. If time outs still occur please reopen this ticket.