2021-01-24 11:48:49.643 [TRACE] [nsteon.internal.device.InsteonDevice] - enqueing direct message with delay 0 2021-01-24 11:48:49.646 [TRACE] [.internal.device.RequestQueueManager] - scheduling request for device 55.87.FF in -3 msec 2021-01-24 11:48:49.655 [DEBUG] [nsteon.internal.device.InsteonDevice] - qe taken off direct: console(0:0:0) OUT:Cmd:0x62|toAddress:55.87.FF|messageFlags:0x15=DIRECT:1:1|command1:0x20|command2:0x0A|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:0xD6| 2021-01-24 11:48:49.657 [TRACE] [nsteon.internal.device.DeviceFeature] - console set query status to: QUERY_PENDING 2021-01-24 11:48:49.663 [TRACE] [binding.insteon.internal.driver.Port] - enqueued msg: OUT:Cmd:0x62|toAddress:55.87.FF|messageFlags:0x15=DIRECT:1:1|command1:0x20|command2:0x0A|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:0xD6| 2021-01-24 11:48:49.664 [DEBUG] [binding.insteon.internal.driver.Port] - writing (500): OUT:Cmd:0x62|toAddress:55.87.FF|messageFlags:0x15=DIRECT:1:1|command1:0x20|command2:0x0A|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:0xD6| 2021-01-24 11:48:49.667 [TRACE] [binding.insteon.internal.driver.Port] - writer waiting for ack. 2021-01-24 11:48:49.673 [DEBUG] [nsteon.internal.device.InsteonDevice] - next request queue processed in 2000 msec, quiettime = 2000 2021-01-24 11:48:49.675 [TRACE] [.internal.device.RequestQueueManager] - device queue for 55.87.FF rescheduled in 2000 msec 2021-01-24 11:48:49.678 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 1 data: 02 2021-01-24 11:48:49.679 [TRACE] [.internal.device.RequestQueueManager] - request queue head: 55.87.FF must wait for 1972 msec 2021-01-24 11:48:49.681 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.684 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 1 data: 02 2021-01-24 11:48:49.686 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 2 data: 02 62 2021-01-24 11:48:49.689 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: false 2021-01-24 11:48:49.691 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.693 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 2 data: 02 62 2021-01-24 11:48:49.696 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 3 data: 02 62 55 2021-01-24 11:48:49.697 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: false 2021-01-24 11:48:49.699 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.702 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 3 data: 02 62 55 2021-01-24 11:48:49.704 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 4 data: 02 62 55 87 2021-01-24 11:48:49.706 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: false 2021-01-24 11:48:49.708 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.711 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 4 data: 02 62 55 87 2021-01-24 11:48:49.713 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 5 data: 02 62 55 87 FF 2021-01-24 11:48:49.715 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: false 2021-01-24 11:48:49.717 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.719 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 5 data: 02 62 55 87 FF 2021-01-24 11:48:49.722 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 6 data: 02 62 55 87 FF 15 2021-01-24 11:48:49.724 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:49.726 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:49.727 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.730 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 6 data: 02 62 55 87 FF 15 2021-01-24 11:48:49.732 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 7 data: 02 62 55 87 FF 15 20 2021-01-24 11:48:49.734 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:49.736 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:49.737 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.739 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 7 data: 02 62 55 87 FF 15 20 2021-01-24 11:48:49.742 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 8 data: 02 62 55 87 FF 15 20 0A 2021-01-24 11:48:49.744 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:49.745 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:49.747 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.749 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 8 data: 02 62 55 87 FF 15 20 0A 2021-01-24 11:48:49.752 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 9 data: 02 62 55 87 FF 15 20 0A 00 2021-01-24 11:48:49.754 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:49.755 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:49.757 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.759 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 9 data: 02 62 55 87 FF 15 20 0A 00 2021-01-24 11:48:49.761 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 10 data: 02 62 55 87 FF 15 20 0A 00 00 2021-01-24 11:48:49.763 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:49.765 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:49.767 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.769 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 10 data: 02 62 55 87 FF 15 20 0A 00 00 2021-01-24 11:48:49.771 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 11 data: 02 62 55 87 FF 15 20 0A 00 00 00 2021-01-24 11:48:49.773 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:49.775 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:49.777 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.779 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 11 data: 02 62 55 87 FF 15 20 0A 00 00 00 2021-01-24 11:48:49.781 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 12 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 2021-01-24 11:48:49.783 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:49.785 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:49.787 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.789 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 12 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 2021-01-24 11:48:49.791 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 13 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 2021-01-24 11:48:49.793 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:49.794 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:49.796 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.798 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 13 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 2021-01-24 11:48:49.800 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 14 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 2021-01-24 11:48:49.802 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:49.804 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:49.805 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.807 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 14 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 2021-01-24 11:48:49.809 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 15 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 00 2021-01-24 11:48:49.811 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:49.812 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:49.814 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.816 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 15 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 00 2021-01-24 11:48:49.818 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 16 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 00 00 2021-01-24 11:48:49.819 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:49.821 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:49.823 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.824 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 16 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 00 00 2021-01-24 11:48:49.826 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 17 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 00 00 00 2021-01-24 11:48:49.828 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:49.830 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:49.831 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.833 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 17 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 00 00 00 2021-01-24 11:48:49.835 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 18 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 00 00 00 00 2021-01-24 11:48:49.837 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:49.838 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:49.840 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.841 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 18 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 00 00 00 00 2021-01-24 11:48:49.844 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 19 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 00 00 00 00 00 2021-01-24 11:48:49.845 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:49.847 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:49.848 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.850 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 19 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 00 00 00 00 00 2021-01-24 11:48:49.852 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 20 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 00 00 00 00 00 00 2021-01-24 11:48:49.853 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:49.855 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:49.857 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.858 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 20 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 00 00 00 00 00 00 2021-01-24 11:48:49.861 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 21 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 00 00 00 00 00 00 00 2021-01-24 11:48:49.862 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:49.864 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:49.866 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.868 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 21 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 00 00 00 00 00 00 00 2021-01-24 11:48:49.870 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 22 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 00 00 00 00 00 00 00 D6 2021-01-24 11:48:49.872 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:49.874 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:49.876 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.877 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 22 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 00 00 00 00 00 00 00 D6 2021-01-24 11:48:49.880 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 23 data: 02 62 55 87 FF 15 20 0A 00 00 00 00 00 00 00 00 00 00 00 00 00 D6 06 2021-01-24 11:48:49.881 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:49.883 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:49.884 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:49.886 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 0 data: 2021-01-24 11:48:49.887 [TRACE] [binding.insteon.internal.driver.Port] - signaling receipt of ack: true 2021-01-24 11:48:49.889 [TRACE] [binding.insteon.internal.driver.Port] - writer got ack: true 2021-01-24 11:48:49.997 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 1 data: 02 2021-01-24 11:48:49.999 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:50.001 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 1 data: 02 2021-01-24 11:48:50.003 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 2 data: 02 50 2021-01-24 11:48:50.004 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:50.006 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:50.008 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 2 data: 02 50 2021-01-24 11:48:50.010 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 3 data: 02 50 55 2021-01-24 11:48:50.012 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:50.014 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:50.015 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 3 data: 02 50 55 2021-01-24 11:48:50.018 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 4 data: 02 50 55 87 2021-01-24 11:48:50.019 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:50.022 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:50.023 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 4 data: 02 50 55 87 2021-01-24 11:48:50.026 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 5 data: 02 50 55 87 FF 2021-01-24 11:48:50.028 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:50.030 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:50.032 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 5 data: 02 50 55 87 FF 2021-01-24 11:48:50.035 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 6 data: 02 50 55 87 FF 53 2021-01-24 11:48:50.037 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:50.039 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:50.040 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 6 data: 02 50 55 87 FF 53 2021-01-24 11:48:50.043 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 7 data: 02 50 55 87 FF 53 BF 2021-01-24 11:48:50.044 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:50.046 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:50.048 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 7 data: 02 50 55 87 FF 53 BF 2021-01-24 11:48:50.050 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 8 data: 02 50 55 87 FF 53 BF 99 2021-01-24 11:48:50.052 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:50.054 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:50.055 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 8 data: 02 50 55 87 FF 53 BF 99 2021-01-24 11:48:50.058 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 9 data: 02 50 55 87 FF 53 BF 99 25 2021-01-24 11:48:50.059 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:50.061 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-24 11:48:50.063 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:50.065 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 9 data: 02 50 55 87 FF 53 BF 99 25 2021-01-24 11:48:50.066 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 10 data: 02 50 55 87 FF 53 BF 99 25 20 2021-01-24 11:48:50.069 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:50.070 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-24 11:48:50.072 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:50.073 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 10 data: 02 50 55 87 FF 53 BF 99 25 20 2021-01-24 11:48:50.076 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 11 data: 02 50 55 87 FF 53 BF 99 25 20 0A 2021-01-24 11:48:50.077 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:50.078 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-24 11:48:50.080 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:50.081 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 0 data: 2021-01-24 11:48:50.083 [DEBUG] [ding.insteon.internal.InsteonBinding] - got msg: IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:53.BF.99|messageFlags:0x25=ACK_OF_DIRECT:1:1|command1:0x20|command2:0x0A| 2021-01-24 11:48:50.084 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLightLevelAboveThreshold 2021-01-24 11:48:50.086 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: MotionSensor2Data 2021-01-24 11:48:50.087 [TRACE] [on.internal.device.MessageDispatcher] - 55.87.FF:MotionSensor2Data->DefaultMsgHandler IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:53.BF.99|messageFlags:0x25=ACK_OF_DIRECT:1:1|command1:0x20|command2:0x0A| 2021-01-24 11:48:50.089 [DEBUG] [steon.internal.device.MessageHandler] - DefaultMsgHandler ignoring unimpl message with cmd1:0x20 2021-01-24 11:48:50.090 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensor2TamperSwitch 2021-01-24 11:48:50.092 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorContact 2021-01-24 11:48:50.094 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLowBattery 2021-01-24 11:48:50.095 [TRACE] [on.internal.device.MessageDispatcher] - 55.87.FF:GenericLastTime->LastTimeHandler IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:53.BF.99|messageFlags:0x25=ACK_OF_DIRECT:1:1|command1:0x20|command2:0x0A| 2021-01-24 11:48:50.097 [DEBUG] [nsteon.internal.device.DeviceFeature] - 55.87.FF:GenericLastTime publishing: 2021-01-24T11:48:50.097133-0500 2021-01-24 11:48:50.099 [TRACE] [nternal.device.DeviceFeatureListener] - old state: DateTimeType:2021-01-24T11:48:21.039290-0500=?2021-01-24T11:48:50.097133-0500 2021-01-24 11:48:50.111 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue': afterAccess = 7 ms timeAverage50 = 67 ms timeAverage100 = 67 ms timeAverage200 = 67 ms afterAccessMin = 6 ms afterAccessMax = 482 ms 1000Statements = 0 sec statementCount = 8 2021-01-24 11:48:50.391 [TRACE] [binding.insteon.internal.driver.Port] - writer checking message queue 2021-01-24 11:48:51.654 [DEBUG] [.internal.device.RequestQueueManager] - device queue for 55.87.FF is empty! 2021-01-24 11:48:51.656 [TRACE] [.internal.device.RequestQueueManager] - waiting for request queues to fill 2021-01-24 11:48:59.290 [TRACE] [nsteon.internal.device.InsteonDevice] - enqueing direct message with delay 0 2021-01-24 11:48:59.295 [TRACE] [.internal.device.RequestQueueManager] - scheduling request for device 55.87.FF in -5 msec 2021-01-24 11:48:59.302 [DEBUG] [nsteon.internal.device.InsteonDevice] - qe taken off direct: console(0:0:0) OUT:Cmd:0x62|toAddress:55.87.FF|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x00|userData1:0x00|userData2:0x09|userData3:0x85|userData4:0x01|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x00|userData14:0x43| 2021-01-24 11:48:59.305 [TRACE] [nsteon.internal.device.DeviceFeature] - console set query status to: QUERY_PENDING 2021-01-24 11:48:59.309 [TRACE] [binding.insteon.internal.driver.Port] - enqueued msg: OUT:Cmd:0x62|toAddress:55.87.FF|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x00|userData1:0x00|userData2:0x09|userData3:0x85|userData4:0x01|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x00|userData14:0x43| 2021-01-24 11:48:59.309 [DEBUG] [binding.insteon.internal.driver.Port] - writing (500): OUT:Cmd:0x62|toAddress:55.87.FF|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x00|userData1:0x00|userData2:0x09|userData3:0x85|userData4:0x01|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x00|userData14:0x43| 2021-01-24 11:48:59.312 [TRACE] [binding.insteon.internal.driver.Port] - writer waiting for ack. 2021-01-24 11:48:59.312 [DEBUG] [nsteon.internal.device.InsteonDevice] - next request queue processed in 2000 msec, quiettime = 2000 2021-01-24 11:48:59.314 [TRACE] [.internal.device.RequestQueueManager] - device queue for 55.87.FF rescheduled in 2000 msec 2021-01-24 11:48:59.317 [TRACE] [.internal.device.RequestQueueManager] - request queue head: 55.87.FF must wait for 1982 msec 2021-01-24 11:48:59.335 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 1 data: 02 2021-01-24 11:48:59.337 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.339 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 1 data: 02 2021-01-24 11:48:59.341 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 2 data: 02 62 2021-01-24 11:48:59.343 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: false 2021-01-24 11:48:59.345 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.347 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 2 data: 02 62 2021-01-24 11:48:59.349 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 3 data: 02 62 55 2021-01-24 11:48:59.351 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: false 2021-01-24 11:48:59.353 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.355 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 3 data: 02 62 55 2021-01-24 11:48:59.357 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 4 data: 02 62 55 87 2021-01-24 11:48:59.359 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: false 2021-01-24 11:48:59.361 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.363 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 4 data: 02 62 55 87 2021-01-24 11:48:59.365 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 5 data: 02 62 55 87 FF 2021-01-24 11:48:59.367 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: false 2021-01-24 11:48:59.368 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.370 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 5 data: 02 62 55 87 FF 2021-01-24 11:48:59.372 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 6 data: 02 62 55 87 FF 1F 2021-01-24 11:48:59.374 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:59.376 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:59.378 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.380 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 6 data: 02 62 55 87 FF 1F 2021-01-24 11:48:59.382 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 7 data: 02 62 55 87 FF 1F 2E 2021-01-24 11:48:59.384 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:59.385 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:59.387 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.389 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 7 data: 02 62 55 87 FF 1F 2E 2021-01-24 11:48:59.391 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 8 data: 02 62 55 87 FF 1F 2E 00 2021-01-24 11:48:59.393 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:59.395 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:59.396 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.398 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 8 data: 02 62 55 87 FF 1F 2E 00 2021-01-24 11:48:59.401 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 9 data: 02 62 55 87 FF 1F 2E 00 00 2021-01-24 11:48:59.402 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:59.404 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:59.406 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.407 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 9 data: 02 62 55 87 FF 1F 2E 00 00 2021-01-24 11:48:59.410 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 10 data: 02 62 55 87 FF 1F 2E 00 00 09 2021-01-24 11:48:59.411 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:59.413 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:59.414 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.416 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 10 data: 02 62 55 87 FF 1F 2E 00 00 09 2021-01-24 11:48:59.418 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 11 data: 02 62 55 87 FF 1F 2E 00 00 09 85 2021-01-24 11:48:59.420 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:59.422 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:59.423 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.425 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 11 data: 02 62 55 87 FF 1F 2E 00 00 09 85 2021-01-24 11:48:59.427 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 12 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 2021-01-24 11:48:59.429 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:59.430 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:59.432 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.434 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 12 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 2021-01-24 11:48:59.436 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 13 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 2021-01-24 11:48:59.438 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:59.440 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:59.441 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.443 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 13 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 2021-01-24 11:48:59.445 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 14 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 2021-01-24 11:48:59.447 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:59.449 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:59.451 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.453 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 14 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 2021-01-24 11:48:59.455 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 15 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 00 2021-01-24 11:48:59.457 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:59.458 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:59.460 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.462 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 15 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 00 2021-01-24 11:48:59.464 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 16 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 00 00 2021-01-24 11:48:59.466 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:59.468 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:59.469 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.471 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 16 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 00 00 2021-01-24 11:48:59.473 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 17 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 00 00 00 2021-01-24 11:48:59.475 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:59.476 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:59.477 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.479 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 17 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 00 00 00 2021-01-24 11:48:59.481 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 18 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 00 00 00 00 2021-01-24 11:48:59.483 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:59.484 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:59.485 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.487 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 18 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 00 00 00 00 2021-01-24 11:48:59.489 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 19 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 00 00 00 00 00 2021-01-24 11:48:59.490 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:59.492 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:59.493 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.495 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 19 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 00 00 00 00 00 2021-01-24 11:48:59.497 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 20 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 00 00 00 00 00 00 2021-01-24 11:48:59.498 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:59.500 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:59.501 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.503 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 20 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 00 00 00 00 00 00 2021-01-24 11:48:59.504 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 21 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 00 00 00 00 00 00 00 2021-01-24 11:48:59.506 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:59.507 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:59.508 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.510 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 21 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 00 00 00 00 00 00 00 2021-01-24 11:48:59.512 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 22 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 00 00 00 00 00 00 00 43 2021-01-24 11:48:59.513 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:59.515 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:59.516 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.518 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 22 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 00 00 00 00 00 00 00 43 2021-01-24 11:48:59.519 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 23 data: 02 62 55 87 FF 1F 2E 00 00 09 85 01 00 00 00 00 00 00 00 00 00 43 06 2021-01-24 11:48:59.521 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 6 extended: true 2021-01-24 11:48:59.522 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 23 2021-01-24 11:48:59.524 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.525 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 0 data: 2021-01-24 11:48:59.526 [TRACE] [binding.insteon.internal.driver.Port] - signaling receipt of ack: true 2021-01-24 11:48:59.528 [TRACE] [binding.insteon.internal.driver.Port] - writer got ack: true 2021-01-24 11:48:59.863 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 1 data: 02 2021-01-24 11:48:59.865 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.867 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 1 data: 02 2021-01-24 11:48:59.870 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 2 data: 02 50 2021-01-24 11:48:59.872 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:59.874 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.876 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 2 data: 02 50 2021-01-24 11:48:59.878 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 3 data: 02 50 55 2021-01-24 11:48:59.881 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:59.883 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.885 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 3 data: 02 50 55 2021-01-24 11:48:59.887 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 4 data: 02 50 55 87 2021-01-24 11:48:59.890 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:59.892 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.894 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 4 data: 02 50 55 87 2021-01-24 11:48:59.896 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 5 data: 02 50 55 87 FF 2021-01-24 11:48:59.899 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:59.900 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.903 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 5 data: 02 50 55 87 FF 2021-01-24 11:48:59.905 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 6 data: 02 50 55 87 FF 53 2021-01-24 11:48:59.907 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:59.909 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.912 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 6 data: 02 50 55 87 FF 53 2021-01-24 11:48:59.914 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 7 data: 02 50 55 87 FF 53 BF 2021-01-24 11:48:59.916 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:59.918 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.920 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 7 data: 02 50 55 87 FF 53 BF 2021-01-24 11:48:59.922 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 8 data: 02 50 55 87 FF 53 BF 99 2021-01-24 11:48:59.924 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:59.926 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.928 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 8 data: 02 50 55 87 FF 53 BF 99 2021-01-24 11:48:59.930 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 9 data: 02 50 55 87 FF 53 BF 99 2F 2021-01-24 11:48:59.932 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:59.934 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-24 11:48:59.935 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.937 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 9 data: 02 50 55 87 FF 53 BF 99 2F 2021-01-24 11:48:59.940 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 10 data: 02 50 55 87 FF 53 BF 99 2F 2E 2021-01-24 11:48:59.941 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:59.943 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-24 11:48:59.945 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.947 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 10 data: 02 50 55 87 FF 53 BF 99 2F 2E 2021-01-24 11:48:59.949 [TRACE] [.insteon.internal.message.MsgFactory] - read buffer: len 11 data: 02 50 55 87 FF 53 BF 99 2F 2E 00 2021-01-24 11:48:59.951 [TRACE] [.insteon.internal.message.MsgFactory] - header length expected: 9 extended: false 2021-01-24 11:48:59.952 [TRACE] [.insteon.internal.message.MsgFactory] - msgLen expected: 11 2021-01-24 11:48:59.954 [TRACE] [.insteon.internal.message.MsgFactory] - done processing current buffer data 2021-01-24 11:48:59.956 [TRACE] [.insteon.internal.message.MsgFactory] - keeping buffer len 0 data: 2021-01-24 11:48:59.958 [DEBUG] [ding.insteon.internal.InsteonBinding] - got msg: IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:53.BF.99|messageFlags:0x2F=ACK_OF_DIRECT:3:3|command1:0x2E|command2:0x00| 2021-01-24 11:48:59.960 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLightLevelAboveThreshold 2021-01-24 11:48:59.962 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: MotionSensor2Data 2021-01-24 11:48:59.964 [TRACE] [on.internal.device.MessageDispatcher] - 55.87.FF:MotionSensor2Data->MotionSensorDataReplyHandler IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:53.BF.99|messageFlags:0x2F=ACK_OF_DIRECT:3:3|command1:0x2E|command2:0x00| 2021-01-24 11:48:59.967 [TRACE] [steon.internal.device.MessageHandler] - MotionSensorDataReplyHandler device 55.87.FF ignoring non-extended msg IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:53.BF.99|messageFlags:0x2F=ACK_OF_DIRECT:3:3|command1:0x2E|command2:0x00| 2021-01-24 11:48:59.968 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensor2TamperSwitch 2021-01-24 11:48:59.970 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorContact 2021-01-24 11:48:59.972 [DEBUG] [nsteon.internal.device.InsteonDevice] - ----- applying message to feature: WirelessMotionSensorLowBattery 2021-01-24 11:48:59.975 [TRACE] [on.internal.device.MessageDispatcher] - 55.87.FF:GenericLastTime->LastTimeHandler IN:Cmd:0x50|fromAddress:55.87.FF|toAddress:53.BF.99|messageFlags:0x2F=ACK_OF_DIRECT:3:3|command1:0x2E|command2:0x00| 2021-01-24 11:48:59.977 [DEBUG] [nsteon.internal.device.DeviceFeature] - 55.87.FF:GenericLastTime publishing: 2021-01-24T11:48:59.976823-0500 2021-01-24 11:48:59.980 [TRACE] [nternal.device.DeviceFeatureListener] - old state: DateTimeType:2021-01-24T11:48:50.097133-0500=?2021-01-24T11:48:59.976823-0500 2021-01-24 11:48:59.992 [INFO ] [persistence.jdbc.internal.JdbcMapper] - JDBC::logTime: 'storeItemValue': afterAccess = 6 ms timeAverage50 = 60 ms timeAverage100 = 60 ms timeAverage200 = 60 ms afterAccessMin = 6 ms afterAccessMax = 482 ms 1000Statements = 0 sec statementCount = 9 2021-01-24 11:49:00.029 [TRACE] [binding.insteon.internal.driver.Port] - writer checking message queue 2021-01-24 11:49:01.302 [DEBUG] [.internal.device.RequestQueueManager] - device queue for 55.87.FF is empty! 2021-01-24 11:49:01.306 [TRACE] [.internal.device.RequestQueueManager] - waiting for request queues to fill