[SOLVED] Failed to initialize Zigbee transport layer [Xbee S2C]

Mehdi_Marzougui · March 8, 2022, 3:18pm

I am using an S2C XBee radio, so far I could not use the zigbee binding properly to connect it to the openhab server, the state of the thing(Xbee coordinator) keeps toggeling betwenn unknown and offline.

In the log it keeps mentioning this message :

16:11:38.579 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:coordinator_xbee:bfd2fb6547' changed from UNKNOWN to OFFLINE: Failed to initialize ZigBee transport layer

The full log is:

16:13:41.404 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
16:13:41.404 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
16:13:41.404 [DEBUG] [inding.zigbee.serial.ZigBeeSerialPort] - Connecting to serial port [COM4] at 9600 baud, flow control FLOWCONTROL_OUT_NONE.
16:13:41.404 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=INITIALISING
16:13:41.538 [DEBUG] [inding.zigbee.serial.ZigBeeSerialPort] - Serial port [COM4] is initialized.
16:13:41.672 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: have 8 bytes available
16:13:41.672 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: try read  8 at offset 0
16:13:41.672 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: did read 8 of 8 at offset 0
16:13:52.194 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: have 8 bytes available
16:13:52.194 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: try read  8 at offset 0
16:13:52.194 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: did read 8 of 8 at offset 0
16:14:02.714 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: have 8 bytes available
16:14:02.719 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: try read  8 at offset 0
16:14:02.719 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: did read 8 of 8 at offset 0
16:14:13.184 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=OFFLINE
16:14:13.184 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:coordinator_xbee:bfd2fb6547' changed from UNKNOWN to OFFLINE: Failed to initialize ZigBee transport layer
16:14:13.184 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:coordinator_xbee:bfd2fb6547' changed from OFFLINE: Failed to initialize ZigBee transport layer to OFFLINE (COMMUNICATION_ERROR)
16:14:18.192 [INFO ] [gbee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
16:14:18.192 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=SHUTDOWN
16:14:18.406 [DEBUG] [inding.zigbee.serial.ZigBeeSerialPort] - Serial port 'COM4' closed.
16:14:18.406 [DEBUG] [nding.zigbee.xbee.handler.XBeeHandler] - Initializing ZigBee XBee serial bridge handler.
16:14:18.406 [DEBUG] [nding.zigbee.xbee.handler.XBeeHandler] - ZigBee XBee Coordinator opening Port:'COM4' PAN:658a, EPAN:5FFAA68B264B646E, Channel:11
16:14:18.406 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start
16:14:18.406 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:coordinator_xbee:bfd2fb6547' changed from OFFLINE (COMMUNICATION_ERROR) to UNKNOWN

chris · March 8, 2022, 8:30pm

Please can you enable debug logging so that we get the zigbee logs. Take a look at the binding docs as it’s explained there how to do this.

Mehdi_Marzougui · March 9, 2022, 1:04am

Hey Chris,

Thank you for you answer, I am quite new to this, so I am not sure what you are exactly asking me to provide.

Here is what I did based on my understanding of what is written in the openhab zigbee binding page:


                           _   _     _     ____
   ___   ___   ___   ___  | | | |   / \   | __ )
  / _ \ / _ \ / _ \ / _ \ | |_| |  / _ \  |  _ \
 | (_) | (_) |  __/| | | ||  _  | / ___ \ | |_) )
  \___/|  __/ \___/|_| |_||_| |_|/_/   \_\|____/
       |_|       3.2.0 - Release Build

Use '<tab>' for a list of available commands
and '[cmd] --help' for help on a specific command.
To exit, use '<ctrl-d>' or 'logout'.

openhab> log:set trace org.openhab.binding.zigbee
openhab> log:tail
01:58:10.588 [DEBUG] [gbee.xbee.internal.XBeeHandlerFactory] - bundle org.openhab.binding.zigbee.xbee:3.2.0 (256)[org.openhab.binding.zigbee.xbee.internal.XBeeHandlerFactory(306)] : invoking bind: setZigBeeChannelConverterFactory: parameters [org.openhab.binding.zigbee.internal.converter.ZigBeeChannelConverterFactoryImpl]
01:58:10.588 [DEBUG] [gbee.xbee.internal.XBeeHandlerFactory] - bundle org.openhab.binding.zigbee.xbee:3.2.0 (256)[org.openhab.binding.zigbee.xbee.internal.XBeeHandlerFactory(306)] : invoked bind: setZigBeeChannelConverterFactory
01:58:10.588 [DEBUG] [gbee.xbee.internal.XBeeHandlerFactory] - bundle org.openhab.binding.zigbee.xbee:3.2.0 (256)[org.openhab.binding.zigbee.xbee.internal.XBeeHandlerFactory(306)] : getting activate: activate
01:58:10.588 [DEBUG] [gbee.xbee.internal.XBeeHandlerFactory] - bundle org.openhab.binding.zigbee.xbee:3.2.0 (256)[org.openhab.binding.zigbee.xbee.internal.XBeeHandlerFactory(306)] : Locating method activate in class org.openhab.binding.zigbee.xbee.internal.XBeeHandlerFactory
01:58:10.588 [DEBUG] [gbee.xbee.internal.XBeeHandlerFactory] - bundle org.openhab.binding.zigbee.xbee:3.2.0 (256)[org.openhab.binding.zigbee.xbee.internal.XBeeHandlerFactory(306)] : Declared Method org.openhab.binding.zigbee.xbee.internal.XBeeHandlerFactory.activate([interface org.osgi.service.component.ComponentContext]) not found
01:58:10.588 [DEBUG] [gbee.xbee.internal.XBeeHandlerFactory] - bundle org.openhab.binding.zigbee.xbee:3.2.0 (256)[org.openhab.binding.zigbee.xbee.internal.XBeeHandlerFactory(306)] : Locating method activate in class org.openhab.core.thing.binding.BaseThingHandlerFactory
01:58:10.588 [DEBUG] [gbee.xbee.internal.XBeeHandlerFactory] - bundle org.openhab.binding.zigbee.xbee:3.2.0 (256)[org.openhab.binding.zigbee.xbee.internal.XBeeHandlerFactory(306)] : Found activate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.activate(org.osgi.service.component.ComponentContext)
01:58:10.588 [DEBUG] [gbee.xbee.internal.XBeeHandlerFactory] - bundle org.openhab.binding.zigbee.xbee:3.2.0 (256)[org.openhab.binding.zigbee.xbee.internal.XBeeHandlerFactory(306)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl]
01:58:10.588 [DEBUG] [gbee.xbee.internal.XBeeHandlerFactory] - bundle org.openhab.binding.zigbee.xbee:3.2.0 (256)[org.openhab.binding.zigbee.xbee.internal.XBeeHandlerFactory(306)] : invoked activate: activate
01:58:10.588 [DEBUG] [gbee.xbee.internal.XBeeHandlerFactory] - bundle org.openhab.binding.zigbee.xbee:3.2.0 (256)[org.openhab.binding.zigbee.xbee.internal.XBeeHandlerFactory(306)] : Set implementation object for component
01:58:10.588 [DEBUG] [gbee.xbee.internal.XBeeHandlerFactory] - bundle org.openhab.binding.zigbee.xbee:3.2.0 (256)[org.openhab.binding.zigbee.xbee.internal.XBeeHandlerFactory(306)] : Changed state from satisfied to active
01:58:10.588 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (248)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(290)] : dm ZigBeeCoordinatorHandler tracking 3 MultipleDynamic added {org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler}={service.id=485, service.bundleid=256, service.scope=singleton} (enter)
01:58:10.588 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (248)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(290)] : dm ZigBeeCoordinatorHandler tracking 3 MultipleDynamic already active, binding {org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler}={service.id=485, service.bundleid=256, service.scope=singleton}
01:58:10.588 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (248)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(290)] : getting bind: addZigBeeCoordinatorHandler
01:58:10.588 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (248)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(290)] : Locating method addZigBeeCoordinatorHandler in class org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService
01:58:10.588 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (248)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(290)] : doFindMethod: Looking for method org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService.addZigBeeCoordinatorHandler
01:58:10.588 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (248)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(290)] : Declared Method org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService.addZigBeeCoordinatorHandler([interface org.osgi.framework.ServiceReference]) not found
01:58:10.588 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (248)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(290)] : Declared Method org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService.addZigBeeCoordinatorHandler([interface org.osgi.service.component.ComponentServiceObjects]) not found
01:58:10.588 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (248)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(290)] : getReferenceClass: Looking for interface class org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler through loader of org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService
01:58:10.588 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (248)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(290)] : getParameterClass: Found class org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler
01:58:10.588 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (248)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(290)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler
01:58:10.588 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (248)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(290)] : doFindMethod: Found Method protected void org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService.addZigBeeCoordinatorHandler(org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler)
01:58:10.588 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (248)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(290)] : Found bind method: protected void org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService.addZigBeeCoordinatorHandler(org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler)
01:58:10.588 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (248)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(290)] : invoking bind: addZigBeeCoordinatorHandler: parameters [org.openhab.binding.zigbee.xbee.handler.XBeeHandler]
01:58:10.588 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (248)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(290)] : invoked bind: addZigBeeCoordinatorHandler
01:58:10.588 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - bundle org.openhab.binding.zigbee:3.2.0 (248)[org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService(290)] : dm ZigBeeCoordinatorHandler tracking 3 MultipleDynamic added {org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler}={service.id=485, service.bundleid=256, service.scope=singleton} (exit)
01:58:10.605 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Initializing ZigBee network [zigbee:coordinator_xbee:bfd2fb6547].
01:58:10.605 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Channel 11.0
01:58:10.605 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - PANID 25994
01:58:10.605 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - EPANID 5FFAA68B264B646E
01:58:10.605 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Network Key 9E9C9FB6D6BAB2E68632F1C5EAA20565
01:58:10.605 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Link Key 5A6967426565416C6C69616E63653039
01:58:10.605 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Config: zigbee_initialise found, initializeNetwork=false
01:58:10.605 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Network Key String 9E9C9FB6D6BAB2E68632F1C5EAA20565
01:58:10.605 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Network key final array 9E9C9FB6D6BAB2E68632F1C5EAA20565
01:58:10.605 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Link Key String 5A6967426565416C6C69616E63653039
01:58:10.605 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Link key final array 5A6967426565416C6C69616E63653039
01:58:10.605 [DEBUG] [nding.zigbee.xbee.handler.XBeeHandler] - Initializing ZigBee XBee serial bridge handler.
01:58:10.605 [DEBUG] [nding.zigbee.xbee.handler.XBeeHandler] - ZigBee XBee Coordinator opening Port:'COM4' PAN:658a, EPAN:5FFAA68B264B646E, Channel:11
01:58:10.605 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start
01:58:10.617 [DEBUG] [gbee.xbee.internal.XBeeHandlerFactory] - bundle org.openhab.binding.zigbee.xbee:3.2.0 (256)[org.openhab.binding.zigbee.xbee.internal.XBeeHandlerFactory(306)] : dm $000 tracking 2 SingleStatic added {org.openhab.core.io.transport.serial.SerialPortManager}={service.id=480, service.bundleid=261, service.scope=bundle, component.name=org.openhab.core.io.transport.serial.internal.SerialPortManagerImpl, component.id=312} (exit)
01:58:11.624 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
01:58:11.624 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
01:58:11.624 [DEBUG] [inding.zigbee.serial.ZigBeeSerialPort] - Connecting to serial port [COM4] at 9600 baud, flow control FLOWCONTROL_OUT_NONE.
01:58:11.624 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=INITIALISING
01:58:12.019 [DEBUG] [inding.zigbee.serial.ZigBeeSerialPort] - Serial port [COM4] is initialized.
01:58:12.156 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: have 8 bytes available
01:58:12.156 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: try read  8 at offset 0
01:58:12.156 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: did read 8 of 8 at offset 0
01:58:15.797 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.
01:58:22.686 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: have 8 bytes available
01:58:22.686 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: try read  8 at offset 0
01:58:22.686 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: did read 8 of 8 at offset 0
01:58:33.180 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: have 5 bytes available
01:58:48.688 [WARN ] [hab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.io.monitor.internal.EventLogger@7105d05a' takes more than 5000ms.
01:58:43.674 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:coordinator_xbee:bfd2fb6547' changed from UNKNOWN to OFFLINE: Failed to initialize ZigBee transport layer
01:58:43.674 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=OFFLINE
01:59:09.625 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: try read  5 at offset 0
01:59:09.631 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: did read 5 of 5 at offset 0
01:59:09.631 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:coordinator_xbee:bfd2fb6547' changed from OFFLINE: Failed to initialize ZigBee transport layer to OFFLINE (COMMUNICATION_ERROR)
01:59:09.648 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: have 3 bytes available
01:59:09.648 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: try read  3 at offset 0
01:59:09.648 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: did read 3 of 3 at offset 0
01:59:10.636 [INFO ] [gbee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
01:59:10.636 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=SHUTDOWN
01:59:10.868 [DEBUG] [inding.zigbee.serial.ZigBeeSerialPort] - Serial port 'COM4' closed.
01:59:10.878 [DEBUG] [nding.zigbee.xbee.handler.XBeeHandler] - Initializing ZigBee XBee serial bridge handler.
01:59:10.878 [DEBUG] [nding.zigbee.xbee.handler.XBeeHandler] - ZigBee XBee Coordinator opening Port:'COM4' PAN:658a, EPAN:5FFAA68B264B646E, Channel:11
01:59:10.878 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start
01:59:10.881 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:coordinator_xbee:bfd2fb6547' changed from OFFLINE (COMMUNICATION_ERROR) to UNKNOWN
01:59:11.888 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
01:59:11.888 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
01:59:11.888 [DEBUG] [inding.zigbee.serial.ZigBeeSerialPort] - Connecting to serial port [COM4] at 9600 baud, flow control FLOWCONTROL_OUT_NONE.
01:59:11.888 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=INITIALISING
01:59:12.044 [DEBUG] [inding.zigbee.serial.ZigBeeSerialPort] - Serial port [COM4] is initialized.
01:59:12.188 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: have 8 bytes available
01:59:12.188 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: try read  8 at offset 0
01:59:12.188 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: did read 8 of 8 at offset 0
01:59:22.705 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: have 8 bytes available
01:59:22.710 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: try read  8 at offset 0
01:59:22.711 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: did read 8 of 8 at offset 0
01:59:33.206 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: have 3 bytes available
01:59:33.206 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: try read  3 at offset 0
01:59:33.206 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: did read 3 of 3 at offset 0
01:59:33.222 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: have 5 bytes available
01:59:33.222 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: try read  5 at offset 0
01:59:33.222 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: did read 5 of 5 at offset 0
01:59:43.721 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=OFFLINE```

Mehdi_Marzougui · March 9, 2022, 1:19am

Hey chris,

I think I understood your instructions now, here is the openhab.log file located in \userdata\logs for the same session in the previous reply

openhab.log (292.6 KB)

Thanks!

chris · March 9, 2022, 1:43am

I need to see more logging - there are other namespaces that need to be enabled to get the zigbee data - all of the zsmartsystems data is currently missing. The binding documentation shows how to enable debug logging - there’s a section called something like “what to do when things don’t go to plan” - take a look at this and enable the additional debug, then provide the log again.

Thanks.

Mehdi_Marzougui · March 9, 2022, 1:59am

Hey chris,

Got you, here it is:


                           _   _     _     ____
   ___   ___   ___   ___  | | | |   / \   | __ )
  / _ \ / _ \ / _ \ / _ \ | |_| |  / _ \  |  _ \
 | (_) | (_) |  __/| | | ||  _  | / ___ \ | |_) )
  \___/|  __/ \___/|_| |_||_| |_|/_/   \_\|____/
       |_|       3.2.0 - Release Build

Use '<tab>' for a list of available commands
and '[cmd] --help' for help on a specific command.
To exit, use '<ctrl-d>' or 'logout'.

openhab> log:set trace org.openhab.binding.zigbee
openhab> log:set trace com.zsmartsystems.zigbee
openhab> log:set trace com.zsmartsystem.zigbee.dongle.ember.internal.ash
openhab> log:tail
02:53:30.108 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 46 F
02:53:30.108 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 52 R
02:53:30.108 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 5E ^
02:53:30.108 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE Data: 00 04 08 01 46 52 5E
02:53:30.108 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - XBEE: Get Packet
02:53:30.578 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBee interrupted in sendRequest XBeeSetSoftwareResetCommand [frameId=1]
02:53:40.064 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBEE Timer: Timeout
02:53:40.582 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBee interrupted in eventWait class com.zsmartsystems.zigbee.dongle.xbee.internal.protocol.XBeeModemStatusEvent
02:53:40.582 [DEBUG] [s.zigbee.dongle.xbee.ZigBeeDongleXBee] - XBee dongle reset 2.
02:53:40.582 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBee interrupted in waitEventAsync class com.zsmartsystems.zigbee.dongle.xbee.internal.protocol.XBeeModemStatusEvent
02:53:40.582 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - TX XBEE queue: 1: XBeeSetSoftwareResetCommand [frameId=2]
02:53:40.582 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - TX XBEE: XBeeSetSoftwareResetCommand [frameId=2]
02:53:40.582 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - TX XBEE Data: 00 04 08 02 46 52 5D
02:53:40.582 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - XBEE Timer: Start
02:53:40.619 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: have 8 bytes available
02:53:40.619 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: try read  8 at offset 0
02:53:40.619 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: did read 8 of 8 at offset 0
02:53:40.619 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 7E ~
02:53:40.619 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 00
02:53:40.619 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 04 ♦
02:53:40.619 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 08
02:53:40.619 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 02 ☻
02:53:40.619 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 46 F
02:53:40.619 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 52 R
02:53:40.619 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 5D ]
02:53:40.619 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE Data: 00 04 08 02 46 52 5D
02:53:40.619 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - XBEE: Get Packet
02:53:41.086 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBee interrupted in sendRequest XBeeSetSoftwareResetCommand [frameId=2]
02:53:50.595 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBEE Timer: Timeout
02:53:51.095 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBee interrupted in eventWait class com.zsmartsystems.zigbee.dongle.xbee.internal.protocol.XBeeModemStatusEvent
02:53:51.095 [DEBUG] [s.zigbee.dongle.xbee.ZigBeeDongleXBee] - XBee dongle reset 3.
02:53:51.095 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBee interrupted in waitEventAsync class com.zsmartsystems.zigbee.dongle.xbee.internal.protocol.XBeeModemStatusEvent
02:53:51.095 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - TX XBEE queue: 1: XBeeSetSoftwareResetCommand [frameId=3]
02:53:51.095 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - TX XBEE: XBeeSetSoftwareResetCommand [frameId=3]
02:53:51.095 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - TX XBEE Data: 00 04 08 03 46 52 5C
02:53:51.095 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - XBEE Timer: Start
02:53:51.126 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: have 8 bytes available
02:53:51.126 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: try read  8 at offset 0
02:53:51.126 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: did read 8 of 8 at offset 0
02:53:51.126 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 7E ~
02:53:51.126 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 00
02:53:51.126 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 04 ♦
02:53:51.126 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 08
02:53:51.126 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 03 ♥
02:53:51.126 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 46 F
02:53:51.126 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 52 R
02:53:51.126 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 5C \
02:53:51.126 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE Data: 00 04 08 03 46 52 5C
02:53:51.126 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - XBEE: Get Packet
02:53:51.601 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBee interrupted in sendRequest XBeeSetSoftwareResetCommand [frameId=3]
02:54:01.106 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBEE Timer: Timeout
02:54:01.622 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBee interrupted in eventWait class com.zsmartsystems.zigbee.dongle.xbee.internal.protocol.XBeeModemStatusEvent
02:54:01.622 [INFO ] [s.zigbee.dongle.xbee.ZigBeeDongleXBee] - XBee dongle reset failed after 4 tries.
02:54:01.622 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBee interrupted in waitEventAsync class com.zsmartsystems.zigbee.dongle.xbee.internal.protocol.XBeeModemStatusEvent
02:54:01.622 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to OFFLINE
02:54:01.622 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=OFFLINE
02:54:01.622 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:coordinator_xbee:bfd2fb6547' changed from UNKNOWN to OFFLINE: Failed to initialize ZigBee transport layer
02:54:01.622 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:coordinator_xbee:bfd2fb6547' changed from OFFLINE: Failed to initialize ZigBee transport layer to OFFLINE (COMMUNICATION_ERROR)
02:54:06.633 [INFO ] [gbee.handler.ZigBeeCoordinatorHandler] - ZigBee dongle inactivity timer. Reinitializing ZigBee
02:54:06.651 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager shutdown: networkState=OFFLINE
02:54:06.653 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - Data store: Deferred Write Time set to 0ms
02:54:06.653 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - Data store: Deferred Write Time set less than Max Deferred Write Time
02:54:06.653 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - Data store: Max Deferred Write Time set to 0ms
02:54:06.653 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to SHUTDOWN
02:54:06.653 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=SHUTDOWN
02:54:06.653 [DEBUG] [database.ZigBeeNetworkDatabaseManager] - Data store: Shutdown
02:54:06.849 [DEBUG] [inding.zigbee.serial.ZigBeeSerialPort] - Serial port 'COM4' closed.
02:54:06.849 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBeeFrameHandler thread exited.
02:54:06.849 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBeeFrameHandler closed.
02:54:06.849 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBee interrupted in waitEventAsync class com.zsmartsystems.zigbee.dongle.xbee.internal.protocol.XBeeModemStatusEvent
02:54:06.849 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBee interrupted in waitEventAsync class com.zsmartsystems.zigbee.dongle.xbee.internal.protocol.XBeeModemStatusEvent
02:54:06.849 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBee interrupted in waitEventAsync class com.zsmartsystems.zigbee.dongle.xbee.internal.protocol.XBeeModemStatusEvent
02:54:06.861 [DEBUG] [s.zigbee.dongle.xbee.ZigBeeDongleXBee] - XBee dongle shutdown.
02:54:06.861 [DEBUG] [.transaction.ZigBeeTransactionManager] - Transaction Manager: Shutdown
02:54:06.861 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: Queue shutdown
02:54:06.861 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Multicast: Queue shutdown
02:54:06.861 [DEBUG] [nding.zigbee.xbee.handler.XBeeHandler] - Initializing ZigBee XBee serial bridge handler.
02:54:06.861 [DEBUG] [nding.zigbee.xbee.handler.XBeeHandler] - ZigBee XBee Coordinator opening Port:'COM4' PAN:658a, EPAN:5FFAA68B264B646E, Channel:11
02:54:06.861 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Scheduling ZigBee start
02:54:06.861 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:coordinator_xbee:bfd2fb6547' changed from OFFLINE (COMMUNICATION_ERROR) to UNKNOWN
02:54:07.866 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - ZigBee network starting
02:54:07.866 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - Initialising ZigBee coordinator
02:54:07.866 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Default: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=1, interTransactionDelay=50, maxRetries=2]
02:54:07.866 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Broadcast: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=2, interTransactionDelay=4000, maxRetries=0]
02:54:07.866 [DEBUG] [ee.transaction.ZigBeeTransactionQueue] - Multicast: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=3, interTransactionDelay=1200, maxRetries=0]
02:54:07.866 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - ZigBeeNetworkManager initialize: networkState=UNINITIALISED
02:54:07.866 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - Network state is updated to INITIALISING
02:54:07.866 [DEBUG] [s.zigbee.dongle.xbee.ZigBeeDongleXBee] - XBee dongle initialize.
02:54:07.866 [DEBUG] [gbee.handler.ZigBeeCoordinatorHandler] - null: networkStateUpdated called with state=INITIALISING
02:54:07.866 [DEBUG] [inding.zigbee.serial.ZigBeeSerialPort] - Connecting to serial port [COM4] at 9600 baud, flow control FLOWCONTROL_OUT_NONE.
02:54:08.057 [DEBUG] [inding.zigbee.serial.ZigBeeSerialPort] - Serial port [COM4] is initialized.
02:54:08.057 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBeeFrameHandler clearing receive buffer.
02:54:08.167 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBeeFrameHandler cleared receive buffer.
02:54:08.167 [DEBUG] [s.zigbee.dongle.xbee.ZigBeeDongleXBee] - XBee dongle reset 1.
02:54:08.167 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBeeFrameHandler thread started
02:54:08.167 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - TX XBEE: XBeeSetSoftwareResetCommand [frameId=1]
02:54:08.167 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - TX XBEE queue: 0: XBeeSetSoftwareResetCommand [frameId=1]
02:54:08.167 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - TX XBEE Data: 00 04 08 01 46 52 5E
02:54:08.167 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - XBEE Timer: Start
02:54:08.167 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - XBEE: Get Packet
02:54:08.167 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - TX XBEE Frame outstanding: XBeeSetSoftwareResetCommand [frameId=1]
02:54:08.198 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: have 5 bytes available
02:54:08.204 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: try read  5 at offset 0
02:54:08.204 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: did read 5 of 5 at offset 0
02:54:08.204 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 7E ~
02:54:08.204 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 00
02:54:08.204 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 04 ♦
02:54:08.204 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 08
02:54:08.204 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 01 ☺
02:54:08.220 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: have 3 bytes available
02:54:08.220 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: try read  3 at offset 0
02:54:08.220 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: did read 3 of 3 at offset 0
02:54:08.220 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 46 F
02:54:08.220 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 52 R
02:54:08.220 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 5E ^
02:54:08.220 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE Data: 00 04 08 01 46 52 5E
02:54:08.220 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - XBEE: Get Packet
02:54:08.684 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBee interrupted in sendRequest XBeeSetSoftwareResetCommand [frameId=1]
02:54:18.186 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBEE Timer: Timeout
02:54:18.690 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBee interrupted in eventWait class com.zsmartsystems.zigbee.dongle.xbee.internal.protocol.XBeeModemStatusEvent
02:54:18.690 [DEBUG] [s.zigbee.dongle.xbee.ZigBeeDongleXBee] - XBee dongle reset 2.
02:54:18.690 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBee interrupted in waitEventAsync class com.zsmartsystems.zigbee.dongle.xbee.internal.protocol.XBeeModemStatusEvent
02:54:18.693 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - TX XBEE queue: 1: XBeeSetSoftwareResetCommand [frameId=2]
02:54:18.695 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - TX XBEE: XBeeSetSoftwareResetCommand [frameId=2]
02:54:18.695 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - TX XBEE Data: 00 04 08 02 46 52 5D
02:54:18.695 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - XBEE Timer: Start
02:54:18.741 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: have 8 bytes available
02:54:18.741 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: try read  8 at offset 0
02:54:18.741 [TRACE] [inding.zigbee.serial.ZigBeeSerialPort] - Processing DATA_AVAILABLE event: did read 8 of 8 at offset 0
02:54:18.741 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 7E ~
02:54:18.741 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 00
02:54:18.741 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 04 ♦
02:54:18.741 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 08
02:54:18.741 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 02 ☻
02:54:18.741 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 46 F
02:54:18.757 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 52 R
02:54:18.757 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE: 5D ]
02:54:18.757 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - RX XBEE Data: 00 04 08 02 46 52 5D
02:54:18.757 [TRACE] [dongle.xbee.internal.XBeeFrameHandler] - XBEE: Get Packet
02:54:19.205 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBee interrupted in sendRequest XBeeSetSoftwareResetCommand [frameId=2]
02:54:28.700 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBEE Timer: Timeout
02:54:29.219 [DEBUG] [dongle.xbee.internal.XBeeFrameHandler] - XBee interrupted in eventWait class com.zsmartsystems.zigbee.dongle.xbee.internal.protocol.XBeeModemStatusEvent```

chris · March 9, 2022, 4:18am

It doesn’t look like the device is responding. The data that is being received appears to be the data that the binding has sent - not the response from the XBee. So either the XBee isn’t connected, and there’s something else performing a loopback, or possibly the XBee isn’t in API mode? I’m not familiar enough with the device to be sure what the root cause is, but the binding doesn’t get the OK response from the device that it’s expecting.

Mehdi_Marzougui · March 9, 2022, 9:11am

Yes! that was it, I switched modules several times and I forgot to switch this one to API mode(using XCTU software). Thanks chris, you saved me a lot of time and confusion.

cheers!