INFO 2017-04-22 15:55:05,374 (Z-Wave): -------------------------------------------------------------------- OpenRemote Z-Wave protocol version : '3.2.2-Beta1' -------------------------------------------------------------------- DEBUG 2017-04-22 15:55:06,335 (Z-Wave): Connection_Manager : Adding shutdown hook to manage unclosed Z-Wave connections in case of controller exit. INFO 2017-04-22 15:55:06,584 (Z-Wave): Serial_Port : Opening the serial port [COM port: /dev/ttyACM0, Communication Layer: RXTX]... INFO 2017-04-22 15:55:06,836 (Z-Wave): Serial_Port : The serial port [COM port: /dev/ttyACM0, Communication Layer: RXTX] has been successfully opened. DEBUG 2017-04-22 15:55:06,958 (Z-Wave): Controller : Retrieving Z-Wave controller firmware version and library type... DEBUG 2017-04-22 15:55:06,999 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=1) Z-Wave function call 'ZW_Version'. DEBUG 2017-04-22 15:55:06,999 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=0) Z-Wave function call 'ZW_Version'. DEBUG 2017-04-22 15:55:07,002 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_Version'... DEBUG 2017-04-22 15:55:07,049 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x03, 0x00, 0x15, 0xE9]. DEBUG 2017-04-22 15:55:07,064 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:07,070 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x03, 0x00, 0x15, 0xE9] transmission OK. DEBUG 2017-04-22 15:55:07,078 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01, 0x10, 0x01, 0x15, 0x5A, 0x2D, 0x57, 0x61, 0x76, 0x65, 0x20, 0x33, 0x2E, 0x39, 0x35, 0x00, 0x01, 0x99] DEBUG 2017-04-22 15:55:07,079 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_Version' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:07,108 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x10, 0x01, 0x15, 0x5A, 0x2D, 0x57, 0x61, 0x76, 0x65, 0x20, 0x33, 0x2E, 0x39, 0x35, 0x00, 0x01, 0x99] has been received. DEBUG 2017-04-22 15:55:07,118 (Z-Wave): RX_Session_Layer : Response received [0x01, 0x10, 0x01, 0x15, 0x5A, 0x2D, 0x57, 0x61, 0x76, 0x65, 0x20, 0x33, 0x2E, 0x39, 0x35, 0x00, 0x01, 0x99] -> Z-Wave function 'ZW_Version' successfully executed. INFO 2017-04-22 15:55:07,132 (Z-Wave): Z-Wave firmware version : Z-Wave 3.95 INFO 2017-04-22 15:55:07,134 (Z-Wave): Z-Wave library type : ZW_LIB_CONTROLLER_STATIC DEBUG 2017-04-22 15:55:07,135 (Z-Wave): Controller : Retrieving serial API capabilities... DEBUG 2017-04-22 15:55:07,144 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=0) Z-Wave function call 'SERIAL_API_GetCapabilities'. DEBUG 2017-04-22 15:55:07,144 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'SERIAL_API_GetCapabilities'... DEBUG 2017-04-22 15:55:07,147 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x03, 0x00, 0x07, 0xFB]. DEBUG 2017-04-22 15:55:07,150 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=0) Z-Wave function call 'SERIAL_API_GetCapabilities'. DEBUG 2017-04-22 15:55:07,152 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:07,156 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x03, 0x00, 0x07, 0xFB] transmission OK. DEBUG 2017-04-22 15:55:07,157 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'SERIAL_API_GetCapabilities' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:07,165 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01, 0x2B, 0x01, 0x07, 0x01, 0x00, 0x00, 0x86, 0x01, 0x01, 0x00, 0x5A, 0xFE, 0x81, 0xFF, 0x88, 0x4F, 0x1F, 0x00, 0x00, 0xFB, 0x9F, 0x7D, 0xA0, 0x67, 0x00, 0x00, 0x80, 0x00, 0x80, 0x86, 0x00, 0x00, 0x00, 0xE8, 0x73, 0x00, 0x00, 0x0E, 0x00, 0x00] DEBUG 2017-04-22 15:55:07,168 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x60, 0x00, 0x00, 0xFA] DEBUG 2017-04-22 15:55:07,184 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x2B, 0x01, 0x07, 0x01, 0x00, 0x00, 0x86, 0x01, 0x01, 0x00, 0x5A, 0xFE, 0x81, 0xFF, 0x88, 0x4F, 0x1F, 0x00, 0x00, 0xFB, 0x9F, 0x7D, 0xA0, 0x67, 0x00, 0x00, 0x80, 0x00, 0x80, 0x86, 0x00, 0x00, 0x00, 0xE8, 0x73, 0x00, 0x00, 0x0E, 0x00, 0x00, 0x60, 0x00, 0x00, 0xFA] has been received. DEBUG 2017-04-22 15:55:07,205 (Z-Wave): RX_Session_Layer : Response received [0x01, 0x2B, 0x01, 0x07, 0x01, 0x00, 0x00, 0x86, 0x01, 0x01, 0x00, 0x5A, 0xFE, 0x81, 0xFF, 0x88, 0x4F, 0x1F, 0x00, 0x00, 0xFB, 0x9F, 0x7D, 0xA0, 0x67, 0x00, 0x00, 0x80, 0x00, 0x80, 0x86, 0x00, 0x00, 0x00, 0xE8, 0x73, 0x00, 0x00, 0x0E, 0x00, 0x00, 0x60, 0x00, 0x00, 0xFA] -> Z-Wave function 'SERIAL_API_GetCapabilities' successfully executed. INFO 2017-04-22 15:55:07,227 (Z-Wave): Serial API Z-Wave firmware : [Version=1.0, Manufacturer='AEON Labs', Product Type=0x0101, Product ID=0x005A] INFO 2017-04-22 15:55:07,247 (Z-Wave): Serial API Z-Wave functions : [0x02 ,0x03 ,0x04 ,0x05 ,0x06 ,0x07 ,0x08 ,0x09 ,0x10 ,0x11 ,0x12 ,0x13 ,0x14 ,0x15 ,0x16 ,0x17 ,0x18 ,0x1C ,0x20 ,0x21 ,0x22 ,0x23 ,0x24 ,0x27 ,0x29 ,0x2A ,0x2B ,0x2C ,0x2D ,0x41 ,0x42 ,0x44 ,0x45 ,0x46 ,0x47 ,0x48 ,0x49 ,0x4A ,0x4B ,0x4C ,0x4D ,0x50 ,0x51 ,0x53 ,0x54 ,0x55 ,0x56 ,0x57 ,0x5E ,0x60 ,0x61 ,0x62 ,0x63 ,0x66 ,0x67 ,0x80 ,0x90 ,0x92 ,0x93 ,0x98 ,0xB4 ,0xB6 ,0xB7 ,0xB8 ,0xB9 ,0xBA ,0xBD ,0xBE ,0xBF ,0xD2 ,0xD3 ,0xD4 ,0xEE ,0xEF ,] DEBUG 2017-04-22 15:55:07,249 (Z-Wave): Controller : Retrieving Z-Wave node list... DEBUG 2017-04-22 15:55:07,259 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=0) Z-Wave function call 'SERIAL_API_GetInitData'. DEBUG 2017-04-22 15:55:07,259 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=1) Z-Wave function call 'SERIAL_API_GetInitData'. DEBUG 2017-04-22 15:55:07,261 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'SERIAL_API_GetInitData'... DEBUG 2017-04-22 15:55:07,263 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x03, 0x00, 0x02, 0xFE]. DEBUG 2017-04-22 15:55:07,267 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:07,270 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x03, 0x00, 0x02, 0xFE] transmission OK. DEBUG 2017-04-22 15:55:07,271 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'SERIAL_API_GetInitData' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:07,360 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:07,368 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x25, 0x01, 0x02, 0x05, 0x08, 0x1D, 0xE9, 0x0D, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00] DEBUG 2017-04-22 15:55:07,371 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x00, 0x00, 0x00, 0x00, 0x05, 0x00, 0x28] DEBUG 2017-04-22 15:55:07,390 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x25, 0x01, 0x02, 0x05, 0x08, 0x1D, 0xE9, 0x0D, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x05, 0x00, 0x28] has been received. DEBUG 2017-04-22 15:55:07,400 (Z-Wave): RX_Session_Layer : Response received [0x01, 0x25, 0x01, 0x02, 0x05, 0x08, 0x1D, 0xE9, 0x0D, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x05, 0x00, 0x28] -> Z-Wave function 'SERIAL_API_GetInitData' successfully executed. DEBUG 2017-04-22 15:55:07,425 (Z-Wave): Controller : The Z-Wave node list has been successfully retrieved : [1, 4, 6, 7, 8, 9, 11, 12]. DEBUG 2017-04-22 15:55:07,452 (Z-Wave): Controller : Retrieving Z-Wave node info (ID=1)... DEBUG 2017-04-22 15:55:07,461 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=1) Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=1)'. DEBUG 2017-04-22 15:55:07,461 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=0) Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=1)'. DEBUG 2017-04-22 15:55:07,462 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=1)'... DEBUG 2017-04-22 15:55:07,465 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x04, 0x00, 0x41, 0x01, 0xBB]. DEBUG 2017-04-22 15:55:07,468 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:07,470 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x04, 0x00, 0x41, 0x01, 0xBB] transmission OK. DEBUG 2017-04-22 15:55:07,471 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01, 0x09, 0x01, 0x41, 0x93, 0x16, 0x01, 0x02, 0x02, 0x01, 0x33] DEBUG 2017-04-22 15:55:07,471 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_GetNodeProtocolInfo(NodeID=1)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:07,475 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x09, 0x01, 0x41, 0x93, 0x16, 0x01, 0x02, 0x02, 0x01, 0x33] has been received. DEBUG 2017-04-22 15:55:07,478 (Z-Wave): RX_Session_Layer : Response received [0x01, 0x09, 0x01, 0x41, 0x93, 0x16, 0x01, 0x02, 0x02, 0x01, 0x33] -> Z-Wave function 'ZW_GetNodeProtocolInfo(NodeID=1)' successfully executed. INFO 2017-04-22 15:55:07,512 (Z-Wave): Controller : Z-Wave node info (ID=1) : [[Device Classes : 'BASIC_TYPE_STATIC_CONTROLLER','GENERIC_TYPE_STATIC_CONTROLLER','SPECIFIC_TYPE_PC_CONTROLLER'],[Capabilities : 'NODEINFO_CAPABILITY_LISTENING'],[Security : '--']]. DEBUG 2017-04-22 15:55:07,514 (Z-Wave): Controller : Retrieving Z-Wave node info (ID=4)... DEBUG 2017-04-22 15:55:07,515 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=0) Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=4)'. DEBUG 2017-04-22 15:55:07,515 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=1) Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=4)'. DEBUG 2017-04-22 15:55:07,515 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=4)'... DEBUG 2017-04-22 15:55:07,517 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x04, 0x00, 0x41, 0x04, 0xBE]. DEBUG 2017-04-22 15:55:07,520 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:07,521 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:07,524 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x09, 0x01, 0x41, 0x53, 0x9C, 0x00, 0x04, 0x20, 0x01, 0x5C] DEBUG 2017-04-22 15:55:07,524 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x04, 0x00, 0x41, 0x04, 0xBE] transmission OK. DEBUG 2017-04-22 15:55:07,527 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_GetNodeProtocolInfo(NodeID=4)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:07,531 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x09, 0x01, 0x41, 0x53, 0x9C, 0x00, 0x04, 0x20, 0x01, 0x5C] has been received. DEBUG 2017-04-22 15:55:07,534 (Z-Wave): RX_Session_Layer : Response received [0x01, 0x09, 0x01, 0x41, 0x53, 0x9C, 0x00, 0x04, 0x20, 0x01, 0x5C] -> Z-Wave function 'ZW_GetNodeProtocolInfo(NodeID=4)' successfully executed. DEBUG 2017-04-22 15:55:07,692 (Z-Wave): Node_Initializer : Node '4' : [ZW_RequestNodeInfo, (Retry='1')] DEBUG 2017-04-22 15:55:07,721 (Z-Wave): Controller_API_WakeUp_Queue : Node '4' : Enqueue (Count='1') : 'ZW_RequestNodeInfo(NodeID=4)'. INFO 2017-04-22 15:55:07,722 (Z-Wave): Controller : Z-Wave node info (ID=4) : [[Device Classes : 'BASIC_TYPE_ROUTING_SLAVE','GENERIC_TYPE_SENSOR_BINARY','SPECIFIC_TYPE_ROUTING_SENSOR_BINARY'],[Capabilities : 'NODEINFO_CAPABILITY_ROUTING'],[Security : 'NODEINFO_SECURITY_OPTIONAL_FUNC_SUPPORT']]. DEBUG 2017-04-22 15:55:07,723 (Z-Wave): Controller : Retrieving Z-Wave node info (ID=6)... DEBUG 2017-04-22 15:55:07,724 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=1) Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=6)'. DEBUG 2017-04-22 15:55:07,724 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=0) Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=6)'. DEBUG 2017-04-22 15:55:07,725 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=6)'... DEBUG 2017-04-22 15:55:07,727 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x04, 0x00, 0x41, 0x06, 0xBC]. DEBUG 2017-04-22 15:55:07,730 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:07,732 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:07,732 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x04, 0x00, 0x41, 0x06, 0xBC] transmission OK. DEBUG 2017-04-22 15:55:07,733 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_GetNodeProtocolInfo(NodeID=6)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:07,734 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x09, 0x01, 0x41, 0xD3, 0x9C, 0x00, 0x04, 0x10, 0x01, 0xEC] DEBUG 2017-04-22 15:55:07,737 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x09, 0x01, 0x41, 0xD3, 0x9C, 0x00, 0x04, 0x10, 0x01, 0xEC] has been received. DEBUG 2017-04-22 15:55:07,741 (Z-Wave): RX_Session_Layer : Response received [0x01, 0x09, 0x01, 0x41, 0xD3, 0x9C, 0x00, 0x04, 0x10, 0x01, 0xEC] -> Z-Wave function 'ZW_GetNodeProtocolInfo(NodeID=6)' successfully executed. INFO 2017-04-22 15:55:07,910 (Z-Wave): Controller : Z-Wave node info (ID=6) : [[Device Classes : 'BASIC_TYPE_ROUTING_SLAVE','GENERIC_TYPE_SWITCH_BINARY','SPECIFIC_TYPE_POWER_SWITCH_BINARY'],[Capabilities : 'NODEINFO_CAPABILITY_ROUTING','NODEINFO_CAPABILITY_LISTENING'],[Security : 'NODEINFO_SECURITY_OPTIONAL_FUNC_SUPPORT']]. DEBUG 2017-04-22 15:55:07,911 (Z-Wave): Controller : Retrieving Z-Wave node info (ID=7)... DEBUG 2017-04-22 15:55:07,912 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=1) Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=7)'. DEBUG 2017-04-22 15:55:07,912 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=0) Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=7)'. DEBUG 2017-04-22 15:55:07,913 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=7)'... DEBUG 2017-04-22 15:55:07,916 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x04, 0x00, 0x41, 0x07, 0xBD]. DEBUG 2017-04-22 15:55:07,918 (Z-Wave): Node : Node '6' : Node has been successfully initialized with the following command classes... DEBUG 2017-04-22 15:55:07,919 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:07,922 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x04, 0x00, 0x41, 0x07, 0xBD] transmission OK. DEBUG 2017-04-22 15:55:07,923 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_GetNodeProtocolInfo(NodeID=7)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:07,923 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01, 0x09, 0x01, 0x41, 0xD3, 0x9C, 0x00, 0x04, 0x11, 0x01, 0xED] DEBUG 2017-04-22 15:55:07,928 (Z-Wave): Node : Node '6' : --> 'COMMAND_CLASS_BASIC', 'supported'. DEBUG 2017-04-22 15:55:07,929 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x09, 0x01, 0x41, 0xD3, 0x9C, 0x00, 0x04, 0x11, 0x01, 0xED] has been received. DEBUG 2017-04-22 15:55:07,930 (Z-Wave): Node : Node '6' : --> 'COMMAND_CLASS_CONFIGURATION', 'supported'. DEBUG 2017-04-22 15:55:07,930 (Z-Wave): Node : Node '6' : --> 'COMMAND_CLASS_MANUFACTURER_SPECIFIC', 'supported'. DEBUG 2017-04-22 15:55:07,931 (Z-Wave): Node : Node '6' : --> 'COMMAND_CLASS_SWITCH_BINARY', 'supported'. DEBUG 2017-04-22 15:55:07,932 (Z-Wave): RX_Session_Layer : Response received [0x01, 0x09, 0x01, 0x41, 0xD3, 0x9C, 0x00, 0x04, 0x11, 0x01, 0xED] -> Z-Wave function 'ZW_GetNodeProtocolInfo(NodeID=7)' successfully executed. DEBUG 2017-04-22 15:55:07,932 (Z-Wave): Node : Node '6' : --> 'COMMAND_CLASS_ASSOCIATION_V2', 'supported'. DEBUG 2017-04-22 15:55:07,938 (Z-Wave): Node : Node '6' : --> 'COMMAND_CLASS_VERSION', 'supported'. INFO 2017-04-22 15:55:08,257 (Z-Wave): Controller : Z-Wave node info (ID=7) : [[Device Classes : 'BASIC_TYPE_ROUTING_SLAVE','GENERIC_TYPE_SWITCH_MULTILEVEL','SPECIFIC_TYPE_POWER_SWITCH_MULTILEVEL'],[Capabilities : 'NODEINFO_CAPABILITY_ROUTING','NODEINFO_CAPABILITY_LISTENING'],[Security : 'NODEINFO_SECURITY_OPTIONAL_FUNC_SUPPORT']]. DEBUG 2017-04-22 15:55:08,260 (Z-Wave): Controller : Retrieving Z-Wave node info (ID=8)... DEBUG 2017-04-22 15:55:08,260 (Z-Wave): Node : Node '7' : Node has been successfully initialized with the following command classes... DEBUG 2017-04-22 15:55:08,261 (Z-Wave): Node : Node '7' : --> 'COMMAND_CLASS_BASIC', 'supported'. DEBUG 2017-04-22 15:55:08,261 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=0) Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=8)'. DEBUG 2017-04-22 15:55:08,261 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=1) Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=8)'. DEBUG 2017-04-22 15:55:08,262 (Z-Wave): Node : Node '7' : --> 'COMMAND_CLASS_MANUFACTURER_SPECIFIC', 'supported'. DEBUG 2017-04-22 15:55:08,262 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=8)'... DEBUG 2017-04-22 15:55:08,262 (Z-Wave): Node : Node '7' : --> 'COMMAND_CLASS_PROTECTION', 'supported'. DEBUG 2017-04-22 15:55:08,263 (Z-Wave): Node : Node '7' : --> 'COMMAND_CLASS_SWITCH_MULTILEVEL', 'supported'. DEBUG 2017-04-22 15:55:08,264 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x04, 0x00, 0x41, 0x08, 0xB2]. DEBUG 2017-04-22 15:55:08,264 (Z-Wave): Node : Node '7' : --> 'COMMAND_CLASS_VERSION', 'supported'. DEBUG 2017-04-22 15:55:08,267 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:08,270 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x04, 0x00, 0x41, 0x08, 0xB2] transmission OK. DEBUG 2017-04-22 15:55:08,271 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_GetNodeProtocolInfo(NodeID=8)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:08,271 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01, 0x09, 0x01, 0x41, 0x53, 0x9C, 0x01, 0x04, 0x07, 0x01, 0x7A] DEBUG 2017-04-22 15:55:08,276 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x09, 0x01, 0x41, 0x53, 0x9C, 0x01, 0x04, 0x07, 0x01, 0x7A] has been received. DEBUG 2017-04-22 15:55:08,282 (Z-Wave): RX_Session_Layer : Response received [0x01, 0x09, 0x01, 0x41, 0x53, 0x9C, 0x01, 0x04, 0x07, 0x01, 0x7A] -> Z-Wave function 'ZW_GetNodeProtocolInfo(NodeID=8)' successfully executed. DEBUG 2017-04-22 15:55:08,289 (Z-Wave): Node_Initializer : Node '8' : [ZW_RequestNodeInfo, (Retry='1')] DEBUG 2017-04-22 15:55:08,290 (Z-Wave): Controller_API_WakeUp_Queue : Node '8' : Enqueue (Count='1') : 'ZW_RequestNodeInfo(NodeID=8)'. INFO 2017-04-22 15:55:08,293 (Z-Wave): Controller : Z-Wave node info (ID=8) : [[Device Classes : 'BASIC_TYPE_ROUTING_SLAVE','GENERIC_TYPE_SENSOR_NOTIFICATION','SPECIFIC_TYPE_NOTIFICATION_SENSOR'],[Capabilities : 'NODEINFO_CAPABILITY_ROUTING'],[Security : 'NODEINFO_SECURITY_OPTIONAL_FUNC_SUPPORT']]. DEBUG 2017-04-22 15:55:08,295 (Z-Wave): Controller : Retrieving Z-Wave node info (ID=9)... DEBUG 2017-04-22 15:55:08,297 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=0) Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=9)'. DEBUG 2017-04-22 15:55:08,297 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=1) Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=9)'. DEBUG 2017-04-22 15:55:08,298 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=9)'... DEBUG 2017-04-22 15:55:08,300 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x04, 0x00, 0x41, 0x09, 0xB3]. DEBUG 2017-04-22 15:55:08,306 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:08,310 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01, 0x09, 0x01, 0x41, 0xD3, 0x9C, 0x00, 0x04, 0x10, 0x03, 0xEE] DEBUG 2017-04-22 15:55:08,313 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x04, 0x00, 0x41, 0x09, 0xB3] transmission OK. DEBUG 2017-04-22 15:55:08,315 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_GetNodeProtocolInfo(NodeID=9)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:08,320 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x09, 0x01, 0x41, 0xD3, 0x9C, 0x00, 0x04, 0x10, 0x03, 0xEE] has been received. DEBUG 2017-04-22 15:55:08,324 (Z-Wave): RX_Session_Layer : Response received [0x01, 0x09, 0x01, 0x41, 0xD3, 0x9C, 0x00, 0x04, 0x10, 0x03, 0xEE] -> Z-Wave function 'ZW_GetNodeProtocolInfo(NodeID=9)' successfully executed. DEBUG 2017-04-22 15:55:08,360 (Z-Wave): Node_Initializer : Node '6' : [ZW_RequestNodeInfo, (Retry='1')] DEBUG 2017-04-22 15:55:08,362 (Z-Wave): Node_Initializer : Node '7' : [ZW_RequestNodeInfo, (Retry='1')] DEBUG 2017-04-22 15:55:08,364 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=2) Z-Wave function call 'ZW_RequestNodeInfo(NodeID=6)'. DEBUG 2017-04-22 15:55:08,364 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=1) Z-Wave function call 'ZW_RequestNodeInfo(NodeID=7)'. DEBUG 2017-04-22 15:55:08,369 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=1) Z-Wave function call 'ZW_RequestNodeInfo(NodeID=6)'. DEBUG 2017-04-22 15:55:08,370 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_RequestNodeInfo(NodeID=6)'... DEBUG 2017-04-22 15:55:08,371 (Z-Wave): ZW_RequestNodeInfo : Sending Z-Wave function 'ZW_RequestNodeInfo(NodeID=6)' call. DEBUG 2017-04-22 15:55:08,373 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x04, 0x00, 0x60, 0x06, 0x9D]. DEBUG 2017-04-22 15:55:08,380 (Z-Wave): Node : Node '9' : Node has been successfully initialized with the following command classes... DEBUG 2017-04-22 15:55:08,381 (Z-Wave): Node : Node '9' : --> 'COMMAND_CLASS_CONFIGURATION', 'supported'. DEBUG 2017-04-22 15:55:08,382 (Z-Wave): Node : Node '9' : --> 'COMMAND_CLASS_BASIC', 'supported'. DEBUG 2017-04-22 15:55:08,383 (Z-Wave): Node : Node '9' : --> 'COMMAND_CLASS_MANUFACTURER_SPECIFIC', 'supported'. DEBUG 2017-04-22 15:55:08,384 (Z-Wave): Node : Node '9' : --> 'COMMAND_CLASS_SWITCH_BINARY', 'supported'. DEBUG 2017-04-22 15:55:08,385 (Z-Wave): Node : Node '9' : --> 'COMMAND_CLASS_VERSION', 'supported'. DEBUG 2017-04-22 15:55:08,386 (Z-Wave): Node : Node '9' : --> 'COMMAND_CLASS_SCENE_ACTIVATION', 'supported'. DEBUG 2017-04-22 15:55:08,389 (Z-Wave): Node_Initializer : Node '9' : [ZW_RequestNodeInfo, (Retry='1')] DEBUG 2017-04-22 15:55:08,391 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=2) Z-Wave function call 'ZW_RequestNodeInfo(NodeID=9)'. DEBUG 2017-04-22 15:55:08,391 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] INFO 2017-04-22 15:55:08,392 (Z-Wave): Controller : Z-Wave node info (ID=9) : [[Device Classes : 'BASIC_TYPE_ROUTING_SLAVE','GENERIC_TYPE_SWITCH_BINARY','SPECIFIC_TYPE_SCENE_SWITCH_BINARY'],[Capabilities : 'NODEINFO_CAPABILITY_ROUTING','NODEINFO_CAPABILITY_LISTENING'],[Security : 'NODEINFO_SECURITY_OPTIONAL_FUNC_SUPPORT']]. DEBUG 2017-04-22 15:55:08,393 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x04, 0x00, 0x60, 0x06, 0x9D] transmission OK. DEBUG 2017-04-22 15:55:08,393 (Z-Wave): Controller : Retrieving Z-Wave node info (ID=11)... DEBUG 2017-04-22 15:55:08,394 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_RequestNodeInfo(NodeID=6)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:08,394 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=3) Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=11)'. DEBUG 2017-04-22 15:55:08,398 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:08,401 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x04, 0x01, 0x60, 0x01, 0x9B] DEBUG 2017-04-22 15:55:08,420 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x04, 0x01, 0x60, 0x01, 0x9B] has been received. DEBUG 2017-04-22 15:55:08,427 (Z-Wave): RX_Session_Layer : Response received [0x01, 0x04, 0x01, 0x60, 0x01, 0x9B] -> Waiting 65,000 [ms] for callback of Z-Wave function call 'ZW_RequestNodeInfo(NodeID=6)'. DEBUG 2017-04-22 15:55:08,428 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:08,436 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x10, 0x00, 0x49, 0x84, 0x06, 0x0A, 0x04, 0x10, 0x01, 0x20, 0x25, 0x27, 0x72, 0x86, 0x70, 0x85, 0x18] DEBUG 2017-04-22 15:55:08,447 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x10, 0x00, 0x49, 0x84, 0x06, 0x0A, 0x04, 0x10, 0x01, 0x20, 0x25, 0x27, 0x72, 0x86, 0x70, 0x85, 0x18] has been received. DEBUG 2017-04-22 15:55:08,468 (Z-Wave): RX_Session_Layer : Callback received [0x01, 0x10, 0x00, 0x49, 0x84, 0x06, 0x0A, 0x04, 0x10, 0x01, 0x20, 0x25, 0x27, 0x72, 0x86, 0x70, 0x85, 0x18] -> Z-Wave function 'ZW_RequestNodeInfo(NodeID=6)' successfully executed. DEBUG 2017-04-22 15:55:08,483 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=2) Z-Wave function call 'ZW_RequestNodeInfo(NodeID=7)'. DEBUG 2017-04-22 15:55:08,484 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_RequestNodeInfo(NodeID=7)'... DEBUG 2017-04-22 15:55:08,485 (Z-Wave): ZW_RequestNodeInfo : Sending Z-Wave function 'ZW_RequestNodeInfo(NodeID=7)' call. DEBUG 2017-04-22 15:55:08,487 (Z-Wave): Node_Initializer : Node '6' : [ZW_RequestNodeInfo, (Retry='1')] succeeded : [[Status: UPDATE_STATE_NODE_INFO_RECEIVED, Node ID: 6, Device Classes: [Basic: BASIC_TYPE_ROUTING_SLAVE, Generic: GENERIC_TYPE_SWITCH_BINARY, Specific: SPECIFIC_TYPE_POWER_SWITCH_BINARY], Command Classes: [Supported: [COMMAND_CLASS_BASIC, COMMAND_CLASS_SWITCH_BINARY, COMMAND_CLASS_SWITCH_ALL, COMMAND_CLASS_MANUFACTURER_SPECIFIC, COMMAND_CLASS_VERSION, COMMAND_CLASS_CONFIGURATION, COMMAND_CLASS_ASSOCIATION], Controlled: [ -- ]]]]. DEBUG 2017-04-22 15:55:08,487 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x04, 0x00, 0x60, 0x07, 0x9C]. DEBUG 2017-04-22 15:55:08,488 (Z-Wave): Node_Initializer : Node '6' : ====== Update dynamic data of command classes... DEBUG 2017-04-22 15:55:08,492 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:08,495 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x04, 0x00, 0x60, 0x07, 0x9C] transmission OK. DEBUG 2017-04-22 15:55:08,496 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_RequestNodeInfo(NodeID=7)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:08,500 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:08,502 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x04, 0x01, 0x60, 0x01, 0x9B] DEBUG 2017-04-22 15:55:08,505 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x04, 0x01, 0x60, 0x01, 0x9B] has been received. DEBUG 2017-04-22 15:55:08,510 (Z-Wave): RX_Session_Layer : Response received [0x01, 0x04, 0x01, 0x60, 0x01, 0x9B] -> Waiting 65,000 [ms] for callback of Z-Wave function call 'ZW_RequestNodeInfo(NodeID=7)'. DEBUG 2017-04-22 15:55:08,577 (Z-Wave): Node_Initializer : Node '6' : ------ Update dynamic data of : [COMMAND_CLASS_BASIC] DEBUG 2017-04-22 15:55:08,578 (Z-Wave): Node_Initializer : Node '6:0' : [COMMAND_CLASS_BASIC::BASIC_GET (Retry='1')] DEBUG 2017-04-22 15:55:08,588 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:08,592 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x0E, 0x00, 0x49, 0x84, 0x07, 0x08, 0x04, 0x11, 0x01, 0x26, 0x27, 0x75, 0x72, 0x86, 0xA7] DEBUG 2017-04-22 15:55:08,595 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x0E, 0x00, 0x49, 0x84, 0x07, 0x08, 0x04, 0x11, 0x01, 0x26, 0x27, 0x75, 0x72, 0x86, 0xA7] has been received. DEBUG 2017-04-22 15:55:08,598 (Z-Wave): RX_Session_Layer : Callback received [0x01, 0x0E, 0x00, 0x49, 0x84, 0x07, 0x08, 0x04, 0x11, 0x01, 0x26, 0x27, 0x75, 0x72, 0x86, 0xA7] -> Z-Wave function 'ZW_RequestNodeInfo(NodeID=7)' successfully executed. DEBUG 2017-04-22 15:55:08,602 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=1) Z-Wave function call 'ZW_RequestNodeInfo(NodeID=9)'. DEBUG 2017-04-22 15:55:08,602 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_RequestNodeInfo(NodeID=9)'... DEBUG 2017-04-22 15:55:08,603 (Z-Wave): ZW_RequestNodeInfo : Sending Z-Wave function 'ZW_RequestNodeInfo(NodeID=9)' call. DEBUG 2017-04-22 15:55:08,603 (Z-Wave): Node_Initializer : Node '7' : [ZW_RequestNodeInfo, (Retry='1')] succeeded : [[Status: UPDATE_STATE_NODE_INFO_RECEIVED, Node ID: 7, Device Classes: [Basic: BASIC_TYPE_ROUTING_SLAVE, Generic: GENERIC_TYPE_SWITCH_MULTILEVEL, Specific: SPECIFIC_TYPE_POWER_SWITCH_MULTILEVEL], Command Classes: [Supported: [COMMAND_CLASS_SWITCH_MULTILEVEL, COMMAND_CLASS_SWITCH_ALL, COMMAND_CLASS_PROTECTION, COMMAND_CLASS_MANUFACTURER_SPECIFIC, COMMAND_CLASS_VERSION], Controlled: [ -- ]]]]. DEBUG 2017-04-22 15:55:08,604 (Z-Wave): Node_Initializer : Node '7' : ====== Update dynamic data of command classes... DEBUG 2017-04-22 15:55:08,605 (Z-Wave): Node_Initializer : Node '7' : ------ Update dynamic data of : [COMMAND_CLASS_BASIC] DEBUG 2017-04-22 15:55:08,605 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x04, 0x00, 0x60, 0x09, 0x92]. DEBUG 2017-04-22 15:55:08,606 (Z-Wave): Node_Initializer : Node '7:0' : [COMMAND_CLASS_BASIC::BASIC_GET (Retry='1')] DEBUG 2017-04-22 15:55:08,610 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:08,616 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x04, 0x00, 0x60, 0x09, 0x92] transmission OK. DEBUG 2017-04-22 15:55:08,617 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:08,617 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_RequestNodeInfo(NodeID=9)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:08,618 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x04, 0x01, 0x60, 0x01, 0x9B] DEBUG 2017-04-22 15:55:08,629 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x04, 0x01, 0x60, 0x01, 0x9B] has been received. DEBUG 2017-04-22 15:55:08,629 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=3) Z-Wave function call 'ZW_SendData(NodeID=6, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'. DEBUG 2017-04-22 15:55:08,631 (Z-Wave): RX_Session_Layer : Response received [0x01, 0x04, 0x01, 0x60, 0x01, 0x9B] -> Waiting 65,000 [ms] for callback of Z-Wave function call 'ZW_RequestNodeInfo(NodeID=9)'. DEBUG 2017-04-22 15:55:08,632 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=2) Z-Wave function call 'ZW_SendData(NodeID=7, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'. DEBUG 2017-04-22 15:55:08,691 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:08,694 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x11, 0x00, 0x49, 0x84, 0x09, 0x0B, 0x04, 0x10, 0x03, 0x25, 0x2B, 0x2C, 0x27, 0x73, 0x70, 0x86, 0x72, 0xC4] DEBUG 2017-04-22 15:55:08,698 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x11, 0x00, 0x49, 0x84, 0x09, 0x0B, 0x04, 0x10, 0x03, 0x25, 0x2B, 0x2C, 0x27, 0x73, 0x70, 0x86, 0x72, 0xC4] has been received. DEBUG 2017-04-22 15:55:08,701 (Z-Wave): RX_Session_Layer : Callback received [0x01, 0x11, 0x00, 0x49, 0x84, 0x09, 0x0B, 0x04, 0x10, 0x03, 0x25, 0x2B, 0x2C, 0x27, 0x73, 0x70, 0x86, 0x72, 0xC4] -> Z-Wave function 'ZW_RequestNodeInfo(NodeID=9)' successfully executed. DEBUG 2017-04-22 15:55:08,704 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=2) Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=11)'. DEBUG 2017-04-22 15:55:08,704 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=11)'... DEBUG 2017-04-22 15:55:08,706 (Z-Wave): Node_Initializer : Node '9' : [ZW_RequestNodeInfo, (Retry='1')] succeeded : [[Status: UPDATE_STATE_NODE_INFO_RECEIVED, Node ID: 9, Device Classes: [Basic: BASIC_TYPE_ROUTING_SLAVE, Generic: GENERIC_TYPE_SWITCH_BINARY, Specific: SPECIFIC_TYPE_SCENE_SWITCH_BINARY], Command Classes: [Supported: [COMMAND_CLASS_SWITCH_BINARY, COMMAND_CLASS_SCENE_ACTIVATION, COMMAND_CLASS_SCENE_ACTUATOR_CONF, COMMAND_CLASS_SWITCH_ALL, COMMAND_CLASS_POWERLEVEL, COMMAND_CLASS_CONFIGURATION, COMMAND_CLASS_VERSION, COMMAND_CLASS_MANUFACTURER_SPECIFIC], Controlled: [ -- ]]]]. DEBUG 2017-04-22 15:55:08,706 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x04, 0x00, 0x41, 0x0B, 0xB1]. DEBUG 2017-04-22 15:55:08,706 (Z-Wave): Node_Initializer : Node '9' : ====== Update dynamic data of command classes... DEBUG 2017-04-22 15:55:08,708 (Z-Wave): Node_Initializer : Node '9' : ------ Update dynamic data of : [COMMAND_CLASS_CONFIGURATION] DEBUG 2017-04-22 15:55:08,709 (Z-Wave): Node_Initializer : Node '9' : ------ Update dynamic data of : [COMMAND_CLASS_BASIC] DEBUG 2017-04-22 15:55:08,710 (Z-Wave): Node_Initializer : Node '9:0' : [COMMAND_CLASS_BASIC::BASIC_GET (Retry='1')] DEBUG 2017-04-22 15:55:08,710 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:08,711 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:08,711 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=3) Z-Wave function call 'ZW_SendData(NodeID=9, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'. DEBUG 2017-04-22 15:55:08,713 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x09, 0x01, 0x41, 0x53, 0x9C, 0x01, 0x04, 0x07, 0x01, 0x7A] DEBUG 2017-04-22 15:55:08,711 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x04, 0x00, 0x41, 0x0B, 0xB1] transmission OK. DEBUG 2017-04-22 15:55:08,719 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_GetNodeProtocolInfo(NodeID=11)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:08,722 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x09, 0x01, 0x41, 0x53, 0x9C, 0x01, 0x04, 0x07, 0x01, 0x7A] has been received. DEBUG 2017-04-22 15:55:08,724 (Z-Wave): RX_Session_Layer : Response received [0x01, 0x09, 0x01, 0x41, 0x53, 0x9C, 0x01, 0x04, 0x07, 0x01, 0x7A] -> Z-Wave function 'ZW_GetNodeProtocolInfo(NodeID=11)' successfully executed. DEBUG 2017-04-22 15:55:08,731 (Z-Wave): Node_Initializer : Node '11' : [ZW_RequestNodeInfo, (Retry='1')] DEBUG 2017-04-22 15:55:08,731 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=2) Z-Wave function call 'ZW_SendData(NodeID=7, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'. DEBUG 2017-04-22 15:55:08,732 (Z-Wave): Controller_API_WakeUp_Queue : Node '11' : Enqueue (Count='1') : 'ZW_RequestNodeInfo(NodeID=11)'. DEBUG 2017-04-22 15:55:08,733 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_SendData(NodeID=7, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'... INFO 2017-04-22 15:55:08,733 (Z-Wave): Controller : Z-Wave node info (ID=11) : [[Device Classes : 'BASIC_TYPE_ROUTING_SLAVE','GENERIC_TYPE_SENSOR_NOTIFICATION','SPECIFIC_TYPE_NOTIFICATION_SENSOR'],[Capabilities : 'NODEINFO_CAPABILITY_ROUTING'],[Security : 'NODEINFO_SECURITY_OPTIONAL_FUNC_SUPPORT']]. DEBUG 2017-04-22 15:55:08,735 (Z-Wave): Controller : Retrieving Z-Wave node info (ID=12)... DEBUG 2017-04-22 15:55:08,736 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=3) Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=12)'. DEBUG 2017-04-22 15:55:08,741 (Z-Wave): TX_Session_Layer : Send (repeat count=1) Z-Wave function 'ZW_SendData(NodeID=7, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x01)' request (callback ID=0x01). DEBUG 2017-04-22 15:55:08,744 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x20, 0x02, 0x05, 0x01, 0xC6]. DEBUG 2017-04-22 15:55:08,752 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:08,754 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x20, 0x02, 0x05, 0x01, 0xC6] transmission OK. DEBUG 2017-04-22 15:55:08,756 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_SendData(NodeID=7, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x01)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:08,756 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:08,764 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x04, 0x01, 0x13, 0x01, 0xE8] DEBUG 2017-04-22 15:55:08,767 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x04, 0x01, 0x13, 0x01, 0xE8] has been received. DEBUG 2017-04-22 15:55:08,774 (Z-Wave): RX_Session_Layer : 'ZW_SendData' response [0x01, 0x04, 0x01, 0x13, 0x01, 0xE8] with status 'RETURN_VALUE_TRUE' received (callback ID=0x01). DEBUG 2017-04-22 15:55:08,786 (Z-Wave): RX_Session_Layer : Waiting 64,949 [ms] for 'ZW_SendData' callback frame (callback ID=0x01). DEBUG 2017-04-22 15:55:08,795 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:08,797 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x07, 0x00, 0x13, 0x01, 0x00, 0x00, 0x04, 0xEE] DEBUG 2017-04-22 15:55:08,801 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x07, 0x00, 0x13, 0x01, 0x00, 0x00, 0x04, 0xEE] has been received. DEBUG 2017-04-22 15:55:08,809 (Z-Wave): RX_Session_Layer : Callback [0x01, 0x07, 0x00, 0x13, 0x01, 0x00, 0x00, 0x04, 0xEE] (callback ID=0x01) with state 'TRANSMIT_COMPLETE_OK' received -> Z-Wave function 'ZW_SendData(NodeID=7, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x01)' successfully executed. DEBUG 2017-04-22 15:55:08,819 (Z-Wave): RX_Session_Layer : Add function to pending transaction list (size='1') : ZW_SendData(NodeID=7, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x01) DEBUG 2017-04-22 15:55:08,822 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=2) Z-Wave function call 'ZW_SendData(NodeID=6, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'. DEBUG 2017-04-22 15:55:08,823 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_SendData(NodeID=6, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'... DEBUG 2017-04-22 15:55:08,827 (Z-Wave): TX_Session_Layer : Send (repeat count=1) Z-Wave function 'ZW_SendData(NodeID=6, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x02)' request (callback ID=0x02). DEBUG 2017-04-22 15:55:08,832 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x20, 0x02, 0x05, 0x02, 0xC4]. DEBUG 2017-04-22 15:55:08,841 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:08,844 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x09, 0x00, 0x04, 0x00, 0x07, 0x03, 0x20, 0x03, 0x00, 0xD5] DEBUG 2017-04-22 15:55:08,845 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x18] DEBUG 2017-04-22 15:55:08,846 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x09, 0x00, 0x04, 0x00, 0x07, 0x03, 0x20, 0x03, 0x00, 0xD5] has been received. DEBUG 2017-04-22 15:55:08,853 (Z-Wave): RX_Session_Layer : Received an unexpected frame [APP_CMD_HANDLER_FRAME : NodeID='7', Status=[RECEIVE_STATUS_TYPE_SINGLE], CommandClass='COMMAND_CLASS_BASIC', Command='0x03', Parameters: [0x00]] while waiting for an ACK of the Z-Wave function 'ZW_SendData(NodeID=6, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x02)'. DEBUG 2017-04-22 15:55:08,860 (Z-Wave): Node_Initializer : Node '7:0' : [COMMAND_CLASS_BASIC::BASIC_REPORT (Retry='1'), Value='0'] DEBUG 2017-04-22 15:55:08,861 (Z-Wave): Node_Initializer : Node '7' : ------ Update dynamic data of : [COMMAND_CLASS_MANUFACTURER_SPECIFIC] DEBUG 2017-04-22 15:55:08,863 (Z-Wave): Node_Initializer : Node '7' : ------ Update dynamic data of : [COMMAND_CLASS_PROTECTION] DEBUG 2017-04-22 15:55:08,864 (Z-Wave): Node_Initializer : Node '7:0' : [COMMAND_CLASS_PROTECTION::PROTECTION_GET (Retry='1')] DEBUG 2017-04-22 15:55:08,874 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=3) Z-Wave function call 'ZW_SendData(NodeID=7, Payload=[0x75, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'. DEBUG 2017-04-22 15:55:08,876 (Z-Wave): RX_Session_Layer : Removed function from pending transaction list (size='0') : ZW_SendData(NodeID=7, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x01) DEBUG 2017-04-22 15:55:08,879 (Z-Wave): RX_Frame_Layer : CAN -> Failed to send data frame [0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x20, 0x02, 0x05, 0x02, 0xC4] because the Z-Wave firmware has an ACK expected instead of the sent frame DEBUG 2017-04-22 15:55:08,880 (Z-Wave): TX_Frame_Layer : CAN -> Wait 100 [ms] before next retransmission attempt. DEBUG 2017-04-22 15:55:08,986 (Z-Wave): TX_Frame_Layer : Retransmission attempt 1, data frame [0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x20, 0x02, 0x05, 0x02, 0xC4] DEBUG 2017-04-22 15:55:08,991 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:09,008 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x20, 0x02, 0x05, 0x02, 0xC4] transmission OK. DEBUG 2017-04-22 15:55:09,009 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:09,010 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x04, 0x01, 0x13, 0x01, 0xE8] DEBUG 2017-04-22 15:55:09,010 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_SendData(NodeID=6, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x02)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:09,012 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x04, 0x01, 0x13, 0x01, 0xE8] has been received. DEBUG 2017-04-22 15:55:09,013 (Z-Wave): RX_Session_Layer : 'ZW_SendData' response [0x01, 0x04, 0x01, 0x13, 0x01, 0xE8] with status 'RETURN_VALUE_TRUE' received (callback ID=0x02). DEBUG 2017-04-22 15:55:09,014 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:09,014 (Z-Wave): RX_Session_Layer : Waiting 64,811 [ms] for 'ZW_SendData' callback frame (callback ID=0x02). DEBUG 2017-04-22 15:55:09,015 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x07, 0x00, 0x13, 0x02, 0x00, 0x00, 0x02, 0xEB] DEBUG 2017-04-22 15:55:09,016 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x07, 0x00, 0x13, 0x02, 0x00, 0x00, 0x02, 0xEB] has been received. DEBUG 2017-04-22 15:55:09,019 (Z-Wave): RX_Session_Layer : Callback [0x01, 0x07, 0x00, 0x13, 0x02, 0x00, 0x00, 0x02, 0xEB] (callback ID=0x02) with state 'TRANSMIT_COMPLETE_OK' received -> Z-Wave function 'ZW_SendData(NodeID=6, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x02)' successfully executed. DEBUG 2017-04-22 15:55:09,020 (Z-Wave): RX_Session_Layer : Add function to pending transaction list (size='1') : ZW_SendData(NodeID=6, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x02) DEBUG 2017-04-22 15:55:09,022 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=2) Z-Wave function call 'ZW_SendData(NodeID=9, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'. DEBUG 2017-04-22 15:55:09,024 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_SendData(NodeID=9, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'... DEBUG 2017-04-22 15:55:09,024 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:09,025 (Z-Wave): TX_Session_Layer : Send (repeat count=1) Z-Wave function 'ZW_SendData(NodeID=9, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x03)' request (callback ID=0x03). DEBUG 2017-04-22 15:55:09,025 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x20, 0x03, 0x00, 0xD4] DEBUG 2017-04-22 15:55:09,027 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x20, 0x02, 0x05, 0x03, 0xCA]. DEBUG 2017-04-22 15:55:09,029 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x20, 0x03, 0x00, 0xD4] has been received. DEBUG 2017-04-22 15:55:09,030 (Z-Wave): RX_Session_Layer : Received an unexpected frame [APP_CMD_HANDLER_FRAME : NodeID='6', Status=[RECEIVE_STATUS_TYPE_SINGLE], CommandClass='COMMAND_CLASS_BASIC', Command='0x03', Parameters: [0x00]] while waiting for an ACK of the Z-Wave function 'ZW_SendData(NodeID=9, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x03)'. DEBUG 2017-04-22 15:55:09,031 (Z-Wave): Node_Initializer : Node '6:0' : [COMMAND_CLASS_BASIC::BASIC_REPORT (Retry='1'), Value='0'] DEBUG 2017-04-22 15:55:09,031 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x18] DEBUG 2017-04-22 15:55:09,032 (Z-Wave): Node_Initializer : Node '6' : ------ Update dynamic data of : [COMMAND_CLASS_CONFIGURATION] DEBUG 2017-04-22 15:55:09,033 (Z-Wave): Node_Initializer : Node '6' : ------ Update dynamic data of : [COMMAND_CLASS_MANUFACTURER_SPECIFIC] DEBUG 2017-04-22 15:55:09,033 (Z-Wave): RX_Session_Layer : Removed function from pending transaction list (size='0') : ZW_SendData(NodeID=6, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x02) DEBUG 2017-04-22 15:55:09,034 (Z-Wave): Node_Initializer : Node '6' : ------ Update dynamic data of : [COMMAND_CLASS_SWITCH_BINARY] DEBUG 2017-04-22 15:55:09,035 (Z-Wave): RX_Frame_Layer : CAN -> Failed to send data frame [0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x20, 0x02, 0x05, 0x03, 0xCA] because the Z-Wave firmware has an ACK expected instead of the sent frame DEBUG 2017-04-22 15:55:09,035 (Z-Wave): Node_Initializer : Node '6:0' : [COMMAND_CLASS_SWITCH_BINARY::SWITCH_BINARY_GET (Retry='1')] DEBUG 2017-04-22 15:55:09,037 (Z-Wave): TX_Frame_Layer : CAN -> Wait 100 [ms] before next retransmission attempt. DEBUG 2017-04-22 15:55:09,047 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=3) Z-Wave function call 'ZW_SendData(NodeID=6, Payload=[0x25, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'. DEBUG 2017-04-22 15:55:09,139 (Z-Wave): TX_Frame_Layer : Retransmission attempt 1, data frame [0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x20, 0x02, 0x05, 0x03, 0xCA] DEBUG 2017-04-22 15:55:09,144 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:09,145 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x20, 0x02, 0x05, 0x03, 0xCA] transmission OK. DEBUG 2017-04-22 15:55:09,146 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_SendData(NodeID=9, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x03)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:09,149 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:09,150 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x04, 0x01, 0x13, 0x01, 0xE8] DEBUG 2017-04-22 15:55:09,152 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x04, 0x01, 0x13, 0x01, 0xE8] has been received. DEBUG 2017-04-22 15:55:09,153 (Z-Wave): RX_Session_Layer : 'ZW_SendData' response [0x01, 0x04, 0x01, 0x13, 0x01, 0xE8] with status 'RETURN_VALUE_TRUE' received (callback ID=0x03). DEBUG 2017-04-22 15:55:09,154 (Z-Wave): RX_Session_Layer : Waiting 64,871 [ms] for 'ZW_SendData' callback frame (callback ID=0x03). DEBUG 2017-04-22 15:55:09,166 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:09,167 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x07, 0x00, 0x13, 0x03, 0x00, 0x00, 0x02, 0xEA] DEBUG 2017-04-22 15:55:09,169 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x07, 0x00, 0x13, 0x03, 0x00, 0x00, 0x02, 0xEA] has been received. DEBUG 2017-04-22 15:55:09,171 (Z-Wave): RX_Session_Layer : Callback [0x01, 0x07, 0x00, 0x13, 0x03, 0x00, 0x00, 0x02, 0xEA] (callback ID=0x03) with state 'TRANSMIT_COMPLETE_OK' received -> Z-Wave function 'ZW_SendData(NodeID=9, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x03)' successfully executed. DEBUG 2017-04-22 15:55:09,172 (Z-Wave): RX_Session_Layer : Add function to pending transaction list (size='1') : ZW_SendData(NodeID=9, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x03) DEBUG 2017-04-22 15:55:09,173 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=2) Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=12)'. DEBUG 2017-04-22 15:55:09,173 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_GetNodeProtocolInfo(NodeID=12)'... DEBUG 2017-04-22 15:55:09,174 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x04, 0x00, 0x41, 0x0C, 0xB6]. DEBUG 2017-04-22 15:55:09,176 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:09,179 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x09, 0x00, 0x04, 0x00, 0x09, 0x03, 0x20, 0x03, 0x00, 0xDB] DEBUG 2017-04-22 15:55:09,180 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x18] DEBUG 2017-04-22 15:55:09,180 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x09, 0x00, 0x04, 0x00, 0x09, 0x03, 0x20, 0x03, 0x00, 0xDB] has been received. DEBUG 2017-04-22 15:55:09,181 (Z-Wave): RX_Session_Layer : Received an unexpected frame [APP_CMD_HANDLER_FRAME : NodeID='9', Status=[RECEIVE_STATUS_TYPE_SINGLE], CommandClass='COMMAND_CLASS_BASIC', Command='0x03', Parameters: [0x00]] while waiting for an ACK of the Z-Wave function 'ZW_GetNodeProtocolInfo(NodeID=12)'. DEBUG 2017-04-22 15:55:09,183 (Z-Wave): Node_Initializer : Node '9:0' : [COMMAND_CLASS_BASIC::BASIC_REPORT (Retry='1'), Value='0'] DEBUG 2017-04-22 15:55:09,185 (Z-Wave): Node_Initializer : Node '9' : ------ Update dynamic data of : [COMMAND_CLASS_MANUFACTURER_SPECIFIC] DEBUG 2017-04-22 15:55:09,185 (Z-Wave): Node_Initializer : Node '9' : ------ Update dynamic data of : [COMMAND_CLASS_SWITCH_BINARY] DEBUG 2017-04-22 15:55:09,186 (Z-Wave): Node_Initializer : Node '9:0' : [COMMAND_CLASS_SWITCH_BINARY::SWITCH_BINARY_GET (Retry='1')] DEBUG 2017-04-22 15:55:09,187 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=3) Z-Wave function call 'ZW_SendData(NodeID=9, Payload=[0x25, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'. DEBUG 2017-04-22 15:55:09,190 (Z-Wave): RX_Session_Layer : Removed function from pending transaction list (size='0') : ZW_SendData(NodeID=9, Payload=[0x20, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x03) DEBUG 2017-04-22 15:55:09,191 (Z-Wave): RX_Frame_Layer : CAN -> Failed to send data frame [0x01, 0x04, 0x00, 0x41, 0x0C, 0xB6] because the Z-Wave firmware has an ACK expected instead of the sent frame DEBUG 2017-04-22 15:55:09,191 (Z-Wave): TX_Frame_Layer : CAN -> Wait 100 [ms] before next retransmission attempt. DEBUG 2017-04-22 15:55:09,292 (Z-Wave): TX_Frame_Layer : Retransmission attempt 1, data frame [0x01, 0x04, 0x00, 0x41, 0x0C, 0xB6] DEBUG 2017-04-22 15:55:09,296 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:09,297 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x04, 0x00, 0x41, 0x0C, 0xB6] transmission OK. DEBUG 2017-04-22 15:55:09,297 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01, 0x09, 0x01, 0x41, 0x53, 0x9C, 0x01, 0x04, 0x07, 0x01, 0x7A] DEBUG 2017-04-22 15:55:09,298 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_GetNodeProtocolInfo(NodeID=12)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:09,300 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x09, 0x01, 0x41, 0x53, 0x9C, 0x01, 0x04, 0x07, 0x01, 0x7A] has been received. DEBUG 2017-04-22 15:55:09,301 (Z-Wave): RX_Session_Layer : Response received [0x01, 0x09, 0x01, 0x41, 0x53, 0x9C, 0x01, 0x04, 0x07, 0x01, 0x7A] -> Z-Wave function 'ZW_GetNodeProtocolInfo(NodeID=12)' successfully executed. DEBUG 2017-04-22 15:55:09,304 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=2) Z-Wave function call 'ZW_SendData(NodeID=7, Payload=[0x75, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'. DEBUG 2017-04-22 15:55:09,305 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_SendData(NodeID=7, Payload=[0x75, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'... DEBUG 2017-04-22 15:55:09,306 (Z-Wave): TX_Session_Layer : Send (repeat count=1) Z-Wave function 'ZW_SendData(NodeID=7, Payload=[0x75, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x04)' request (callback ID=0x04). DEBUG 2017-04-22 15:55:09,307 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x75, 0x02, 0x05, 0x04, 0x96]. DEBUG 2017-04-22 15:55:09,312 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:09,313 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x75, 0x02, 0x05, 0x04, 0x96] transmission OK. DEBUG 2017-04-22 15:55:09,314 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_SendData(NodeID=7, Payload=[0x75, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x04)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:09,317 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:09,318 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x04, 0x01, 0x13, 0x01, 0xE8] DEBUG 2017-04-22 15:55:09,320 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x04, 0x01, 0x13, 0x01, 0xE8] has been received. DEBUG 2017-04-22 15:55:09,321 (Z-Wave): RX_Session_Layer : 'ZW_SendData' response [0x01, 0x04, 0x01, 0x13, 0x01, 0xE8] with status 'RETURN_VALUE_TRUE' received (callback ID=0x04). DEBUG 2017-04-22 15:55:09,322 (Z-Wave): RX_Session_Layer : Waiting 64,984 [ms] for 'ZW_SendData' callback frame (callback ID=0x04). DEBUG 2017-04-22 15:55:09,355 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:09,357 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x07, 0x00, 0x13, 0x04, 0x00, 0x00, 0x04, 0xEB] DEBUG 2017-04-22 15:55:09,359 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x07, 0x00, 0x13, 0x04, 0x00, 0x00, 0x04, 0xEB] has been received. DEBUG 2017-04-22 15:55:09,361 (Z-Wave): RX_Session_Layer : Callback [0x01, 0x07, 0x00, 0x13, 0x04, 0x00, 0x00, 0x04, 0xEB] (callback ID=0x04) with state 'TRANSMIT_COMPLETE_OK' received -> Z-Wave function 'ZW_SendData(NodeID=7, Payload=[0x75, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x04)' successfully executed. DEBUG 2017-04-22 15:55:09,363 (Z-Wave): RX_Session_Layer : Add function to pending transaction list (size='1') : ZW_SendData(NodeID=7, Payload=[0x75, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x04) DEBUG 2017-04-22 15:55:09,364 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=1) Z-Wave function call 'ZW_SendData(NodeID=6, Payload=[0x25, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'. DEBUG 2017-04-22 15:55:09,365 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_SendData(NodeID=6, Payload=[0x25, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'... DEBUG 2017-04-22 15:55:09,366 (Z-Wave): TX_Session_Layer : Send (repeat count=1) Z-Wave function 'ZW_SendData(NodeID=6, Payload=[0x25, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x05)' request (callback ID=0x05). DEBUG 2017-04-22 15:55:09,367 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x25, 0x02, 0x05, 0x05, 0xC6]. DEBUG 2017-04-22 15:55:09,372 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:09,373 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x09, 0x00, 0x13, 0x06, 0x02, 0x25, 0x02, 0x05, 0x05, 0xC6] transmission OK. DEBUG 2017-04-22 15:55:09,374 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_SendData(NodeID=6, Payload=[0x25, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x05)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:09,378 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:09,379 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x04, 0x01, 0x13, 0x01, 0xE8] DEBUG 2017-04-22 15:55:09,381 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x04, 0x01, 0x13, 0x01, 0xE8] has been received. DEBUG 2017-04-22 15:55:09,382 (Z-Wave): RX_Session_Layer : 'ZW_SendData' response [0x01, 0x04, 0x01, 0x13, 0x01, 0xE8] with status 'RETURN_VALUE_TRUE' received (callback ID=0x05). DEBUG 2017-04-22 15:55:09,382 (Z-Wave): RX_Session_Layer : Waiting 64,984 [ms] for 'ZW_SendData' callback frame (callback ID=0x05). DEBUG 2017-04-22 15:55:09,401 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:09,402 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x09, 0x00, 0x04, 0x00, 0x07, 0x03, 0x75, 0x03, 0x00, 0x80] DEBUG 2017-04-22 15:55:09,405 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x09, 0x00, 0x04, 0x00, 0x07, 0x03, 0x75, 0x03, 0x00, 0x80] has been received. DEBUG 2017-04-22 15:55:09,412 (Z-Wave): Node_Initializer : Node '7:0' : [COMMAND_CLASS_PROTECTION::PROTECTION_GET (Retry='1'), State='UNPROTECTED'] DEBUG 2017-04-22 15:55:09,414 (Z-Wave): Node_Initializer : Node '7' : ------ Update dynamic data of : [COMMAND_CLASS_SWITCH_MULTILEVEL] DEBUG 2017-04-22 15:55:09,415 (Z-Wave): Node_Initializer : Node '7:0' : [COMMAND_CLASS_SWITCH_MULTILEVEL::SWITCH_MULTILEVEL_GET (Retry='1')] DEBUG 2017-04-22 15:55:09,415 (Z-Wave): RX_Session_Layer : Removed function from pending transaction list (size='0') : ZW_SendData(NodeID=7, Payload=[0x75, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x04) DEBUG 2017-04-22 15:55:09,427 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=2) Z-Wave function call 'ZW_SendData(NodeID=7, Payload=[0x26, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'. DEBUG 2017-04-22 15:55:09,479 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:09,480 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x07, 0x00, 0x13, 0x05, 0x00, 0x00, 0x09, 0xE7] DEBUG 2017-04-22 15:55:09,482 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x07, 0x00, 0x13, 0x05, 0x00, 0x00, 0x09, 0xE7] has been received. DEBUG 2017-04-22 15:55:09,483 (Z-Wave): RX_Session_Layer : Callback [0x01, 0x07, 0x00, 0x13, 0x05, 0x00, 0x00, 0x09, 0xE7] (callback ID=0x05) with state 'TRANSMIT_COMPLETE_OK' received -> Z-Wave function 'ZW_SendData(NodeID=6, Payload=[0x25, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x05)' successfully executed. DEBUG 2017-04-22 15:55:09,484 (Z-Wave): RX_Session_Layer : Add function to pending transaction list (size='1') : ZW_SendData(NodeID=6, Payload=[0x25, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x05) DEBUG 2017-04-22 15:55:09,485 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=1) Z-Wave function call 'ZW_SendData(NodeID=9, Payload=[0x25, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'. DEBUG 2017-04-22 15:55:09,486 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_SendData(NodeID=9, Payload=[0x25, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'... DEBUG 2017-04-22 15:55:09,487 (Z-Wave): TX_Session_Layer : Send (repeat count=1) Z-Wave function 'ZW_SendData(NodeID=9, Payload=[0x25, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x06)' request (callback ID=0x06). DEBUG 2017-04-22 15:55:09,488 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x25, 0x02, 0x05, 0x06, 0xCA]. DEBUG 2017-04-22 15:55:09,492 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:09,494 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x09, 0x00, 0x13, 0x09, 0x02, 0x25, 0x02, 0x05, 0x06, 0xCA] transmission OK. DEBUG 2017-04-22 15:55:09,495 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_SendData(NodeID=9, Payload=[0x25, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x06)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:09,498 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:09,499 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x04, 0x01, 0x13, 0x01, 0xE8] DEBUG 2017-04-22 15:55:09,501 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x04, 0x01, 0x13, 0x01, 0xE8] has been received. DEBUG 2017-04-22 15:55:09,501 (Z-Wave): RX_Session_Layer : 'ZW_SendData' response [0x01, 0x04, 0x01, 0x13, 0x01, 0xE8] with status 'RETURN_VALUE_TRUE' received (callback ID=0x06). DEBUG 2017-04-22 15:55:09,502 (Z-Wave): RX_Session_Layer : Waiting 64,985 [ms] for 'ZW_SendData' callback frame (callback ID=0x06). DEBUG 2017-04-22 15:55:09,547 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:09,548 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x07, 0x00, 0x13, 0x06, 0x00, 0x00, 0x05, 0xE8] DEBUG 2017-04-22 15:55:09,549 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x07, 0x00, 0x13, 0x06, 0x00, 0x00, 0x05, 0xE8] has been received. DEBUG 2017-04-22 15:55:09,550 (Z-Wave): RX_Session_Layer : Callback [0x01, 0x07, 0x00, 0x13, 0x06, 0x00, 0x00, 0x05, 0xE8] (callback ID=0x06) with state 'TRANSMIT_COMPLETE_OK' received -> Z-Wave function 'ZW_SendData(NodeID=9, Payload=[0x25, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x06)' successfully executed. DEBUG 2017-04-22 15:55:09,550 (Z-Wave): RX_Session_Layer : Add function to pending transaction list (size='2') : ZW_SendData(NodeID=9, Payload=[0x25, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x06) DEBUG 2017-04-22 15:55:09,551 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=0) Z-Wave function call 'ZW_SendData(NodeID=7, Payload=[0x26, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'. DEBUG 2017-04-22 15:55:09,551 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_SendData(NodeID=7, Payload=[0x26, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x00)'... DEBUG 2017-04-22 15:55:09,552 (Z-Wave): TX_Session_Layer : Send (repeat count=1) Z-Wave function 'ZW_SendData(NodeID=7, Payload=[0x26, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x07)' request (callback ID=0x07). DEBUG 2017-04-22 15:55:09,552 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x05, 0x07, 0xC6]. DEBUG 2017-04-22 15:55:09,556 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:09,557 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x09, 0x00, 0x04, 0x00, 0x09, 0x03, 0x25, 0x03, 0x00, 0xDE] DEBUG 2017-04-22 15:55:09,558 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x18] DEBUG 2017-04-22 15:55:09,559 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x09, 0x00, 0x04, 0x00, 0x09, 0x03, 0x25, 0x03, 0x00, 0xDE] has been received. DEBUG 2017-04-22 15:55:09,560 (Z-Wave): RX_Session_Layer : Received an unexpected frame [APP_CMD_HANDLER_FRAME : NodeID='9', Status=[RECEIVE_STATUS_TYPE_SINGLE], CommandClass='COMMAND_CLASS_SWITCH_BINARY', Command='0x03', Parameters: [0x00]] while waiting for an ACK of the Z-Wave function 'ZW_SendData(NodeID=7, Payload=[0x26, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x07)'. DEBUG 2017-04-22 15:55:09,590 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:09,591 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x25, 0x03, 0x00, 0xD1] DEBUG 2017-04-22 15:55:09,825 (Z-Wave): Node_Initializer : Node '9:0' : [COMMAND_CLASS_SWITCH_BINARY::SWITCH_BINARY_REPORT (Retry='1'), State='OFF'] DEBUG 2017-04-22 15:55:09,826 (Z-Wave): Node_Initializer : Node '9' : ------ Update dynamic data of : [COMMAND_CLASS_VERSION] DEBUG 2017-04-22 15:55:09,826 (Z-Wave): RX_Session_Layer : Removed function from pending transaction list (size='1') : ZW_SendData(NodeID=9, Payload=[0x25, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x06) DEBUG 2017-04-22 15:55:09,827 (Z-Wave): Node_Initializer : Node '9' : ------ Update dynamic data of : [COMMAND_CLASS_SCENE_ACTIVATION] INFO 2017-04-22 15:55:09,827 (Z-Wave): Node '9' : Node [Manufacturer='Linear Corp', Type='Unknown'] has been successfully initialized. DEBUG 2017-04-22 15:55:09,827 (Z-Wave): RX_Frame_Layer : CAN -> Failed to send data frame [0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x05, 0x07, 0xC6] because the Z-Wave firmware has an ACK expected instead of the sent frame DEBUG 2017-04-22 15:55:09,828 (Z-Wave): TX_Frame_Layer : CAN -> Wait 100 [ms] before next retransmission attempt. DEBUG 2017-04-22 15:55:09,829 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x09, 0x00, 0x04, 0x00, 0x06, 0x03, 0x25, 0x03, 0x00, 0xD1] has been received. DEBUG 2017-04-22 15:55:09,830 (Z-Wave): RX_Session_Layer : Received an unexpected frame [APP_CMD_HANDLER_FRAME : NodeID='6', Status=[RECEIVE_STATUS_TYPE_SINGLE], CommandClass='COMMAND_CLASS_SWITCH_BINARY', Command='0x03', Parameters: [0x00]] while waiting for an ACK of the Z-Wave function 'ZW_SendData(NodeID=7, Payload=[0x26, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x07)'. DEBUG 2017-04-22 15:55:09,830 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:09,831 (Z-Wave): Node_Initializer : Node '6:0' : [COMMAND_CLASS_SWITCH_BINARY::SWITCH_BINARY_REPORT (Retry='1'), State='OFF'] DEBUG 2017-04-22 15:55:09,831 (Z-Wave): Node_Initializer : Node '6' : ------ Update dynamic data of : [COMMAND_CLASS_ASSOCIATION_V2] DEBUG 2017-04-22 15:55:09,831 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x09, 0x00, 0x04, 0x00, 0x07, 0x03, 0x75, 0x03, 0x00, 0x80] DEBUG 2017-04-22 15:55:09,831 (Z-Wave): Node_Initializer : Node '6' : ------ Update dynamic data of : [COMMAND_CLASS_VERSION] INFO 2017-04-22 15:55:09,832 (Z-Wave): Node '6' : Node [Manufacturer='Remotec Technology Ltd', Type='Unknown'] has been successfully initialized. DEBUG 2017-04-22 15:55:09,832 (Z-Wave): RX_Session_Layer : Removed function from pending transaction list (size='0') : ZW_SendData(NodeID=6, Payload=[0x25, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x05) DEBUG 2017-04-22 15:55:09,833 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x09, 0x00, 0x04, 0x00, 0x07, 0x03, 0x75, 0x03, 0x00, 0x80] has been received. DEBUG 2017-04-22 15:55:09,834 (Z-Wave): RX_Session_Layer : Received an unexpected frame [APP_CMD_HANDLER_FRAME : NodeID='7', Status=[RECEIVE_STATUS_TYPE_SINGLE], CommandClass='COMMAND_CLASS_PROTECTION', Command='0x03', Parameters: [0x00]] while waiting for an ACK of the Z-Wave function 'ZW_SendData(NodeID=7, Payload=[0x26, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x07)'. DEBUG 2017-04-22 15:55:09,839 (Z-Wave): RX_Session_Layer : Node '7' : [APP_CMD_HANDLER_FRAME : NodeID='7', Status=[RECEIVE_STATUS_TYPE_SINGLE], CommandClass='COMMAND_CLASS_PROTECTION', Command='0x03', Parameters: [0x00]] DEBUG 2017-04-22 15:55:09,852 (Z-Wave): CCProtection : Node '7:0' : [COMMAND_CLASS_PROTECTION::PROTECTION_REPORT, State='UNPROTECTED']. DEBUG 2017-04-22 15:55:09,929 (Z-Wave): TX_Frame_Layer : Retransmission attempt 1, data frame [0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x05, 0x07, 0xC6] DEBUG 2017-04-22 15:55:09,932 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:09,933 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x09, 0x00, 0x13, 0x07, 0x02, 0x26, 0x02, 0x05, 0x07, 0xC6] transmission OK. DEBUG 2017-04-22 15:55:09,933 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_SendData(NodeID=7, Payload=[0x26, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x07)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:09,937 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:09,938 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x04, 0x01, 0x13, 0x01, 0xE8] DEBUG 2017-04-22 15:55:09,939 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x04, 0x01, 0x13, 0x01, 0xE8] has been received. DEBUG 2017-04-22 15:55:09,939 (Z-Wave): RX_Session_Layer : 'ZW_SendData' response [0x01, 0x04, 0x01, 0x13, 0x01, 0xE8] with status 'RETURN_VALUE_TRUE' received (callback ID=0x07). DEBUG 2017-04-22 15:55:09,939 (Z-Wave): RX_Session_Layer : Waiting 64,612 [ms] for 'ZW_SendData' callback frame (callback ID=0x07). DEBUG 2017-04-22 15:55:09,975 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:09,976 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x07, 0x00, 0x13, 0x07, 0x00, 0x00, 0x04, 0xE8] DEBUG 2017-04-22 15:55:09,976 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x07, 0x00, 0x13, 0x07, 0x00, 0x00, 0x04, 0xE8] has been received. DEBUG 2017-04-22 15:55:09,977 (Z-Wave): RX_Session_Layer : Callback [0x01, 0x07, 0x00, 0x13, 0x07, 0x00, 0x00, 0x04, 0xE8] (callback ID=0x07) with state 'TRANSMIT_COMPLETE_OK' received -> Z-Wave function 'ZW_SendData(NodeID=7, Payload=[0x26, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x07)' successfully executed. DEBUG 2017-04-22 15:55:09,978 (Z-Wave): RX_Session_Layer : Add function to pending transaction list (size='1') : ZW_SendData(NodeID=7, Payload=[0x26, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x07) DEBUG 2017-04-22 15:55:10,002 (Z-Wave): Installing BouncyCastle security provider... DEBUG 2017-04-22 15:55:10,020 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01] DEBUG 2017-04-22 15:55:10,021 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x09, 0x00, 0x04, 0x00, 0x07, 0x03, 0x26, 0x03, 0x00, 0xD3] DEBUG 2017-04-22 15:55:10,022 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x09, 0x00, 0x04, 0x00, 0x07, 0x03, 0x26, 0x03, 0x00, 0xD3] has been received. DEBUG 2017-04-22 15:55:10,026 (Z-Wave): Node_Initializer : Node '7:0' : [COMMAND_CLASS_SWITCH_MULTILEVEL::SWITCH_MULTILEVEL_REPORT (Retry='1'), Value='0'] DEBUG 2017-04-22 15:55:10,026 (Z-Wave): RX_Session_Layer : Removed function from pending transaction list (size='0') : ZW_SendData(NodeID=7, Payload=[0x26, 0x02], TxOptions=[TRANSMIT_OPTION_AUTO_ROUTE, TRANSMIT_EXPLORE_OPTION_ACK], CallbackID=0x07) DEBUG 2017-04-22 15:55:10,028 (Z-Wave): Node_Initializer : Node '7' : ------ Update dynamic data of : [COMMAND_CLASS_VERSION] INFO 2017-04-22 15:55:10,028 (Z-Wave): Node '7' : Node [Manufacturer='Vision Security', Type='Unknown'] has been successfully initialized. DEBUG 2017-04-22 15:55:15,812 (Z-Wave): Node : Node '12' : Node has been successfully initialized with the following command classes... INFO 2017-04-22 15:55:15,812 (Z-Wave): Controller : Z-Wave node info (ID=12) : [[Device Classes : 'BASIC_TYPE_ROUTING_SLAVE','GENERIC_TYPE_SENSOR_NOTIFICATION','SPECIFIC_TYPE_NOTIFICATION_SENSOR'],[Capabilities : 'NODEINFO_CAPABILITY_ROUTING'],[Security : 'NODEINFO_SECURITY_OPTIONAL_FUNC_SUPPORT']]. DEBUG 2017-04-22 15:55:15,813 (Z-Wave): Node : Node '12' : --> 'COMMAND_CLASS_NO_OPERATION', 'supported'. DEBUG 2017-04-22 15:55:15,813 (Z-Wave): Controller : Configuring Z-Wave controller as SUC... DEBUG 2017-04-22 15:55:15,813 (Z-Wave): Node : Node '12' : --> 'COMMAND_CLASS_BATTERY', 'supported'. DEBUG 2017-04-22 15:55:15,814 (Z-Wave): Node : Node '12' : --> 'COMMAND_CLASS_BASIC', 'supported'. DEBUG 2017-04-22 15:55:15,814 (Z-Wave): Node : Node '12' : --> 'COMMAND_CLASS_METER_V2', 'supported'. DEBUG 2017-04-22 15:55:15,815 (Z-Wave): Node : Node '12' : --> 'COMMAND_CLASS_MANUFACTURER_SPECIFIC', 'supported'. DEBUG 2017-04-22 15:55:15,816 (Z-Wave): Node : Node '12' : --> 'COMMAND_CLASS_WAKE_UP_V2', 'supported'. DEBUG 2017-04-22 15:55:15,816 (Z-Wave): Node : Node '12' : --> 'COMMAND_CLASS_ASSOCIATION_V2', 'supported'. DEBUG 2017-04-22 15:55:15,816 (Z-Wave): Node : Node '12' : --> 'COMMAND_CLASS_VERSION', 'supported'. DEBUG 2017-04-22 15:55:15,817 (Z-Wave): Node : Node '12' : --> 'COMMAND_CLASS_SECURITY', 'supported'. DEBUG 2017-04-22 15:55:15,819 (Z-Wave): Node_Initializer : Node '12' : [ZW_RequestNodeInfo, (Retry='1')] DEBUG 2017-04-22 15:55:15,820 (Z-Wave): Controller_API_WakeUp_Queue : Node '12' : Enqueue (Count='1') : 'ZW_RequestNodeInfo(NodeID=12)'. DEBUG 2017-04-22 15:55:15,858 (Z-Wave): Controller_API : Dequeue (WORKING-Queue, Count=0) Z-Wave function call 'ZW_SetSUCNodeID(NodeID=1, IsLocalNode=true, State=ENABLE_SUC, TxOption=LOW_POWER, Capability=ZW_SUC_FUNC_NODEID_SERVER)'. DEBUG 2017-04-22 15:55:15,858 (Z-Wave): Controller_API : Enqueue (WORKING-Queue, Count=1) Z-Wave function call 'ZW_SetSUCNodeID(NodeID=1, IsLocalNode=true, State=ENABLE_SUC, TxOption=LOW_POWER, Capability=ZW_SUC_FUNC_NODEID_SERVER)'. DEBUG 2017-04-22 15:55:15,859 (Z-Wave): TX_Session_Layer : Executing Z-Wave function call 'ZW_SetSUCNodeID(NodeID=1, IsLocalNode=true, State=ENABLE_SUC, TxOption=LOW_POWER, Capability=ZW_SUC_FUNC_NODEID_SERVER)'... DEBUG 2017-04-22 15:55:15,861 (Z-Wave): TX_Frame_Layer : Send data frame [0x01, 0x08, 0x00, 0x54, 0x01, 0x01, 0x01, 0x01, 0x08, 0xAB]. DEBUG 2017-04-22 15:55:15,867 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x06] DEBUG 2017-04-22 15:55:15,868 (Z-Wave): RX_Serial_Port_RXTX : Data bytes read : [0x01, 0x04, 0x01, 0x54, 0x01, 0xAF] DEBUG 2017-04-22 15:55:15,870 (Z-Wave): RX_Frame_Layer : ACK -> Data frame [0x01, 0x08, 0x00, 0x54, 0x01, 0x01, 0x01, 0x01, 0x08, 0xAB] transmission OK. DEBUG 2017-04-22 15:55:15,871 (Z-Wave): RX_Session_Layer : ACK -> Z-Wave function 'ZW_SetSUCNodeID(NodeID=1, IsLocalNode=true, State=ENABLE_SUC, TxOption=LOW_POWER, Capability=ZW_SUC_FUNC_NODEID_SERVER)' has been successfully sent - waiting 5,000 [ms] for response frame. DEBUG 2017-04-22 15:55:15,874 (Z-Wave): RX_Frame_Layer : Data frame [0x01, 0x04, 0x01, 0x54, 0x01, 0xAF] has been received. DEBUG 2017-04-22 15:55:15,883 (Z-Wave): Controller : The Z-Wave controller has been successfully configured as SUC. DEBUG 2017-04-22 15:55:15,884 (Z-Wave): RX_Session_Layer : Response received [0x01, 0x04, 0x01, 0x54, 0x01, 0xAF] -> Z-Wave function 'ZW_SetSUCNodeID(NodeID=1, IsLocalNode=true, State=ENABLE_SUC, TxOption=LOW_POWER, Capability=ZW_SUC_FUNC_NODEID_SERVER)' successfully executed. DEBUG 2017-04-22 15:55:15,884 (Z-Wave): Command_Builder : Building Z-Wave command DEBUG 2017-04-22 15:55:15,886 (Z-Wave): Command_Builder : Z-Wave command: nodeId = '1', endPoint = '0' DEBUG 2017-04-22 15:55:15,887 (Z-Wave): Command_Builder : Z-Wave command: command = INCLUSION_MODE_STATUS DEBUG 2017-04-22 15:55:15,953 (Z-Wave): Command_Builder : Building Z-Wave command DEBUG 2017-04-22 15:55:15,954 (Z-Wave): Command_Builder : Z-Wave command: nodeId = '1', endPoint = '0' DEBUG 2017-04-22 15:55:15,955 (Z-Wave): Command_Builder : Z-Wave command: command = EXCLUSION_MODE_STATUS