-------------------------------------------------------------------------------------------------------------------------------------------------------- CONTACT CLOSURE ON MOVMENT -------------------------------------------------------------------------------------------------------------------------------------------------------- 2021-01-09 13:15:38.288 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 1 data: 02 2021-01-09 13:15:38.289 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.290 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 1 data: 02 2021-01-09 13:15:38.303 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 2 data: 02 50 2021-01-09 13:15:38.305 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:38.306 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.308 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 2 data: 02 50 2021-01-09 13:15:38.309 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 3 data: 02 50 55 2021-01-09 13:15:38.311 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:38.312 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.314 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 3 data: 02 50 55 2021-01-09 13:15:38.315 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 4 data: 02 50 55 87 2021-01-09 13:15:38.317 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:38.318 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.320 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 4 data: 02 50 55 87 2021-01-09 13:15:38.321 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 5 data: 02 50 55 87 FF 2021-01-09 13:15:38.323 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:38.324 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.326 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 5 data: 02 50 55 87 FF 2021-01-09 13:15:38.327 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 6 data: 02 50 55 87 FF 00 2021-01-09 13:15:38.329 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:38.330 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.332 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 6 data: 02 50 55 87 FF 00 2021-01-09 13:15:38.333 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 7 data: 02 50 55 87 FF 00 00 2021-01-09 13:15:38.335 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:38.336 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.338 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 7 data: 02 50 55 87 FF 00 00 2021-01-09 13:15:38.339 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 8 data: 02 50 55 87 FF 00 00 01 2021-01-09 13:15:38.341 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:38.342 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.344 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 8 data: 02 50 55 87 FF 00 00 01 2021-01-09 13:15:38.346 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 9 data: 02 50 55 87 FF 00 00 01 CF 2021-01-09 13:15:38.347 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:38.348 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:15:38.349 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.351 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 9 data: 02 50 55 87 FF 00 00 01 CF 2021-01-09 13:15:38.353 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 10 data: 02 50 55 87 FF 00 00 01 CF 11 2021-01-09 13:15:38.354 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:38.355 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:15:38.356 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.358 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 10 data: 02 50 55 87 FF 00 00 01 CF 11 2021-01-09 13:15:38.359 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 11 data: 02 50 55 87 FF 00 00 01 CF 11 01 2021-01-09 13:15:38.361 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:38.362 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:15:38.363 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.364 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 0 data: 2021-01-09 13:15:38.366 [DEBUG] [ding.insteon.internal.InsteonBinding] - got msg: IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x11|command2:0x01| 2021-01-09 13:15:38.367 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLightLevelAboveThreshold 2021-01-09 13:15:38.369 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF updating group 1 state to BCAST 2021-01-09 13:15:38.370 [DEBUG] [rnal.device.GroupMessageStateMachine] - 55.87.FF group 1 state: EXPECT_BCAST --BCAST--> EXPECT_CLEAN, publish: true 2021-01-09 13:15:38.372 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored because matches group: false matches filter: true 2021-01-09 13:15:38.373 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: MotionSensor2Data 2021-01-09 13:15:38.374 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for BCAST 2021-01-09 13:15:38.375 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored because matches group: false matches filter: true 2021-01-09 13:15:38.377 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensor2TamperSwitch 2021-01-09 13:15:38.378 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for BCAST 2021-01-09 13:15:38.379 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored because matches group: false matches filter: true 2021-01-09 13:15:38.381 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorContact 2021-01-09 13:15:38.382 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for BCAST 2021-01-09 13:15:38.384 [DEBUG] [on.internal.device.MessageDispatcher] - 55.87.FF:WirelessMotionSensorContact->OpenedSleepingContactHandler cmd1:0x11 group 1/1 2021-01-09 13:15:38.385 [DEBUG] [nsteon.internal.device.DeviceFeature] - 55.87.FF:WirelessMotionSensorContact publishing: OPEN 2021-01-09 13:15:38.386 [TRACE] [nternal.device.DeviceFeatureListener] - old state: OpenClosedType:CLOSED=?OPEN 2021-01-09 13:15:38.388 [WARN ] [rm.AbstractFileTransformationService] - Could not transform 'OPEN' with the file 'motionSensors.map' : Target value not found in map for 'OPEN' 2021-01-09 13:15:38.391 [TRACE] [nsteon.internal.device.InsteonDevice] - enqueing direct message with delay 0 2021-01-09 13:15:38.393 [TRACE] [.internal.device.RequestQueueManager] - scheduling request for device 55.87.FF in -2 msec 2021-01-09 13:15:38.395 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLowBattery 2021-01-09 13:15:38.397 [DEBUG] [nsteon.internal.device.InsteonDevice] - gave up waiting for query reply from device 55.87.FF 2021-01-09 13:15:38.398 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for BCAST 2021-01-09 13:15:38.399 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue': afterAccess = 6 ms timeAverage50 = 6 ms timeAverage100 = 6 ms timeAverage200 = 6 ms afterAccessMin = 2 ms afterAccessMax = 855 ms 1000Statements = 13563 sec statementCount = 526 2021-01-09 13:15:38.399 [DEBUG] [nsteon.internal.device.InsteonDevice] - qe taken off direct: WirelessMotionSensorContact(1:1:5) OUT:Cmd:0x62|toAddress:55.87.FF|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x03|userData1:0x00|userData2:0x00|userData3:0x00|userData4:0x00|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x00|userData14:0xCF| 2021-01-09 13:15:38.400 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored because matches group: false matches filter: true 2021-01-09 13:15:38.401 [TRACE] [nsteon.internal.device.DeviceFeature] - WirelessMotionSensorContact set query status to: QUERY_PENDING 2021-01-09 13:15:38.402 [TRACE] [on.internal.device.MessageDispatcher] - 55.87.FF:GenericLastTime->LastTimeHandler IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x11|command2:0x01| 2021-01-09 13:15:38.403 [TRACE] [binding.insteon.internal.driver.Port] - enqueued msg: OUT:Cmd:0x62|toAddress:55.87.FF|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x03|userData1:0x00|userData2:0x00|userData3:0x00|userData4:0x00|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x00|userData14:0xCF| 2021-01-09 13:15:38.403 [DEBUG] [binding.insteon.internal.driver.Port] - writing (500): OUT:Cmd:0x62|toAddress:55.87.FF|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x03|userData1:0x00|userData2:0x00|userData3:0x00|userData4:0x00|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x00|userData14:0xCF| 2021-01-09 13:15:38.404 [DEBUG] [nsteon.internal.device.InsteonDevice] - next request queue processed in 2000 msec, quiettime = 2000 2021-01-09 13:15:38.404 [TRACE] [binding.insteon.internal.driver.Port] - writer waiting for ack. 2021-01-09 13:15:38.405 [DEBUG] [nsteon.internal.device.DeviceFeature] - 55.87.FF:GenericLastTime publishing: 2021-01-09T13:15:38.404526-0500 2021-01-09 13:15:38.405 [TRACE] [.internal.device.RequestQueueManager] - device queue for 55.87.FF rescheduled in 2000 msec 2021-01-09 13:15:38.407 [TRACE] [.internal.device.RequestQueueManager] - request queue head: 55.87.FF must wait for 1990 msec 2021-01-09 13:15:38.408 [TRACE] [nternal.device.DeviceFeatureListener] - old state: DateTimeType:2021-01-09T13:14:56.489057-0500=?2021-01-09T13:15:38.404526-0500 2021-01-09 13:15:38.410 [TRACE] [binding.insteon.internal.driver.Port] - got unsolicited message 2021-01-09 13:15:38.415 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 1 data: 02 2021-01-09 13:15:38.418 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue': afterAccess = 5 ms timeAverage50 = 6 ms timeAverage100 = 6 ms timeAverage200 = 6 ms afterAccessMin = 2 ms afterAccessMax = 855 ms 1000Statements = 13563 sec statementCount = 527 2021-01-09 13:15:38.418 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.420 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 1 data: 02 2021-01-09 13:15:38.421 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 2 data: 02 62 2021-01-09 13:15:38.423 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: false 2021-01-09 13:15:38.424 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.425 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 2 data: 02 62 2021-01-09 13:15:38.427 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 3 data: 02 62 55 2021-01-09 13:15:38.428 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: false 2021-01-09 13:15:38.429 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.430 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 3 data: 02 62 55 2021-01-09 13:15:38.431 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 4 data: 02 62 55 87 2021-01-09 13:15:38.433 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: false 2021-01-09 13:15:38.434 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.435 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 4 data: 02 62 55 87 2021-01-09 13:15:38.436 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 5 data: 02 62 55 87 FF 2021-01-09 13:15:38.437 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: false 2021-01-09 13:15:38.438 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.440 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 5 data: 02 62 55 87 FF 2021-01-09 13:15:38.441 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 6 data: 02 62 55 87 FF 1F 2021-01-09 13:15:38.442 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:15:38.443 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:15:38.444 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.445 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 6 data: 02 62 55 87 FF 1F 2021-01-09 13:15:38.447 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 7 data: 02 62 55 87 FF 1F 2E 2021-01-09 13:15:38.448 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:15:38.449 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:15:38.450 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.451 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 7 data: 02 62 55 87 FF 1F 2E 2021-01-09 13:15:38.452 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 8 data: 02 62 55 87 FF 1F 2E 03 2021-01-09 13:15:38.454 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:15:38.454 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:15:38.455 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.457 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 8 data: 02 62 55 87 FF 1F 2E 03 2021-01-09 13:15:38.458 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 9 data: 02 62 55 87 FF 1F 2E 03 00 2021-01-09 13:15:38.459 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:15:38.460 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:15:38.461 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.462 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 9 data: 02 62 55 87 FF 1F 2E 03 00 2021-01-09 13:15:38.464 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 10 data: 02 62 55 87 FF 1F 2E 03 00 00 2021-01-09 13:15:38.465 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:15:38.466 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:15:38.467 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.468 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 10 data: 02 62 55 87 FF 1F 2E 03 00 00 2021-01-09 13:15:38.470 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 11 data: 02 62 55 87 FF 1F 2E 03 00 00 00 2021-01-09 13:15:38.470 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:15:38.472 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:15:38.472 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.474 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 11 data: 02 62 55 87 FF 1F 2E 03 00 00 00 2021-01-09 13:15:38.475 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 12 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 2021-01-09 13:15:38.476 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:15:38.477 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:15:38.478 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.479 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 12 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 2021-01-09 13:15:38.481 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 13 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 2021-01-09 13:15:38.482 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:15:38.483 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:15:38.484 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.485 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 13 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 2021-01-09 13:15:38.487 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 14 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 2021-01-09 13:15:38.488 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:15:38.489 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:15:38.490 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.491 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 14 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 2021-01-09 13:15:38.492 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 15 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 2021-01-09 13:15:38.493 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:15:38.494 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:15:38.495 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.496 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 15 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 2021-01-09 13:15:38.498 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 16 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 2021-01-09 13:15:38.499 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:15:38.500 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:15:38.501 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.502 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 16 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 2021-01-09 13:15:38.503 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 17 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 2021-01-09 13:15:38.504 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:15:38.505 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:15:38.506 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.507 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 17 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 2021-01-09 13:15:38.509 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 18 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 2021-01-09 13:15:38.510 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:15:38.511 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:15:38.511 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.513 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 18 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 2021-01-09 13:15:38.514 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 19 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 00 2021-01-09 13:15:38.515 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:15:38.516 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:15:38.517 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.518 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 19 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 00 2021-01-09 13:15:38.519 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 20 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 00 00 2021-01-09 13:15:38.520 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:15:38.521 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:15:38.522 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.523 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 20 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 00 00 2021-01-09 13:15:38.524 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 21 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 00 00 00 2021-01-09 13:15:38.525 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:15:38.526 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:15:38.527 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.528 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 21 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 00 00 00 2021-01-09 13:15:38.530 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 22 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 00 00 00 CF 2021-01-09 13:15:38.531 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:15:38.531 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:15:38.532 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.533 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 22 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 00 00 00 CF 2021-01-09 13:15:38.535 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 23 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 00 00 00 CF 06 2021-01-09 13:15:38.536 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:15:38.536 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:15:38.537 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:38.538 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 0 data: 2021-01-09 13:15:38.539 [TRACE] [binding.insteon.internal.driver.Port] - signaling receipt of ack: true 2021-01-09 13:15:38.540 [TRACE] [binding.insteon.internal.driver.Port] - writer got ack: true 2021-01-09 13:15:39.041 [TRACE] [binding.insteon.internal.driver.Port] - writer checking message queue 2021-01-09 13:15:40.398 [DEBUG] [.internal.device.RequestQueueManager] - device queue for 55.87.FF is empty! 2021-01-09 13:15:40.400 [TRACE] [.internal.device.RequestQueueManager] - waiting for request queues to fill 2021-01-09 13:15:42.526 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 1 data: 02 2021-01-09 13:15:42.528 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:42.529 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 1 data: 02 2021-01-09 13:15:42.531 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 2 data: 02 50 2021-01-09 13:15:42.532 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:42.533 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:42.535 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 2 data: 02 50 2021-01-09 13:15:42.537 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 3 data: 02 50 55 2021-01-09 13:15:42.538 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:42.539 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:42.541 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 3 data: 02 50 55 2021-01-09 13:15:42.542 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 4 data: 02 50 55 87 2021-01-09 13:15:42.544 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:42.545 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:42.547 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 4 data: 02 50 55 87 2021-01-09 13:15:42.549 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 5 data: 02 50 55 87 FF 2021-01-09 13:15:42.550 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:42.551 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:42.553 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 5 data: 02 50 55 87 FF 2021-01-09 13:15:42.555 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 6 data: 02 50 55 87 FF 53 2021-01-09 13:15:42.556 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:42.557 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:42.559 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 6 data: 02 50 55 87 FF 53 2021-01-09 13:15:42.561 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 7 data: 02 50 55 87 FF 53 BF 2021-01-09 13:15:42.562 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:42.563 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:42.565 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 7 data: 02 50 55 87 FF 53 BF 2021-01-09 13:15:42.567 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 8 data: 02 50 55 87 FF 53 BF 99 2021-01-09 13:15:42.568 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:42.570 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:42.571 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 8 data: 02 50 55 87 FF 53 BF 99 2021-01-09 13:15:42.573 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 9 data: 02 50 55 87 FF 53 BF 99 4F 2021-01-09 13:15:42.574 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:42.575 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:15:42.577 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:42.578 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 9 data: 02 50 55 87 FF 53 BF 99 4F 2021-01-09 13:15:42.580 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 10 data: 02 50 55 87 FF 53 BF 99 4F 11 2021-01-09 13:15:42.581 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:42.582 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:15:42.583 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:42.585 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 10 data: 02 50 55 87 FF 53 BF 99 4F 11 2021-01-09 13:15:42.587 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 11 data: 02 50 55 87 FF 53 BF 99 4F 11 01 2021-01-09 13:15:42.588 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:42.589 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:15:42.590 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:42.591 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 0 data: 2021-01-09 13:15:42.593 [DEBUG] [ding.insteon.internal.InsteonBinding] - got msg: IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:53.BF.99|messageFlags:0x4F=ALL_LINK_CLEANUP:3:3|command1:0x11|command2:0x01| 2021-01-09 13:15:42.594 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLightLevelAboveThreshold 2021-01-09 13:15:42.596 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF updating group 1 state to CLEAN 2021-01-09 13:15:42.597 [DEBUG] [rnal.device.GroupMessageStateMachine] - 55.87.FF group 1 state: EXPECT_CLEAN --CLEAN--> EXPECT_SUCCESS, publish: false 2021-01-09 13:15:42.598 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:15:42.600 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: MotionSensor2Data 2021-01-09 13:15:42.601 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for CLEAN 2021-01-09 13:15:42.602 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:15:42.604 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensor2TamperSwitch 2021-01-09 13:15:42.605 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for CLEAN 2021-01-09 13:15:42.606 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:15:42.607 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorContact 2021-01-09 13:15:42.609 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for CLEAN 2021-01-09 13:15:42.610 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: true matches filter: true 2021-01-09 13:15:42.611 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLowBattery 2021-01-09 13:15:42.613 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for CLEAN 2021-01-09 13:15:42.614 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:15:42.616 [TRACE] [on.internal.device.MessageDispatcher] - 55.87.FF:GenericLastTime->LastTimeHandler IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:53.BF.99|messageFlags:0x4F=ALL_LINK_CLEANUP:3:3|command1:0x11|command2:0x01| 2021-01-09 13:15:42.618 [DEBUG] [nsteon.internal.device.DeviceFeature] - 55.87.FF:GenericLastTime publishing: 2021-01-09T13:15:42.617701-0500 2021-01-09 13:15:42.619 [TRACE] [nternal.device.DeviceFeatureListener] - old state: DateTimeType:2021-01-09T13:15:38.404526-0500=?2021-01-09T13:15:42.617701-0500 2021-01-09 13:15:42.631 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue': afterAccess = 8 ms timeAverage50 = 6 ms timeAverage100 = 6 ms timeAverage200 = 6 ms afterAccessMin = 2 ms afterAccessMax = 855 ms 1000Statements = 13563 sec statementCount = 528 2021-01-09 13:15:42.990 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 1 data: 02 2021-01-09 13:15:42.991 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:42.992 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 1 data: 02 2021-01-09 13:15:42.994 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 2 data: 02 50 2021-01-09 13:15:42.995 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:42.996 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:42.998 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 2 data: 02 50 2021-01-09 13:15:42.999 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 3 data: 02 50 55 2021-01-09 13:15:43.001 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.002 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.003 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 3 data: 02 50 55 2021-01-09 13:15:43.005 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 4 data: 02 50 55 87 2021-01-09 13:15:43.006 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.007 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.008 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 4 data: 02 50 55 87 2021-01-09 13:15:43.010 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 5 data: 02 50 55 87 FF 2021-01-09 13:15:43.011 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.012 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.014 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 5 data: 02 50 55 87 FF 2021-01-09 13:15:43.015 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 6 data: 02 50 55 87 FF 11 2021-01-09 13:15:43.017 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.018 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.019 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 6 data: 02 50 55 87 FF 11 2021-01-09 13:15:43.021 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 7 data: 02 50 55 87 FF 11 01 2021-01-09 13:15:43.022 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.023 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.025 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 7 data: 02 50 55 87 FF 11 01 2021-01-09 13:15:43.026 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 8 data: 02 50 55 87 FF 11 01 01 2021-01-09 13:15:43.028 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.029 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.030 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 8 data: 02 50 55 87 FF 11 01 01 2021-01-09 13:15:43.032 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 9 data: 02 50 55 87 FF 11 01 01 CB 2021-01-09 13:15:43.034 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.035 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:15:43.036 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.037 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 9 data: 02 50 55 87 FF 11 01 01 CB 2021-01-09 13:15:43.039 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 10 data: 02 50 55 87 FF 11 01 01 CB 06 2021-01-09 13:15:43.040 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.042 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:15:43.043 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.044 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 10 data: 02 50 55 87 FF 11 01 01 CB 06 2021-01-09 13:15:43.046 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 11 data: 02 50 55 87 FF 11 01 01 CB 06 00 2021-01-09 13:15:43.047 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.048 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:15:43.049 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.050 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 0 data: 2021-01-09 13:15:43.052 [DEBUG] [ding.insteon.internal.InsteonBinding] - got msg: IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:11.01.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x06|command2:0x00| 2021-01-09 13:15:43.053 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLightLevelAboveThreshold 2021-01-09 13:15:43.055 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF updating group 1 state to SUCCESS 2021-01-09 13:15:43.056 [DEBUG] [rnal.device.GroupMessageStateMachine] - 55.87.FF group 1 state: EXPECT_SUCCESS --SUCCESS--> EXPECT_BCAST, publish: false 2021-01-09 13:15:43.057 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:15:43.058 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: MotionSensor2Data 2021-01-09 13:15:43.060 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for SUCCESS 2021-01-09 13:15:43.061 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:15:43.062 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensor2TamperSwitch 2021-01-09 13:15:43.064 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for SUCCESS 2021-01-09 13:15:43.065 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:15:43.066 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorContact 2021-01-09 13:15:43.068 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for SUCCESS 2021-01-09 13:15:43.069 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: true matches filter: true 2021-01-09 13:15:43.070 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLowBattery 2021-01-09 13:15:43.071 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for SUCCESS 2021-01-09 13:15:43.073 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:15:43.074 [TRACE] [on.internal.device.MessageDispatcher] - 55.87.FF:GenericLastTime->LastTimeHandler IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:11.01.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x06|command2:0x00| 2021-01-09 13:15:43.076 [DEBUG] [nsteon.internal.device.DeviceFeature] - 55.87.FF:GenericLastTime publishing: 2021-01-09T13:15:43.075725-0500 2021-01-09 13:15:43.077 [TRACE] [nternal.device.DeviceFeatureListener] - old state: DateTimeType:2021-01-09T13:15:42.617701-0500=?2021-01-09T13:15:43.075725-0500 2021-01-09 13:15:43.087 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue': afterAccess = 5 ms timeAverage50 = 6 ms timeAverage100 = 6 ms timeAverage200 = 6 ms afterAccessMin = 2 ms afterAccessMax = 855 ms 1000Statements = 13563 sec statementCount = 529 2021-01-09 13:15:43.469 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 1 data: 02 2021-01-09 13:15:43.470 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.472 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 1 data: 02 2021-01-09 13:15:43.473 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 2 data: 02 50 2021-01-09 13:15:43.474 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.476 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.477 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 2 data: 02 50 2021-01-09 13:15:43.479 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 3 data: 02 50 55 2021-01-09 13:15:43.480 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.481 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.483 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 3 data: 02 50 55 2021-01-09 13:15:43.484 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 4 data: 02 50 55 87 2021-01-09 13:15:43.485 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.487 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.488 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 4 data: 02 50 55 87 2021-01-09 13:15:43.490 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 5 data: 02 50 55 87 FF 2021-01-09 13:15:43.491 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.492 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.494 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 5 data: 02 50 55 87 FF 2021-01-09 13:15:43.495 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 6 data: 02 50 55 87 FF 11 2021-01-09 13:15:43.496 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.498 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.499 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 6 data: 02 50 55 87 FF 11 2021-01-09 13:15:43.501 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 7 data: 02 50 55 87 FF 11 01 2021-01-09 13:15:43.502 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.503 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.505 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 7 data: 02 50 55 87 FF 11 01 2021-01-09 13:15:43.507 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 8 data: 02 50 55 87 FF 11 01 01 2021-01-09 13:15:43.508 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.509 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.511 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 8 data: 02 50 55 87 FF 11 01 01 2021-01-09 13:15:43.512 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 9 data: 02 50 55 87 FF 11 01 01 CB 2021-01-09 13:15:43.513 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.515 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:15:43.516 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.517 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 9 data: 02 50 55 87 FF 11 01 01 CB 2021-01-09 13:15:43.519 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 10 data: 02 50 55 87 FF 11 01 01 CB 06 2021-01-09 13:15:43.520 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.521 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:15:43.522 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.523 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 10 data: 02 50 55 87 FF 11 01 01 CB 06 2021-01-09 13:15:43.525 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 11 data: 02 50 55 87 FF 11 01 01 CB 06 00 2021-01-09 13:15:43.526 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:15:43.527 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:15:43.528 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:15:43.530 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 0 data: 2021-01-09 13:15:43.531 [DEBUG] [ding.insteon.internal.InsteonBinding] - got msg: IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:11.01.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x06|command2:0x00| 2021-01-09 13:15:43.532 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLightLevelAboveThreshold 2021-01-09 13:15:43.534 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF updating group 1 state to SUCCESS 2021-01-09 13:15:43.535 [DEBUG] [rnal.device.GroupMessageStateMachine] - 55.87.FF group 1 state: EXPECT_BCAST --SUCCESS--> EXPECT_BCAST, publish: false 2021-01-09 13:15:43.536 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:15:43.537 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: MotionSensor2Data 2021-01-09 13:15:43.539 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for SUCCESS 2021-01-09 13:15:43.540 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:15:43.541 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensor2TamperSwitch 2021-01-09 13:15:43.542 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for SUCCESS 2021-01-09 13:15:43.543 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:15:43.544 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorContact 2021-01-09 13:15:43.546 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for SUCCESS 2021-01-09 13:15:43.547 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: true matches filter: true 2021-01-09 13:15:43.548 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLowBattery 2021-01-09 13:15:43.549 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for SUCCESS 2021-01-09 13:15:43.551 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:15:43.552 [TRACE] [on.internal.device.MessageDispatcher] - 55.87.FF:GenericLastTime->LastTimeHandler IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:11.01.01|messageFlags:0xCB=ALL_LINK_BROADCAST:3:2|command1:0x06|command2:0x00| 2021-01-09 13:15:43.554 [DEBUG] [nsteon.internal.device.DeviceFeature] - 55.87.FF:GenericLastTime publishing: 2021-01-09T13:15:43.553781-0500 2021-01-09 13:15:43.555 [TRACE] [nternal.device.DeviceFeatureListener] - old state: DateTimeType:2021-01-09T13:15:43.075725-0500=?2021-01-09T13:15:43.553781-0500 2021-01-09 13:15:43.563 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue': afterAccess = 4 ms timeAverage50 = 6 ms timeAverage100 = 6 ms timeAverage200 = 6 ms afterAccessMin = 2 ms afterAccessMax = 855 ms 1000Statements = 13563 sec statementCount = 530 -------------------------------------------------------------------------------------------------------------------------------------------------------- CONTACT OPEN AFTER TIMEOUT -------------------------------------------------------------------------------------------------------------------------------------------------------- 2021-01-09 13:16:07.199 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 1 data: 02 2021-01-09 13:16:07.200 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.201 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 1 data: 02 2021-01-09 13:16:07.214 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 2 data: 02 50 2021-01-09 13:16:07.215 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:07.216 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.218 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 2 data: 02 50 2021-01-09 13:16:07.219 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 3 data: 02 50 55 2021-01-09 13:16:07.221 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:07.222 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.223 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 3 data: 02 50 55 2021-01-09 13:16:07.225 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 4 data: 02 50 55 87 2021-01-09 13:16:07.226 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:07.227 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.229 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 4 data: 02 50 55 87 2021-01-09 13:16:07.230 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 5 data: 02 50 55 87 FF 2021-01-09 13:16:07.232 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:07.233 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.234 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 5 data: 02 50 55 87 FF 2021-01-09 13:16:07.236 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 6 data: 02 50 55 87 FF 00 2021-01-09 13:16:07.237 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:07.238 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.240 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 6 data: 02 50 55 87 FF 00 2021-01-09 13:16:07.241 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 7 data: 02 50 55 87 FF 00 00 2021-01-09 13:16:07.243 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:07.244 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.245 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 7 data: 02 50 55 87 FF 00 00 2021-01-09 13:16:07.247 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 8 data: 02 50 55 87 FF 00 00 01 2021-01-09 13:16:07.248 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:07.250 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.251 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 8 data: 02 50 55 87 FF 00 00 01 2021-01-09 13:16:07.253 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 9 data: 02 50 55 87 FF 00 00 01 CF 2021-01-09 13:16:07.254 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:07.255 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:16:07.256 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.258 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 9 data: 02 50 55 87 FF 00 00 01 CF 2021-01-09 13:16:07.260 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 10 data: 02 50 55 87 FF 00 00 01 CF 13 2021-01-09 13:16:07.265 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:07.267 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:16:07.269 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.270 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 10 data: 02 50 55 87 FF 00 00 01 CF 13 2021-01-09 13:16:07.272 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 11 data: 02 50 55 87 FF 00 00 01 CF 13 01 2021-01-09 13:16:07.274 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:07.275 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:16:07.276 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.277 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 0 data: 2021-01-09 13:16:07.279 [DEBUG] [ding.insteon.internal.InsteonBinding] - got msg: IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x13|command2:0x01| 2021-01-09 13:16:07.280 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLightLevelAboveThreshold 2021-01-09 13:16:07.282 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF updating group 1 state to BCAST 2021-01-09 13:16:07.283 [DEBUG] [rnal.device.GroupMessageStateMachine] - 55.87.FF group 1 state: EXPECT_BCAST --BCAST--> EXPECT_CLEAN, publish: true 2021-01-09 13:16:07.285 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored because matches group: false matches filter: true 2021-01-09 13:16:07.286 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: MotionSensor2Data 2021-01-09 13:16:07.288 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for BCAST 2021-01-09 13:16:07.289 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored because matches group: false matches filter: true 2021-01-09 13:16:07.290 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensor2TamperSwitch 2021-01-09 13:16:07.292 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for BCAST 2021-01-09 13:16:07.293 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored because matches group: false matches filter: true 2021-01-09 13:16:07.294 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorContact 2021-01-09 13:16:07.296 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for BCAST 2021-01-09 13:16:07.297 [DEBUG] [on.internal.device.MessageDispatcher] - 55.87.FF:WirelessMotionSensorContact->ClosedSleepingContactHandler cmd1:0x13 group 1/1 2021-01-09 13:16:07.299 [DEBUG] [nsteon.internal.device.DeviceFeature] - 55.87.FF:WirelessMotionSensorContact publishing: CLOSED 2021-01-09 13:16:07.300 [TRACE] [nternal.device.DeviceFeatureListener] - old state: OpenClosedType:OPEN=?CLOSED 2021-01-09 13:16:07.302 [WARN ] [rm.AbstractFileTransformationService] - Could not transform 'CLOSED' with the file 'motionSensors.map' : Target value not found in map for 'CLOSED' 2021-01-09 13:16:07.304 [TRACE] [nsteon.internal.device.InsteonDevice] - enqueing direct message with delay 0 2021-01-09 13:16:07.313 [TRACE] [.internal.device.RequestQueueManager] - scheduling request for device 55.87.FF in -8 msec 2021-01-09 13:16:07.313 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue': afterAccess = 7 ms timeAverage50 = 6 ms timeAverage100 = 6 ms timeAverage200 = 6 ms afterAccessMin = 2 ms afterAccessMax = 855 ms 1000Statements = 13563 sec statementCount = 531 2021-01-09 13:16:07.314 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLowBattery 2021-01-09 13:16:07.314 [DEBUG] [nsteon.internal.device.InsteonDevice] - gave up waiting for query reply from device 55.87.FF 2021-01-09 13:16:07.315 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for BCAST 2021-01-09 13:16:07.316 [DEBUG] [nsteon.internal.device.InsteonDevice] - qe taken off direct: WirelessMotionSensorContact(1:1:5) OUT:Cmd:0x62|toAddress:55.87.FF|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x03|userData1:0x00|userData2:0x00|userData3:0x00|userData4:0x00|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x00|userData14:0xCF| 2021-01-09 13:16:07.316 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored because matches group: false matches filter: true 2021-01-09 13:16:07.316 [TRACE] [nsteon.internal.device.DeviceFeature] - WirelessMotionSensorContact set query status to: QUERY_PENDING 2021-01-09 13:16:07.318 [TRACE] [on.internal.device.MessageDispatcher] - 55.87.FF:GenericLastTime->LastTimeHandler IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x13|command2:0x01| 2021-01-09 13:16:07.318 [DEBUG] [binding.insteon.internal.driver.Port] - writing (500): OUT:Cmd:0x62|toAddress:55.87.FF|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x03|userData1:0x00|userData2:0x00|userData3:0x00|userData4:0x00|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x00|userData14:0xCF| 2021-01-09 13:16:07.318 [TRACE] [binding.insteon.internal.driver.Port] - enqueued msg: OUT:Cmd:0x62|toAddress:55.87.FF|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x03|userData1:0x00|userData2:0x00|userData3:0x00|userData4:0x00|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x00|userData14:0xCF| 2021-01-09 13:16:07.320 [DEBUG] [nsteon.internal.device.DeviceFeature] - 55.87.FF:GenericLastTime publishing: 2021-01-09T13:16:07.320060-0500 2021-01-09 13:16:07.320 [TRACE] [binding.insteon.internal.driver.Port] - writer waiting for ack. 2021-01-09 13:16:07.322 [TRACE] [nternal.device.DeviceFeatureListener] - old state: DateTimeType:2021-01-09T13:15:43.553781-0500=?2021-01-09T13:16:07.320060-0500 2021-01-09 13:16:07.322 [DEBUG] [nsteon.internal.device.InsteonDevice] - next request queue processed in 2000 msec, quiettime = 2000 2021-01-09 13:16:07.323 [TRACE] [.internal.device.RequestQueueManager] - device queue for 55.87.FF rescheduled in 2000 msec 2021-01-09 13:16:07.324 [TRACE] [.internal.device.RequestQueueManager] - request queue head: 55.87.FF must wait for 1990 msec 2021-01-09 13:16:07.324 [TRACE] [binding.insteon.internal.driver.Port] - got unsolicited message 2021-01-09 13:16:07.333 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue': afterAccess = 6 ms timeAverage50 = 6 ms timeAverage100 = 6 ms timeAverage200 = 6 ms afterAccessMin = 2 ms afterAccessMax = 855 ms 1000Statements = 13563 sec statementCount = 532 2021-01-09 13:16:07.342 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 1 data: 02 2021-01-09 13:16:07.344 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.345 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 1 data: 02 2021-01-09 13:16:07.346 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 2 data: 02 62 2021-01-09 13:16:07.347 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: false 2021-01-09 13:16:07.348 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.349 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 2 data: 02 62 2021-01-09 13:16:07.351 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 3 data: 02 62 55 2021-01-09 13:16:07.352 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: false 2021-01-09 13:16:07.353 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.354 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 3 data: 02 62 55 2021-01-09 13:16:07.355 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 4 data: 02 62 55 87 2021-01-09 13:16:07.356 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: false 2021-01-09 13:16:07.357 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.358 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 4 data: 02 62 55 87 2021-01-09 13:16:07.360 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 5 data: 02 62 55 87 FF 2021-01-09 13:16:07.361 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: false 2021-01-09 13:16:07.362 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.363 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 5 data: 02 62 55 87 FF 2021-01-09 13:16:07.364 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 6 data: 02 62 55 87 FF 1F 2021-01-09 13:16:07.365 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:16:07.366 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:16:07.367 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.369 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 6 data: 02 62 55 87 FF 1F 2021-01-09 13:16:07.370 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 7 data: 02 62 55 87 FF 1F 2E 2021-01-09 13:16:07.371 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:16:07.372 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:16:07.373 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.374 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 7 data: 02 62 55 87 FF 1F 2E 2021-01-09 13:16:07.376 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 8 data: 02 62 55 87 FF 1F 2E 03 2021-01-09 13:16:07.377 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:16:07.378 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:16:07.378 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.380 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 8 data: 02 62 55 87 FF 1F 2E 03 2021-01-09 13:16:07.381 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 9 data: 02 62 55 87 FF 1F 2E 03 00 2021-01-09 13:16:07.382 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:16:07.383 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:16:07.384 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.385 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 9 data: 02 62 55 87 FF 1F 2E 03 00 2021-01-09 13:16:07.386 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 10 data: 02 62 55 87 FF 1F 2E 03 00 00 2021-01-09 13:16:07.387 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:16:07.388 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:16:07.389 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.391 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 10 data: 02 62 55 87 FF 1F 2E 03 00 00 2021-01-09 13:16:07.392 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 11 data: 02 62 55 87 FF 1F 2E 03 00 00 00 2021-01-09 13:16:07.393 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:16:07.394 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:16:07.395 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.396 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 11 data: 02 62 55 87 FF 1F 2E 03 00 00 00 2021-01-09 13:16:07.397 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 12 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 2021-01-09 13:16:07.398 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:16:07.399 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:16:07.400 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.401 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 12 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 2021-01-09 13:16:07.403 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 13 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 2021-01-09 13:16:07.404 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:16:07.405 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:16:07.406 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.407 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 13 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 2021-01-09 13:16:07.408 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 14 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 2021-01-09 13:16:07.409 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:16:07.410 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:16:07.411 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.412 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 14 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 2021-01-09 13:16:07.414 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 15 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 2021-01-09 13:16:07.415 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:16:07.415 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:16:07.416 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.417 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 15 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 2021-01-09 13:16:07.419 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 16 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 2021-01-09 13:16:07.420 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:16:07.421 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:16:07.422 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.423 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 16 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 2021-01-09 13:16:07.424 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 17 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 2021-01-09 13:16:07.425 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:16:07.426 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:16:07.427 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.428 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 17 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 2021-01-09 13:16:07.430 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 18 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 2021-01-09 13:16:07.431 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:16:07.432 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:16:07.433 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.434 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 18 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 2021-01-09 13:16:07.435 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 19 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 00 2021-01-09 13:16:07.436 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:16:07.437 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:16:07.438 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.439 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 19 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 00 2021-01-09 13:16:07.440 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 20 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 00 00 2021-01-09 13:16:07.441 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:16:07.442 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:16:07.443 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.444 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 20 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 00 00 2021-01-09 13:16:07.446 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 21 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 00 00 00 2021-01-09 13:16:07.446 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:16:07.447 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:16:07.448 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.449 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 21 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 00 00 00 2021-01-09 13:16:07.451 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 22 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 00 00 00 CF 2021-01-09 13:16:07.452 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:16:07.453 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:16:07.453 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.455 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 22 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 00 00 00 CF 2021-01-09 13:16:07.456 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 23 data: 02 62 55 87 FF 1F 2E 03 00 00 00 00 00 00 00 00 00 00 00 00 00 CF 06 2021-01-09 13:16:07.457 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-09 13:16:07.458 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-09 13:16:07.459 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:07.459 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 0 data: 2021-01-09 13:16:07.460 [TRACE] [binding.insteon.internal.driver.Port] - signaling receipt of ack: true 2021-01-09 13:16:07.461 [TRACE] [binding.insteon.internal.driver.Port] - writer got ack: true 2021-01-09 13:16:07.962 [TRACE] [binding.insteon.internal.driver.Port] - writer checking message queue 2021-01-09 13:16:09.316 [DEBUG] [.internal.device.RequestQueueManager] - device queue for 55.87.FF is empty! 2021-01-09 13:16:09.317 [TRACE] [.internal.device.RequestQueueManager] - waiting for request queues to fill 2021-01-09 13:16:11.579 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 1 data: 02 2021-01-09 13:16:11.581 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:11.583 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 1 data: 02 2021-01-09 13:16:11.584 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 2 data: 02 50 2021-01-09 13:16:11.585 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:11.586 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:11.588 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 2 data: 02 50 2021-01-09 13:16:11.589 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 3 data: 02 50 55 2021-01-09 13:16:11.591 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:11.592 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:11.593 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 3 data: 02 50 55 2021-01-09 13:16:11.595 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 4 data: 02 50 55 87 2021-01-09 13:16:11.596 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:11.598 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:11.599 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 4 data: 02 50 55 87 2021-01-09 13:16:11.601 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 5 data: 02 50 55 87 FF 2021-01-09 13:16:11.602 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:11.603 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:11.605 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 5 data: 02 50 55 87 FF 2021-01-09 13:16:11.606 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 6 data: 02 50 55 87 FF 53 2021-01-09 13:16:11.608 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:11.609 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:11.611 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 6 data: 02 50 55 87 FF 53 2021-01-09 13:16:11.612 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 7 data: 02 50 55 87 FF 53 BF 2021-01-09 13:16:11.614 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:11.615 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:11.616 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 7 data: 02 50 55 87 FF 53 BF 2021-01-09 13:16:11.618 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 8 data: 02 50 55 87 FF 53 BF 99 2021-01-09 13:16:11.620 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:11.621 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:11.623 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 8 data: 02 50 55 87 FF 53 BF 99 2021-01-09 13:16:11.624 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 9 data: 02 50 55 87 FF 53 BF 99 4F 2021-01-09 13:16:11.625 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:11.626 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:16:11.628 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:11.629 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 9 data: 02 50 55 87 FF 53 BF 99 4F 2021-01-09 13:16:11.631 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 10 data: 02 50 55 87 FF 53 BF 99 4F 13 2021-01-09 13:16:11.632 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:11.633 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:16:11.634 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:11.635 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 10 data: 02 50 55 87 FF 53 BF 99 4F 13 2021-01-09 13:16:11.637 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 11 data: 02 50 55 87 FF 53 BF 99 4F 13 01 2021-01-09 13:16:11.638 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:11.639 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:16:11.640 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:11.641 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 0 data: 2021-01-09 13:16:11.643 [DEBUG] [ding.insteon.internal.InsteonBinding] - got msg: IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:53.BF.99|messageFlags:0x4F=ALL_LINK_CLEANUP:3:3|command1:0x13|command2:0x01| 2021-01-09 13:16:11.644 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLightLevelAboveThreshold 2021-01-09 13:16:11.646 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF updating group 1 state to CLEAN 2021-01-09 13:16:11.647 [DEBUG] [rnal.device.GroupMessageStateMachine] - 55.87.FF group 1 state: EXPECT_CLEAN --CLEAN--> EXPECT_SUCCESS, publish: false 2021-01-09 13:16:11.648 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:16:11.649 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: MotionSensor2Data 2021-01-09 13:16:11.651 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for CLEAN 2021-01-09 13:16:11.652 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:16:11.653 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensor2TamperSwitch 2021-01-09 13:16:11.654 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for CLEAN 2021-01-09 13:16:11.655 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:16:11.657 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorContact 2021-01-09 13:16:11.658 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for CLEAN 2021-01-09 13:16:11.660 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: true matches filter: true 2021-01-09 13:16:11.662 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLowBattery 2021-01-09 13:16:11.663 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for CLEAN 2021-01-09 13:16:11.664 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:16:11.666 [TRACE] [on.internal.device.MessageDispatcher] - 55.87.FF:GenericLastTime->LastTimeHandler IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:53.BF.99|messageFlags:0x4F=ALL_LINK_CLEANUP:3:3|command1:0x13|command2:0x01| 2021-01-09 13:16:11.667 [DEBUG] [nsteon.internal.device.DeviceFeature] - 55.87.FF:GenericLastTime publishing: 2021-01-09T13:16:11.667306-0500 2021-01-09 13:16:11.668 [TRACE] [nternal.device.DeviceFeatureListener] - old state: DateTimeType:2021-01-09T13:16:07.320060-0500=?2021-01-09T13:16:11.667306-0500 2021-01-09 13:16:11.689 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue': afterAccess = 15 ms timeAverage50 = 6 ms timeAverage100 = 6 ms timeAverage200 = 6 ms afterAccessMin = 2 ms afterAccessMax = 855 ms 1000Statements = 13563 sec statementCount = 533 2021-01-09 13:16:11.995 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 1 data: 02 2021-01-09 13:16:11.997 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:11.998 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 1 data: 02 2021-01-09 13:16:12.000 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 2 data: 02 50 2021-01-09 13:16:12.001 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.003 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.004 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 2 data: 02 50 2021-01-09 13:16:12.006 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 3 data: 02 50 55 2021-01-09 13:16:12.007 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.008 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.010 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 3 data: 02 50 55 2021-01-09 13:16:12.011 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 4 data: 02 50 55 87 2021-01-09 13:16:12.013 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.014 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.016 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 4 data: 02 50 55 87 2021-01-09 13:16:12.017 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 5 data: 02 50 55 87 FF 2021-01-09 13:16:12.019 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.020 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.022 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 5 data: 02 50 55 87 FF 2021-01-09 13:16:12.023 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 6 data: 02 50 55 87 FF 13 2021-01-09 13:16:12.025 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.026 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.027 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 6 data: 02 50 55 87 FF 13 2021-01-09 13:16:12.029 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 7 data: 02 50 55 87 FF 13 01 2021-01-09 13:16:12.031 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.032 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.034 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 7 data: 02 50 55 87 FF 13 01 2021-01-09 13:16:12.035 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 8 data: 02 50 55 87 FF 13 01 01 2021-01-09 13:16:12.037 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.038 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.039 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 8 data: 02 50 55 87 FF 13 01 01 2021-01-09 13:16:12.041 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 9 data: 02 50 55 87 FF 13 01 01 CF 2021-01-09 13:16:12.042 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.044 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:16:12.045 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.046 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 9 data: 02 50 55 87 FF 13 01 01 CF 2021-01-09 13:16:12.048 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 10 data: 02 50 55 87 FF 13 01 01 CF 06 2021-01-09 13:16:12.049 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.050 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:16:12.051 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.053 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 10 data: 02 50 55 87 FF 13 01 01 CF 06 2021-01-09 13:16:12.054 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 11 data: 02 50 55 87 FF 13 01 01 CF 06 00 2021-01-09 13:16:12.056 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.057 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:16:12.058 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.059 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 0 data: 2021-01-09 13:16:12.061 [DEBUG] [ding.insteon.internal.InsteonBinding] - got msg: IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:13.01.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x06|command2:0x00| 2021-01-09 13:16:12.062 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLightLevelAboveThreshold 2021-01-09 13:16:12.063 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF updating group 1 state to SUCCESS 2021-01-09 13:16:12.065 [DEBUG] [rnal.device.GroupMessageStateMachine] - 55.87.FF group 1 state: EXPECT_SUCCESS --SUCCESS--> EXPECT_BCAST, publish: false 2021-01-09 13:16:12.066 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:16:12.067 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: MotionSensor2Data 2021-01-09 13:16:12.069 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for SUCCESS 2021-01-09 13:16:12.070 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:16:12.071 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensor2TamperSwitch 2021-01-09 13:16:12.072 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for SUCCESS 2021-01-09 13:16:12.074 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:16:12.075 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorContact 2021-01-09 13:16:12.076 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for SUCCESS 2021-01-09 13:16:12.078 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: true matches filter: true 2021-01-09 13:16:12.079 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLowBattery 2021-01-09 13:16:12.080 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for SUCCESS 2021-01-09 13:16:12.081 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:16:12.083 [TRACE] [on.internal.device.MessageDispatcher] - 55.87.FF:GenericLastTime->LastTimeHandler IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:13.01.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x06|command2:0x00| 2021-01-09 13:16:12.085 [DEBUG] [nsteon.internal.device.DeviceFeature] - 55.87.FF:GenericLastTime publishing: 2021-01-09T13:16:12.084752-0500 2021-01-09 13:16:12.086 [TRACE] [nternal.device.DeviceFeatureListener] - old state: DateTimeType:2021-01-09T13:16:11.667306-0500=?2021-01-09T13:16:12.084752-0500 2021-01-09 13:16:12.096 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue': afterAccess = 6 ms timeAverage50 = 6 ms timeAverage100 = 6 ms timeAverage200 = 6 ms afterAccessMin = 2 ms afterAccessMax = 855 ms 1000Statements = 13563 sec statementCount = 534 2021-01-09 13:16:12.474 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 1 data: 02 2021-01-09 13:16:12.477 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.479 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 1 data: 02 2021-01-09 13:16:12.481 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 2 data: 02 50 2021-01-09 13:16:12.482 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.483 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.485 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 2 data: 02 50 2021-01-09 13:16:12.487 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 3 data: 02 50 55 2021-01-09 13:16:12.488 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.489 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.491 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 3 data: 02 50 55 2021-01-09 13:16:12.492 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 4 data: 02 50 55 87 2021-01-09 13:16:12.494 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.495 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.496 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 4 data: 02 50 55 87 2021-01-09 13:16:12.498 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 5 data: 02 50 55 87 FF 2021-01-09 13:16:12.500 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.501 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.502 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 5 data: 02 50 55 87 FF 2021-01-09 13:16:12.504 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 6 data: 02 50 55 87 FF 13 2021-01-09 13:16:12.506 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.507 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.508 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 6 data: 02 50 55 87 FF 13 2021-01-09 13:16:12.510 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 7 data: 02 50 55 87 FF 13 01 2021-01-09 13:16:12.512 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.513 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.515 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 7 data: 02 50 55 87 FF 13 01 2021-01-09 13:16:12.516 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 8 data: 02 50 55 87 FF 13 01 01 2021-01-09 13:16:12.518 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.519 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.520 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 8 data: 02 50 55 87 FF 13 01 01 2021-01-09 13:16:12.522 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 9 data: 02 50 55 87 FF 13 01 01 CF 2021-01-09 13:16:12.523 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.524 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:16:12.525 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.527 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 9 data: 02 50 55 87 FF 13 01 01 CF 2021-01-09 13:16:12.529 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 10 data: 02 50 55 87 FF 13 01 01 CF 06 2021-01-09 13:16:12.530 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.531 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:16:12.532 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.534 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 10 data: 02 50 55 87 FF 13 01 01 CF 06 2021-01-09 13:16:12.535 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 11 data: 02 50 55 87 FF 13 01 01 CF 06 00 2021-01-09 13:16:12.536 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-09 13:16:12.538 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-09 13:16:12.539 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-09 13:16:12.540 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 0 data: 2021-01-09 13:16:12.541 [DEBUG] [ding.insteon.internal.InsteonBinding] - got msg: IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:13.01.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x06|command2:0x00| 2021-01-09 13:16:12.543 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLightLevelAboveThreshold 2021-01-09 13:16:12.544 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF updating group 1 state to SUCCESS 2021-01-09 13:16:12.546 [DEBUG] [rnal.device.GroupMessageStateMachine] - 55.87.FF group 1 state: EXPECT_BCAST --SUCCESS--> EXPECT_BCAST, publish: false 2021-01-09 13:16:12.547 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:16:12.548 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: MotionSensor2Data 2021-01-09 13:16:12.549 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for SUCCESS 2021-01-09 13:16:12.551 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:16:12.552 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensor2TamperSwitch 2021-01-09 13:16:12.553 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for SUCCESS 2021-01-09 13:16:12.555 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:16:12.556 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorContact 2021-01-09 13:16:12.557 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for SUCCESS 2021-01-09 13:16:12.558 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: true matches filter: true 2021-01-09 13:16:12.560 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLowBattery 2021-01-09 13:16:12.561 [TRACE] [nsteon.internal.device.InsteonDevice] - 55.87.FF using previous group 1 state for SUCCESS 2021-01-09 13:16:12.562 [DEBUG] [on.internal.device.MessageDispatcher] - message ignored as duplicate. Matches group: false matches filter: true 2021-01-09 13:16:12.564 [TRACE] [on.internal.device.MessageDispatcher] - 55.87.FF:GenericLastTime->LastTimeHandler IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:13.01.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x06|command2:0x00| 2021-01-09 13:16:12.566 [DEBUG] [nsteon.internal.device.DeviceFeature] - 55.87.FF:GenericLastTime publishing: 2021-01-09T13:16:12.565574-0500 2021-01-09 13:16:12.567 [TRACE] [nternal.device.DeviceFeatureListener] - old state: DateTimeType:2021-01-09T13:16:12.084752-0500=?2021-01-09T13:16:12.565574-0500 2021-01-09 13:16:12.575 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue': afterAccess = 4 ms timeAverage50 = 6 ms timeAverage100 = 6 ms timeAverage200 = 6 ms afterAccessMin = 2 ms afterAccessMax = 855 ms 1000Statements = 13563 sec statementCount = 535