== ATTEMPT FRESH START == 1 02/28/08 12:09:45 /usr/pluto/bin/Spawn_Device.sh 33 (spawning-device) 26263 Dev: 33; Already Running list: 15,16,17,18,28, == FRESH START == 1 02/28/08 12:09:45 /usr/pluto/bin/Spawn_Device.sh 33 (spawning-device) device: 33 ip: localhost cmd_line: ZWave 0 02/28/08 12:09:45 33 (spawning-device) Entering 33 ========== NEW LOG SECTION ========== 1 02/28/08 12:09:45 33 (spawning-device) Starting... 1 1 02/28/08 12:09:45 33 (spawning-device) Found /usr/pluto/bin/ZWave 10 02/28/08 12:09:45.787 Device: 33 starting. Connecting to: localhost <0x2ab49b058b40> 10 02/28/08 12:09:45.792 Setting timeout for socket 4 to 20 <0x2ab49b058b40> 10 02/28/08 12:09:45.880 Socket::SendMessage type 5 id 37 from 33 to -1000 <0x2ab49b058b40> 10 02/28/08 12:09:45.945 TranslateSerialUSB found /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-5/1-5:1.0/ttyUSB0/ttyUSB0, returning /dev/ttyUSB0 <0x2ab49b058b40> 36 02/28/08 12:09:45.945 Using serial port: ttyUSB0. <0x2ab49b058b40> 36 02/28/08 12:09:45.959 SerialConnection::connect init serial mutex <0x2ab49b058b40> 36 02/28/08 12:09:45.959 receive thread created OK!!!! <0x2ab49b058b40> 35 02/28/08 12:09:45.959 entry point receiveFunction <0x41001950> 35 02/28/08 12:09:46.164 ++++++++++++ ZWave is connected <0x2ab49b058b40> 36 02/28/08 12:09:46.164 ### Run Current Job <0x41802950> 36 02/28/08 12:09:46.220 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:09:46.220 SerialConnection::send len = 2 buf = 0x00 0x15 <0x41802950> 36 02/28/08 12:09:46.220 SerialConnection::send unlock serial mutex <0x41802950> 05 02/28/08 12:09:51.039 ### Go to timeout queue <0x41802950> 05 02/28/08 12:09:51.039 ### execute the next job from timeout queue <0x41802950> 05 02/28/08 12:09:51.039 ZWJobInitialize::timeoutHandler <0x41802950> 36 02/28/08 12:09:51.095 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:09:51.095 SerialConnection::send len = 2 buf = 0x00 0x15 <0x41802950> 36 02/28/08 12:09:51.095 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:09:51.319 size too small 1 <0x41802950> 35 02/28/08 12:09:51.375 size too small 1 <0x41802950> 35 02/28/08 12:09:51.431 size too small 1 <0x41802950> 35 02/28/08 12:09:51.487 size too small 1 <0x41802950> 35 02/28/08 12:09:51.543 size too small 1 <0x41802950> 35 02/28/08 12:09:51.599 size too small 1 <0x41802950> 35 02/28/08 12:09:51.655 size too small 1 <0x41802950> 35 02/28/08 12:09:51.711 size too small 1 <0x41802950> 35 02/28/08 12:09:51.767 size too small 1 <0x41802950> 35 02/28/08 12:09:51.823 size too small 1 <0x41802950> 35 02/28/08 12:09:51.879 size too small 1 <0x41802950> 35 02/28/08 12:09:51.935 size too small 1 <0x41802950> 35 02/28/08 12:09:51.991 size too small 1 <0x41802950> 35 02/28/08 12:09:52.047 size too small 1 <0x41802950> 35 02/28/08 12:09:52.103 size too small 1 <0x41802950> 35 02/28/08 12:09:52.159 size too small 1 <0x41802950> 35 02/28/08 12:09:52.215 size too small 1 <0x41802950> 35 02/28/08 12:09:52.271 size too small 1 <0x41802950> 35 02/28/08 12:09:52.327 size too small 1 <0x41802950> 35 02/28/08 12:09:52.383 size too small 1 <0x41802950> 35 02/28/08 12:09:52.439 size too small 1 <0x41802950> 35 02/28/08 12:09:52.495 size too small 1 <0x41802950> 35 02/28/08 12:09:52.551 size too small 1 <0x41802950> 35 02/28/08 12:09:52.607 size too small 1 <0x41802950> 35 02/28/08 12:09:52.663 size too small 1 <0x41802950> 35 02/28/08 12:09:52.719 size too small 1 <0x41802950> 35 02/28/08 12:09:52.775 size too small 1 <0x41802950> 35 02/28/08 12:09:52.831 size too small 1 <0x41802950> 35 02/28/08 12:09:52.887 size too small 1 <0x41802950> 35 02/28/08 12:09:52.943 size too small 1 <0x41802950> 35 02/28/08 12:09:52.999 size too small 1 <0x41802950> 35 02/28/08 12:09:53.055 size too small 1 <0x41802950> 35 02/28/08 12:09:53.111 size too small 1 <0x41802950> 35 02/28/08 12:09:53.167 size too small 1 <0x41802950> 35 02/28/08 12:09:53.223 size too small 1 <0x41802950> 35 02/28/08 12:09:53.279 size too small 1 <0x41802950> 35 02/28/08 12:09:53.335 size too small 1 <0x41802950> 35 02/28/08 12:09:53.391 size too small 1 <0x41802950> 35 02/28/08 12:09:53.447 size too small 1 <0x41802950> 35 02/28/08 12:09:53.503 size too small 1 <0x41802950> 35 02/28/08 12:09:53.559 size too small 1 <0x41802950> 35 02/28/08 12:09:53.615 size too small 1 <0x41802950> 35 02/28/08 12:09:53.671 size too small 1 <0x41802950> 35 02/28/08 12:09:53.727 size too small 1 <0x41802950> 35 02/28/08 12:09:53.783 size too small 1 <0x41802950> 35 02/28/08 12:09:53.839 size too small 1 <0x41802950> 35 02/28/08 12:09:53.895 size too small 1 <0x41802950> 35 02/28/08 12:09:53.951 size too small 1 <0x41802950> 35 02/28/08 12:09:54.007 size too small 1 <0x41802950> 35 02/28/08 12:09:54.063 size too small 1 <0x41802950> 35 02/28/08 12:09:54.119 size too small 1 <0x41802950> 35 02/28/08 12:09:54.175 size too small 1 <0x41802950> 35 02/28/08 12:09:54.231 size too small 1 <0x41802950> 35 02/28/08 12:09:54.287 size too small 1 <0x41802950> 35 02/28/08 12:09:54.343 size too small 1 <0x41802950> 35 02/28/08 12:09:54.399 size too small 1 <0x41802950> 35 02/28/08 12:09:54.455 size too small 1 <0x41802950> 35 02/28/08 12:09:54.511 size too small 1 <0x41802950> 35 02/28/08 12:09:54.567 size too small 1 <0x41802950> 35 02/28/08 12:09:54.623 size too small 1 <0x41802950> 35 02/28/08 12:09:54.679 size too small 1 <0x41802950> 35 02/28/08 12:09:54.735 size too small 1 <0x41802950> 35 02/28/08 12:09:54.791 size too small 1 <0x41802950> 35 02/28/08 12:09:54.847 size too small 1 <0x41802950> 35 02/28/08 12:09:54.903 size too small 1 <0x41802950> 35 02/28/08 12:09:54.959 size too small 1 <0x41802950> 35 02/28/08 12:09:55.015 size too small 1 <0x41802950> 35 02/28/08 12:09:55.071 size too small 1 <0x41802950> 35 02/28/08 12:09:55.127 size too small 1 <0x41802950> 35 02/28/08 12:09:55.183 size too small 1 <0x41802950> 35 02/28/08 12:09:55.239 size too small 1 <0x41802950> 35 02/28/08 12:09:55.295 size too small 1 <0x41802950> 35 02/28/08 12:09:55.351 size too small 1 <0x41802950> 35 02/28/08 12:09:55.407 size too small 1 <0x41802950> 35 02/28/08 12:09:55.463 size too small 1 <0x41802950> 35 02/28/08 12:09:55.519 size too small 1 <0x41802950> 35 02/28/08 12:09:55.575 size too small 1 <0x41802950> 35 02/28/08 12:09:55.631 size too small 1 <0x41802950> 35 02/28/08 12:09:55.687 size too small 1 <0x41802950> 35 02/28/08 12:09:55.743 size too small 1 <0x41802950> 35 02/28/08 12:09:55.799 size too small 1 <0x41802950> 35 02/28/08 12:09:55.855 size too small 1 <0x41802950> 35 02/28/08 12:09:55.911 size too small 1 <0x41802950> 35 02/28/08 12:09:55.967 size too small 1 <0x41802950> 35 02/28/08 12:09:56.023 size too small 1 <0x41802950> 05 02/28/08 12:09:56.023 ### Go to timeout queue <0x41802950> 05 02/28/08 12:09:56.023 ### execute the next job from timeout queue <0x41802950> 05 02/28/08 12:09:56.023 ZWJobInitialize::timeoutHandler <0x41802950> 36 02/28/08 12:09:56.079 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:09:56.183 SerialConnection::send len = 2 buf = 0x00 0x15 <0x41802950> 36 02/28/08 12:09:56.183 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:09:56.519 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:09:56.519 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:09:56.519 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:09:56.519 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:09:56.519 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:09:56.519 receiveCommand::begin <0x41802950> 35 02/28/08 12:09:56.519 buffer.size()= 18 <0x41802950> 35 02/28/08 12:09:56.519 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:09:56.519 SerialConnection : received command len = 15 buf = 0x01 0x15 0x5a 0x2d 0x57 0x61 0x76 0x65 0x20 0x32 0x2e 0x32 0x34 0x00 0x01 <0x41802950> 35 02/28/08 12:09:56.520 ZWJobInitialize len = 15 buf = 0x01 0x15 0x5a 0x2d 0x57 0x61 0x76 0x65 0x20 0x32 0x2e 0x32 0x34 0x00 0x01 <0x41802950> 35 02/28/08 12:09:56.520 ZWJobGetVersion len = 15 buf = 0x01 0x15 0x5a 0x2d 0x57 0x61 0x76 0x65 0x20 0x32 0x2e 0x32 0x34 0x00 0x01 <0x41802950> 35 02/28/08 12:09:56.520 Z-Wave 2.24 <0x41802950> 36 02/28/08 12:09:56.575 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:09:56.575 SerialConnection::send len = 2 buf = 0x00 0x20 <0x41802950> 36 02/28/08 12:09:56.575 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:09:56.855 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:09:56.855 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:09:56.855 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:09:56.855 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:09:56.855 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:09:56.855 receiveCommand::begin <0x41802950> 35 02/28/08 12:09:56.855 buffer.size()= 10 <0x41802950> 35 02/28/08 12:09:56.855 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:09:56.855 SerialConnection : received command len = 7 buf = 0x01 0x20 0x00 0x01 0x14 0x7f 0x01 <0x41802950> 35 02/28/08 12:09:56.855 ZWJobInitialize len = 7 buf = 0x01 0x20 0x00 0x01 0x14 0x7f 0x01 <0x41802950> 35 02/28/08 12:09:56.855 ZWJobGetID len = 7 buf = 0x01 0x20 0x00 0x01 0x14 0x7f 0x01 <0x41802950> 36 02/28/08 12:09:56.911 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:09:56.911 SerialConnection::send len = 2 buf = 0x00 0x02 <0x41802950> 36 02/28/08 12:09:56.911 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:09:57.135 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:09:57.415 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:09:57.415 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:09:57.415 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:09:57.415 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:09:57.415 receiveCommand::begin <0x41802950> 35 02/28/08 12:09:57.415 buffer.size()= 39 <0x41802950> 35 02/28/08 12:09:57.415 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:09:57.415 SerialConnection : received command len = 36 buf = 0x01 0x02 0x04 0x00 0x1d 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x01 0x02 <0x41802950> 35 02/28/08 12:09:57.415 ZWJobInitialize len = 36 buf = 0x01 0x02 0x04 0x00 0x1d 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x01 0x02 <0x41802950> 35 02/28/08 12:09:57.415 ZWJobGetInitData len = 36 buf = 0x01 0x02 0x04 0x00 0x1d 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x01 0x02 <0x41802950> 36 02/28/08 12:09:57.471 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:09:57.471 SerialConnection::send len = 3 buf = 0x00 0x52 0x01 <0x41802950> 36 02/28/08 12:09:57.471 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:09:57.751 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:09:57.751 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:09:57.751 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:09:57.751 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:09:57.751 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:09:57.751 receiveCommand::begin <0x41802950> 35 02/28/08 12:09:57.751 buffer.size()= 6 <0x41802950> 35 02/28/08 12:09:57.751 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:09:57.751 SerialConnection : received command len = 3 buf = 0x01 0x52 0x01 <0x41802950> 35 02/28/08 12:09:57.751 ZWJobInitialize len = 3 buf = 0x01 0x52 0x01 <0x41802950> 35 02/28/08 12:09:57.751 ZWJobGetSUC len = 3 buf = 0x01 0x52 0x01 <0x41802950> 36 02/28/08 12:09:57.807 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:09:57.807 SerialConnection::send len = 2 buf = 0x00 0x56 <0x41802950> 36 02/28/08 12:09:57.807 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:09:58.031 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:09:58.031 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:09:58.031 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:09:58.031 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:09:58.031 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:09:58.031 receiveCommand::begin <0x41802950> 35 02/28/08 12:09:58.031 buffer.size()= 6 <0x41802950> 35 02/28/08 12:09:58.031 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:09:58.031 SerialConnection : received command len = 3 buf = 0x01 0x56 0x00 <0x41802950> 35 02/28/08 12:09:58.031 ZWJobInitialize len = 3 buf = 0x01 0x56 0x00 <0x41802950> 35 02/28/08 12:09:58.031 ZWJobGetSUC len = 3 buf = 0x01 0x56 0x00 <0x41802950> 36 02/28/08 12:09:58.087 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:09:58.087 SerialConnection::send len = 3 buf = 0x00 0x41 0x01 <0x41802950> 36 02/28/08 12:09:58.087 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:09:58.367 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:09:58.367 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:09:58.367 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:09:58.367 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:09:58.367 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:09:58.367 receiveCommand::begin <0x41802950> 35 02/28/08 12:09:58.367 buffer.size()= 11 <0x41802950> 35 02/28/08 12:09:58.367 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:09:58.367 SerialConnection : received command len = 8 buf = 0x01 0x41 0xca 0x06 0x00 0x02 0x02 0x01 <0x41802950> 35 02/28/08 12:09:58.367 ZWJobInitialize len = 8 buf = 0x01 0x41 0xca 0x06 0x00 0x02 0x02 0x01 <0x41802950> 35 02/28/08 12:09:58.367 ZWJobGetNodeProtocolInfo len = 8 buf = 0x01 0x41 0xca 0x06 0x00 0x02 0x02 0x01 <0x41802950> 35 02/28/08 12:09:58.367 ----- INIT ---- 3 <0x41802950> 35 02/28/08 12:09:58.367 ----- INIT ---- 1 <0x41802950> 35 02/28/08 12:09:58.367 ----- INIT ---- 2 <0x41802950> 36 02/28/08 12:09:58.367 ## Current Job Finished --- Left = 0 <0x41802950> 36 02/28/08 12:09:58.376 ZWave::ReportChildDevices trying to get list of devices <0x42003950> 36 02/28/08 12:09:58.376 ZWave::ReportChildDevices got: <0x42003950> 36 02/28/08 12:09:58.376 <0x42003950> 10 02/28/08 12:09:58.376 Socket::SendMessage type 2 id 54 from 33 to -1001 <0x42003950> 10 02/28/08 12:09:58.379 Connect OK <0x2ab49b058b40> 05 02/28/08 12:09:58.379 Creating child 34 <0x2ab49b058b40> 10 02/28/08 12:09:58.380 Got CreateEvent for unknown type 1820. <0x2ab49b058b40> 05 02/28/08 12:09:58.380 Note: Device manager has attached a device of type 1820 that this has no custom event handler for. It will not fire events. <0x2ab49b058b40> 10 02/28/08 12:09:58.380 Got CreateCommand for unknown type 1820. <0x2ab49b058b40> 05 02/28/08 12:09:58.380 Note: Device manager has attached a device of type 1820 that this has no custom handler for. This is normal for IR. <0x2ab49b058b40> 10 02/28/08 12:09:58.380 Requesthandler 0x667590 (device: 33) runThread now running <0x43005950> 10 02/28/08 12:10:18.688 Receive string: <0x43005950> 10 02/28/08 12:10:18.688 Received 0x667590 device: 33 <0x43005950> 10 02/28/08 12:10:19.910 Receive string: <0x43005950> 10 02/28/08 12:10:19.910 Received 0x667590 device: 33 <0x43005950> 10 02/28/08 12:10:20.929 Receive string: <0x43005950> 10 02/28/08 12:10:20.929 Received 0x667590 device: 33 <0x43005950> 10 02/28/08 12:10:42.164 Receive string: <0x43005950> 10 02/28/08 12:10:42.164 Received 0x667590 device: 33 <0x43005950> 10 02/28/08 12:27:08.171 Receive string: MESSAGE 72 <0x43005950> 10 02/28/08 12:27:08.171 Received MESSAGE 72 0x667590 device: 33 <0x43005950> 10 02/28/08 12:27:08.171 Received Message type 1 ID 757 from 20 to 33 (device: 33) resp 3 <0x43005950> 36 02/28/08 12:27:08.173 ZWave::DownloadConfiguration trying to get list of devices <0x43806950> 35 02/28/08 12:27:08.173 -------- 3 <0x43806950> 35 02/28/08 12:27:08.173 SerialConnection ------------- asa 1 <0x43806950> 35 02/28/08 12:27:08.275 SerialConnection ------------- asa 2 <0x43806950> 36 02/28/08 12:27:08.275 waiting for thread to finish <0x43806950> 35 02/28/08 12:27:08.375 exit receiveFunction : nr. of reads 3391 <0x41001950> 36 02/28/08 12:27:08.375 thread finished <0x43806950> 35 02/28/08 12:27:08.375 SerialConnection ------------- asa 3 <0x43806950> 35 02/28/08 12:27:08.375 SerialConnection ------------- asa 4 <0x43806950> 35 02/28/08 12:27:08.375 -------- 4 <0x43806950> 36 02/28/08 12:27:08.387 SerialConnection::connect init serial mutex <0x43806950> 36 02/28/08 12:27:08.387 receive thread created OK!!!! <0x43806950> 35 02/28/08 12:27:08.387 entry point receiveFunction <0x40800950> 35 02/28/08 12:27:08.591 ++++++++++++ ZWave is connected <0x43806950> 36 02/28/08 12:27:08.603 ### Run Current Job <0x41802950> 36 02/28/08 12:27:08.659 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:27:08.659 SerialConnection::send len = 7 buf = 0x00 0x03 0x01 0x02 0x01 0x01 0x21 <0x41802950> 36 02/28/08 12:27:08.659 SerialConnection::send unlock serial mutex <0x41802950> 36 02/28/08 12:27:09.215 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:27:09.215 SerialConnection::send len = 3 buf = 0x00 0x42 0x01 <0x41802950> 36 02/28/08 12:27:09.215 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:27:09.271 size too small 1 <0x41802950> 35 02/28/08 12:27:09.323 size too small 1 <0x41802950> 35 02/28/08 12:27:09.375 size too small 1 <0x41802950> 35 02/28/08 12:27:09.427 size too small 2 <0x41802950> 35 02/28/08 12:27:09.483 size too small 2 <0x41802950> 35 02/28/08 12:27:09.539 size too small 2 <0x41802950> 35 02/28/08 12:27:09.595 size too small 2 <0x41802950> 35 02/28/08 12:27:09.651 size too small 2 <0x41802950> 35 02/28/08 12:27:09.703 size too small 2 <0x41802950> 35 02/28/08 12:27:09.756 size too small 2 <0x41802950> 35 02/28/08 12:27:09.811 size too small 2 <0x41802950> 35 02/28/08 12:27:09.863 size too small 2 <0x41802950> 35 02/28/08 12:27:09.919 size too small 2 <0x41802950> 35 02/28/08 12:27:09.975 size too small 2 <0x41802950> 35 02/28/08 12:27:10.027 size too small 2 <0x41802950> 35 02/28/08 12:27:10.079 size too small 2 <0x41802950> 35 02/28/08 12:27:10.135 size too small 2 <0x41802950> 35 02/28/08 12:27:10.191 size too small 2 <0x41802950> 35 02/28/08 12:27:10.243 size too small 2 <0x41802950> 35 02/28/08 12:27:10.299 size too small 2 <0x41802950> 35 02/28/08 12:27:10.355 size too small 2 <0x41802950> 35 02/28/08 12:27:10.411 size too small 2 <0x41802950> 35 02/28/08 12:27:10.467 size too small 2 <0x41802950> 35 02/28/08 12:27:10.519 size too small 2 <0x41802950> 35 02/28/08 12:27:10.571 size too small 2 <0x41802950> 35 02/28/08 12:27:10.627 size too small 2 <0x41802950> 35 02/28/08 12:27:10.679 size too small 2 <0x41802950> 35 02/28/08 12:27:10.735 size too small 2 <0x41802950> 35 02/28/08 12:27:10.791 size too small 2 <0x41802950> 35 02/28/08 12:27:10.847 size too small 2 <0x41802950> 35 02/28/08 12:27:10.903 size too small 2 <0x41802950> 35 02/28/08 12:27:10.955 size too small 2 <0x41802950> 35 02/28/08 12:27:11.007 size too small 2 <0x41802950> 35 02/28/08 12:27:11.059 size too small 2 <0x41802950> 35 02/28/08 12:27:11.114 size too small 2 <0x41802950> 35 02/28/08 12:27:11.167 size too small 2 <0x41802950> 35 02/28/08 12:27:11.223 size too small 2 <0x41802950> 35 02/28/08 12:27:11.279 size too small 2 <0x41802950> 35 02/28/08 12:27:11.335 size too small 2 <0x41802950> 35 02/28/08 12:27:11.390 size too small 2 <0x41802950> 35 02/28/08 12:27:11.443 size too small 2 <0x41802950> 35 02/28/08 12:27:11.499 size too small 2 <0x41802950> 35 02/28/08 12:27:11.551 size too small 2 <0x41802950> 35 02/28/08 12:27:11.607 size too small 2 <0x41802950> 35 02/28/08 12:27:11.663 size too small 2 <0x41802950> 35 02/28/08 12:27:11.719 size too small 2 <0x41802950> 35 02/28/08 12:27:11.771 size too small 2 <0x41802950> 35 02/28/08 12:27:11.827 size too small 2 <0x41802950> 35 02/28/08 12:27:11.883 size too small 2 <0x41802950> 35 02/28/08 12:27:11.935 size too small 2 <0x41802950> 35 02/28/08 12:27:11.991 size too small 2 <0x41802950> 35 02/28/08 12:27:12.047 size too small 2 <0x41802950> 35 02/28/08 12:27:12.099 size too small 2 <0x41802950> 35 02/28/08 12:27:12.151 size too small 2 <0x41802950> 35 02/28/08 12:27:12.203 size too small 2 <0x41802950> 35 02/28/08 12:27:12.259 size too small 2 <0x41802950> 35 02/28/08 12:27:12.315 size too small 2 <0x41802950> 35 02/28/08 12:27:12.367 size too small 2 <0x41802950> 35 02/28/08 12:27:12.419 size too small 2 <0x41802950> 35 02/28/08 12:27:12.475 size too small 2 <0x41802950> 10 02/28/08 12:27:15.027 Socket::SendMessage type 2 id 55 from 33 to -1001 <0x43806950> 05 02/28/08 12:27:16.023 -------------------------- Job Timeout _________ <0x41802950> 35 02/28/08 12:27:17.142 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:27:17.143 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:27:17.143 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:27:17.143 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:27:17.143 receiveCommand::begin <0x41802950> 35 02/28/08 12:27:17.143 buffer.size()= 6 <0x41802950> 35 02/28/08 12:27:17.143 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:27:17.143 SerialConnection : received command len = 3 buf = 0x00 0x42 0x01 <0x41802950> 10 02/28/08 12:28:31.912 Receive string: <0x43005950> 10 02/28/08 12:28:31.912 Received 0x667590 device: 33 <0x43005950> 10 02/28/08 12:28:37.107 Receive string: MESSAGE 72 <0x43005950> 10 02/28/08 12:28:37.108 Received MESSAGE 72 0x667590 device: 33 <0x43005950> 10 02/28/08 12:28:37.108 Received Message type 1 ID 757 from 20 to 33 (device: 33) resp 3 <0x43005950> 36 02/28/08 12:28:37.108 ZWave::DownloadConfiguration trying to get list of devices <0x44007950> 35 02/28/08 12:28:37.108 -------- 3 <0x44007950> 35 02/28/08 12:28:37.108 SerialConnection ------------- asa 1 <0x44007950> 35 02/28/08 12:28:37.273 SerialConnection ------------- asa 2 <0x44007950> 36 02/28/08 12:28:37.273 waiting for thread to finish <0x44007950> 35 02/28/08 12:28:37.373 exit receiveFunction : nr. of reads 290 <0x40800950> 36 02/28/08 12:28:37.373 thread finished <0x44007950> 35 02/28/08 12:28:37.373 SerialConnection ------------- asa 3 <0x44007950> 35 02/28/08 12:28:37.373 SerialConnection ------------- asa 4 <0x44007950> 35 02/28/08 12:28:37.373 -------- 4 <0x44007950> 36 02/28/08 12:28:37.388 SerialConnection::connect init serial mutex <0x44007950> 36 02/28/08 12:28:37.388 receive thread created OK!!!! <0x44007950> 35 02/28/08 12:28:37.388 entry point receiveFunction <0x41001950> 35 02/28/08 12:28:37.593 ++++++++++++ ZWave is connected <0x44007950> 36 02/28/08 12:28:37.605 ### Run Current Job <0x41802950> 36 02/28/08 12:28:37.656 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:28:37.657 SerialConnection::send len = 7 buf = 0x00 0x03 0x01 0x02 0x01 0x01 0x21 <0x41802950> 36 02/28/08 12:28:37.657 SerialConnection::send unlock serial mutex <0x41802950> 36 02/28/08 12:28:38.212 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:28:38.213 SerialConnection::send len = 3 buf = 0x00 0x42 0x02 <0x41802950> 36 02/28/08 12:28:38.213 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:28:38.420 size too small 1 <0x41802950> 35 02/28/08 12:28:38.473 size too small 1 <0x41802950> 35 02/28/08 12:28:38.524 size too small 1 <0x41802950> 35 02/28/08 12:28:38.576 size too small 1 <0x41802950> 35 02/28/08 12:28:38.628 size too small 1 <0x41802950> 35 02/28/08 12:28:38.680 size too small 1 <0x41802950> 35 02/28/08 12:28:38.732 size too small 1 <0x41802950> 35 02/28/08 12:28:38.784 size too small 1 <0x41802950> 35 02/28/08 12:28:38.838 size too small 1 <0x41802950> 35 02/28/08 12:28:38.892 size too small 1 <0x41802950> 35 02/28/08 12:28:38.944 size too small 1 <0x41802950> 35 02/28/08 12:28:38.996 size too small 1 <0x41802950> 35 02/28/08 12:28:39.048 size too small 1 <0x41802950> 35 02/28/08 12:28:39.100 size too small 1 <0x41802950> 35 02/28/08 12:28:39.156 size too small 1 <0x41802950> 35 02/28/08 12:28:39.208 size too small 1 <0x41802950> 35 02/28/08 12:28:39.260 size too small 1 <0x41802950> 35 02/28/08 12:28:39.312 size too small 1 <0x41802950> 35 02/28/08 12:28:39.364 size too small 1 <0x41802950> 35 02/28/08 12:28:39.416 size too small 1 <0x41802950> 35 02/28/08 12:28:39.470 size too small 1 <0x41802950> 35 02/28/08 12:28:39.524 size too small 1 <0x41802950> 35 02/28/08 12:28:39.576 size too small 1 <0x41802950> 35 02/28/08 12:28:39.628 size too small 1 <0x41802950> 35 02/28/08 12:28:39.680 size too small 1 <0x41802950> 35 02/28/08 12:28:39.732 size too small 1 <0x41802950> 35 02/28/08 12:28:39.788 size too small 1 <0x41802950> 35 02/28/08 12:28:39.840 size too small 1 <0x41802950> 35 02/28/08 12:28:39.892 size too small 1 <0x41802950> 35 02/28/08 12:28:39.944 size too small 1 <0x41802950> 35 02/28/08 12:28:39.996 size too small 1 <0x41802950> 35 02/28/08 12:28:40.048 size too small 1 <0x41802950> 35 02/28/08 12:28:40.100 size too small 1 <0x41802950> 35 02/28/08 12:28:40.152 size too small 1 <0x41802950> 35 02/28/08 12:28:40.204 size too small 1 <0x41802950> 35 02/28/08 12:28:40.256 size too small 1 <0x41802950> 35 02/28/08 12:28:40.308 size too small 1 <0x41802950> 35 02/28/08 12:28:40.360 size too small 1 <0x41802950> 35 02/28/08 12:28:40.412 size too small 1 <0x41802950> 35 02/28/08 12:28:40.464 size too small 1 <0x41802950> 35 02/28/08 12:28:40.516 size too small 1 <0x41802950> 35 02/28/08 12:28:40.572 size too small 1 <0x41802950> 35 02/28/08 12:28:40.624 size too small 1 <0x41802950> 35 02/28/08 12:28:40.676 size too small 1 <0x41802950> 35 02/28/08 12:28:40.728 size too small 1 <0x41802950> 35 02/28/08 12:28:40.780 size too small 1 <0x41802950> 35 02/28/08 12:28:40.832 size too small 1 <0x41802950> 35 02/28/08 12:28:40.884 size too small 1 <0x41802950> 35 02/28/08 12:28:40.936 size too small 1 <0x41802950> 35 02/28/08 12:28:40.988 size too small 1 <0x41802950> 35 02/28/08 12:28:41.040 size too small 1 <0x41802950> 35 02/28/08 12:28:41.092 size too small 1 <0x41802950> 35 02/28/08 12:28:41.144 size too small 1 <0x41802950> 35 02/28/08 12:28:41.196 size too small 1 <0x41802950> 35 02/28/08 12:28:41.248 size too small 1 <0x41802950> 35 02/28/08 12:28:41.300 size too small 1 <0x41802950> 35 02/28/08 12:28:41.354 size too small 1 <0x41802950> 35 02/28/08 12:28:41.408 size too small 1 <0x41802950> 35 02/28/08 12:28:41.460 size too small 1 <0x41802950> 10 02/28/08 12:28:44.023 Socket::SendMessage type 2 id 55 from 33 to -1001 <0x44007950> 05 02/28/08 12:28:45.048 -------------------------- Job Timeout _________ <0x41802950> 35 02/28/08 12:28:46.112 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:28:46.112 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:28:46.112 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:28:46.112 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:28:46.112 receiveCommand::begin <0x41802950> 35 02/28/08 12:28:46.112 buffer.size()= 6 <0x41802950> 35 02/28/08 12:28:46.112 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:28:46.112 SerialConnection : received command len = 3 buf = 0x00 0x42 0x02 <0x41802950> 10 02/28/08 12:30:09.372 Receive string: MESSAGE 73 <0x43005950> 10 02/28/08 12:30:09.372 Received MESSAGE 73 0x667590 device: 33 <0x43005950> 10 02/28/08 12:30:09.372 Received Message type 7 ID 1 from 0 to 33 (device: 33) resp 0 <0x43005950> 05 02/28/08 12:30:09.372 Got a reload command from 0  <0x43005950> 10 02/28/08 12:30:09.623 Command_Impl::OnReload 33 <0x43005950> 10 02/28/08 12:30:09.624 Socket m_Socket 7/0x667590 Command_Impl1 Dev #33 m_bQuit=1 <0x43005950> 10 02/28/08 12:30:09.624 Requesthandler 0x667590 (device: 33) Closing request handler connection <0x43005950> 13 02/28/08 12:30:09.624 Exiting BeginHandleRequestThread thread... <0x43005950> 35 02/28/08 12:30:09.624 -------- 3 <0x2ab49b058b40> 35 02/28/08 12:30:09.624 SerialConnection ------------- asa 1 <0x2ab49b058b40> 13 02/28/08 12:30:09.625 Exiting MessageQueueThread_DCECI thread... <0x42804950> 35 02/28/08 12:30:09.730 SerialConnection ------------- asa 2 <0x2ab49b058b40> 36 02/28/08 12:30:09.731 waiting for thread to finish <0x2ab49b058b40> 35 02/28/08 12:30:09.786 exit receiveFunction : nr. of reads 301 <0x41001950> 36 02/28/08 12:30:09.787 thread finished <0x2ab49b058b40> 35 02/28/08 12:30:09.787 SerialConnection ------------- asa 3 <0x2ab49b058b40> 35 02/28/08 12:30:09.787 SerialConnection ------------- asa 4 <0x2ab49b058b40> 35 02/28/08 12:30:09.787 -------- 4 <0x2ab49b058b40> 35 02/28/08 12:30:10.055 SerialConnection ------------- 3 <0x2ab49b058b40> 35 02/28/08 12:30:10.055 SerialConnection --- destructor <0x2ab49b058b40> 35 02/28/08 12:30:10.055 SerialConnection ------------- 4 <0x2ab49b058b40> 10 02/28/08 12:30:10.055 Waiting for message queue thread to quit <0x2ab49b058b40> 10 02/28/08 12:30:10.055 Socket m_Socket 7/0x667590 Command_Impl1 Dev #33 m_bQuit=1 <0x2ab49b058b40> 10 02/28/08 12:30:10.055 Socket m_Socket 7/0x667590 Command_Impl1 Dev #33 m_bQuit=1 <0x2ab49b058b40> 13 02/28/08 12:30:10.055 Socket::Close() m_Socket 4 <0x2ab49b058b40> 13 02/28/08 12:30:10.055 Socket::Close() m_Socket 4 closesocket: 0 <0x2ab49b058b40> 13 02/28/08 12:30:10.055 Socket::Close() m_Socket 5 <0x2ab49b058b40> 13 02/28/08 12:30:10.055 Socket::Close() m_Socket 5 closesocket: 0 <0x2ab49b058b40> 10 02/28/08 12:30:10.055 Message queue thread quit <0x2ab49b058b40> 10 02/28/08 12:30:10.055 Message queue thread joined <0x2ab49b058b40> 10 02/28/08 12:30:10.055 About to call kill spawned devices <0x2ab49b058b40> 10 02/28/08 12:30:10.055 Need to kill 0 child devices <0x2ab49b058b40> 10 02/28/08 12:30:10.055 Killing completed. <0x2ab49b058b40> 13 02/28/08 12:30:10.056 Socket::~Socket(): deleting socket @0x67bb60 Event Dev #33 (socket id in destructor: m_Socket: -1) <0x2ab49b058b40> 13 02/28/08 12:30:10.057 Socket::~Socket(): deleting socket @0x67f560 Event Dev #33 (socket id in destructor: m_Socket: -1) <0x2ab49b058b40> 10 02/28/08 12:30:10.057 ~Command_Impl finished <0x2ab49b058b40> 13 02/28/08 12:30:10.057 ~HandleRequestSocket 0x667590 device: 33 ip: 127.0.0.1 <0x2ab49b058b40> 13 02/28/08 12:30:10.057 RequestSocket::Disconnect 0x667590 device: 33 <0x2ab49b058b40> 05 02/28/08 12:30:10.057 void ClientSocket::Disconnect() on this socket: 0x667590 (m_Socket: 7) <0x2ab49b058b40> 13 02/28/08 12:30:10.057 Socket::Close() m_Socket 7 <0x2ab49b058b40> 13 02/28/08 12:30:10.057 Socket::Close() m_Socket 7 closesocket: 0 <0x2ab49b058b40> 13 02/28/08 12:30:10.057 Socket::~Socket(): deleting socket @0x667590 Command_Impl1 Dev #33 (socket id in destructor: m_Socket: -1) <0x2ab49b058b40> 10 02/28/08 12:30:10.057 Device: 33 ending <0x2ab49b058b40> Return code: 2 2 02/28/08 12:30:10 33 (spawning-device) Device requests restart... count=1/50 dev=33 Thu Feb 28 12:30:10 EST 2008 Restart ========== NEW LOG SECTION ========== 1 02/28/08 12:30:18 33 (spawning-device) Starting... 1 1 02/28/08 12:30:18 33 (spawning-device) Found /usr/pluto/bin/ZWave 10 02/28/08 12:30:18.322 Device: 33 starting. Connecting to: localhost <0x2ab39ecfdb40> 10 02/28/08 12:30:18.348 Setting timeout for socket 4 to 20 <0x2ab39ecfdb40> 10 02/28/08 12:30:18.501 Socket::SendMessage type 5 id 37 from 33 to -1000 <0x2ab39ecfdb40> 10 02/28/08 12:30:18.608 TranslateSerialUSB found /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-5/1-5:1.0/ttyUSB0/ttyUSB0, returning /dev/ttyUSB0 <0x2ab39ecfdb40> 36 02/28/08 12:30:18.608 Using serial port: ttyUSB0. <0x2ab39ecfdb40> 36 02/28/08 12:30:18.630 SerialConnection::connect init serial mutex <0x2ab39ecfdb40> 36 02/28/08 12:30:18.630 receive thread created OK!!!! <0x2ab39ecfdb40> 35 02/28/08 12:30:18.632 entry point receiveFunction <0x41001950> 35 02/28/08 12:30:18.833 ++++++++++++ ZWave is connected <0x2ab39ecfdb40> 36 02/28/08 12:30:18.833 ### Run Current Job <0x41802950> 36 02/28/08 12:30:18.885 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:30:18.885 SerialConnection::send len = 2 buf = 0x00 0x15 <0x41802950> 36 02/28/08 12:30:18.885 SerialConnection::send unlock serial mutex <0x41802950> 05 02/28/08 12:30:23.013 ### Go to timeout queue <0x41802950> 05 02/28/08 12:30:23.013 ### execute the next job from timeout queue <0x41802950> 05 02/28/08 12:30:23.013 ZWJobInitialize::timeoutHandler <0x41802950> 36 02/28/08 12:30:23.065 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:30:23.065 SerialConnection::send len = 2 buf = 0x00 0x15 <0x41802950> 36 02/28/08 12:30:23.065 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:30:23.377 size too small 1 <0x41802950> 35 02/28/08 12:30:23.429 size too small 1 <0x41802950> 35 02/28/08 12:30:23.481 size too small 1 <0x41802950> 35 02/28/08 12:30:23.533 size too small 1 <0x41802950> 35 02/28/08 12:30:23.585 size too small 1 <0x41802950> 35 02/28/08 12:30:23.637 size too small 1 <0x41802950> 05 02/28/08 12:30:28.016 ### Go to timeout queue <0x41802950> 05 02/28/08 12:30:28.017 ### execute the next job from timeout queue <0x41802950> 05 02/28/08 12:30:28.017 ZWJobInitialize::timeoutHandler <0x41802950> 36 02/28/08 12:30:28.068 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:30:28.068 SerialConnection::send len = 2 buf = 0x00 0x15 <0x41802950> 36 02/28/08 12:30:28.068 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:30:28.276 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:30:28.276 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:30:28.276 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:30:28.277 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:30:28.277 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:30:28.277 receiveCommand::begin <0x41802950> 35 02/28/08 12:30:28.277 buffer.size()= 18 <0x41802950> 35 02/28/08 12:30:28.277 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:30:28.277 SerialConnection : received command len = 15 buf = 0x01 0x15 0x5a 0x2d 0x57 0x61 0x76 0x65 0x20 0x32 0x2e 0x32 0x34 0x00 0x01 <0x41802950> 35 02/28/08 12:30:28.277 ZWJobInitialize len = 15 buf = 0x01 0x15 0x5a 0x2d 0x57 0x61 0x76 0x65 0x20 0x32 0x2e 0x32 0x34 0x00 0x01 <0x41802950> 35 02/28/08 12:30:28.277 ZWJobGetVersion len = 15 buf = 0x01 0x15 0x5a 0x2d 0x57 0x61 0x76 0x65 0x20 0x32 0x2e 0x32 0x34 0x00 0x01 <0x41802950> 35 02/28/08 12:30:28.277 Z-Wave 2.24 <0x41802950> 36 02/28/08 12:30:28.328 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:30:28.328 SerialConnection::send len = 2 buf = 0x00 0x20 <0x41802950> 36 02/28/08 12:30:28.328 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:30:28.588 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:30:28.588 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:30:28.588 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:30:28.588 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:30:28.589 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:30:28.589 receiveCommand::begin <0x41802950> 35 02/28/08 12:30:28.589 buffer.size()= 10 <0x41802950> 35 02/28/08 12:30:28.589 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:30:28.589 SerialConnection : received command len = 7 buf = 0x01 0x20 0x00 0x01 0x14 0x7f 0x01 <0x41802950> 35 02/28/08 12:30:28.589 ZWJobInitialize len = 7 buf = 0x01 0x20 0x00 0x01 0x14 0x7f 0x01 <0x41802950> 35 02/28/08 12:30:28.589 ZWJobGetID len = 7 buf = 0x01 0x20 0x00 0x01 0x14 0x7f 0x01 <0x41802950> 36 02/28/08 12:30:28.640 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:30:28.640 SerialConnection::send len = 2 buf = 0x00 0x02 <0x41802950> 36 02/28/08 12:30:28.640 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:30:28.900 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:30:28.900 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:30:28.900 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:30:28.900 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:30:28.900 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:30:28.901 receiveCommand::begin <0x41802950> 35 02/28/08 12:30:28.901 buffer.size()= 39 <0x41802950> 35 02/28/08 12:30:28.901 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:30:28.901 SerialConnection : received command len = 36 buf = 0x01 0x02 0x04 0x00 0x1d 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x01 0x02 <0x41802950> 35 02/28/08 12:30:28.901 ZWJobInitialize len = 36 buf = 0x01 0x02 0x04 0x00 0x1d 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x01 0x02 <0x41802950> 35 02/28/08 12:30:28.901 ZWJobGetInitData len = 36 buf = 0x01 0x02 0x04 0x00 0x1d 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x01 0x02 <0x41802950> 36 02/28/08 12:30:28.952 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:30:28.952 SerialConnection::send len = 3 buf = 0x00 0x52 0x01 <0x41802950> 36 02/28/08 12:30:28.952 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:30:29.212 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:30:29.212 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:30:29.212 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:30:29.212 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:30:29.213 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:30:29.213 receiveCommand::begin <0x41802950> 35 02/28/08 12:30:29.213 buffer.size()= 6 <0x41802950> 35 02/28/08 12:30:29.213 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:30:29.213 SerialConnection : received command len = 3 buf = 0x01 0x52 0x01 <0x41802950> 35 02/28/08 12:30:29.213 ZWJobInitialize len = 3 buf = 0x01 0x52 0x01 <0x41802950> 35 02/28/08 12:30:29.213 ZWJobGetSUC len = 3 buf = 0x01 0x52 0x01 <0x41802950> 36 02/28/08 12:30:29.264 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:30:29.264 SerialConnection::send len = 2 buf = 0x00 0x56 <0x41802950> 36 02/28/08 12:30:29.264 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:30:29.524 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:30:29.524 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:30:29.524 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:30:29.524 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:30:29.524 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:30:29.525 receiveCommand::begin <0x41802950> 35 02/28/08 12:30:29.525 buffer.size()= 6 <0x41802950> 35 02/28/08 12:30:29.525 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:30:29.525 SerialConnection : received command len = 3 buf = 0x01 0x56 0x00 <0x41802950> 35 02/28/08 12:30:29.525 ZWJobInitialize len = 3 buf = 0x01 0x56 0x00 <0x41802950> 35 02/28/08 12:30:29.525 ZWJobGetSUC len = 3 buf = 0x01 0x56 0x00 <0x41802950> 36 02/28/08 12:30:29.576 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:30:29.576 SerialConnection::send len = 3 buf = 0x00 0x41 0x01 <0x41802950> 36 02/28/08 12:30:29.576 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:30:29.836 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:30:29.836 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:30:29.836 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:30:29.836 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:30:29.836 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:30:29.837 receiveCommand::begin <0x41802950> 35 02/28/08 12:30:29.837 buffer.size()= 11 <0x41802950> 35 02/28/08 12:30:29.837 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:30:29.837 SerialConnection : received command len = 8 buf = 0x01 0x41 0xca 0x06 0x00 0x02 0x02 0x01 <0x41802950> 35 02/28/08 12:30:29.837 ZWJobInitialize len = 8 buf = 0x01 0x41 0xca 0x06 0x00 0x02 0x02 0x01 <0x41802950> 35 02/28/08 12:30:29.837 ZWJobGetNodeProtocolInfo len = 8 buf = 0x01 0x41 0xca 0x06 0x00 0x02 0x02 0x01 <0x41802950> 35 02/28/08 12:30:29.837 ----- INIT ---- 3 <0x41802950> 35 02/28/08 12:30:29.837 ----- INIT ---- 1 <0x41802950> 35 02/28/08 12:30:29.837 ----- INIT ---- 2 <0x41802950> 36 02/28/08 12:30:29.837 ## Current Job Finished --- Left = 0 <0x41802950> 36 02/28/08 12:30:29.845 ZWave::ReportChildDevices trying to get list of devices <0x42003950> 36 02/28/08 12:30:29.845 ZWave::ReportChildDevices got: <0x42003950> 36 02/28/08 12:30:29.845 <0x42003950> 10 02/28/08 12:30:29.845 Socket::SendMessage type 2 id 54 from 33 to -1001 <0x42003950> 10 02/28/08 12:30:29.849 Connect OK <0x2ab39ecfdb40> 05 02/28/08 12:30:29.849 Creating child 34 <0x2ab39ecfdb40> 10 02/28/08 12:30:29.849 Got CreateEvent for unknown type 1820. <0x2ab39ecfdb40> 05 02/28/08 12:30:29.849 Note: Device manager has attached a device of type 1820 that this has no custom event handler for. It will not fire events. <0x2ab39ecfdb40> 10 02/28/08 12:30:29.849 Got CreateCommand for unknown type 1820. <0x2ab39ecfdb40> 05 02/28/08 12:30:29.849 Note: Device manager has attached a device of type 1820 that this has no custom handler for. This is normal for IR. <0x2ab39ecfdb40> 10 02/28/08 12:30:29.849 Requesthandler 0x667590 (device: 33) runThread now running <0x43005950> 10 02/28/08 12:30:36.827 Receive string: <0x43005950> 10 02/28/08 12:30:36.827 Received 0x667590 device: 33 <0x43005950> 10 02/28/08 12:38:55.722 Receive string: MESSAGE 73 <0x43005950> 10 02/28/08 12:38:55.722 Received MESSAGE 73 0x667590 device: 33 <0x43005950> 10 02/28/08 12:38:55.722 Received Message type 7 ID 0 from 0 to 33 (device: 33) resp 0 <0x43005950> 10 02/28/08 12:38:55.976 Command_Impl::OnQuit forwarding quit's to children <0x43005950> 10 02/28/08 12:38:55.976 Socket m_Socket 7/0x667590 Command_Impl1 Dev #33 m_bQuit=1 <0x43005950> 10 02/28/08 12:38:55.976 Requesthandler 0x667590 (device: 33) Closing request handler connection <0x43005950> 13 02/28/08 12:38:55.977 Exiting BeginHandleRequestThread thread... <0x43005950> 13 02/28/08 12:38:55.978 Exiting MessageQueueThread_DCECI thread... <0x42804950> 35 02/28/08 12:38:55.979 -------- 3 <0x2ab39ecfdb40> 35 02/28/08 12:38:55.979 SerialConnection ------------- asa 1 <0x2ab39ecfdb40> 35 02/28/08 12:38:56.091 SerialConnection ------------- asa 2 <0x2ab39ecfdb40> 36 02/28/08 12:38:56.091 waiting for thread to finish <0x2ab39ecfdb40> 35 02/28/08 12:38:56.091 exit receiveFunction : nr. of reads 1683 <0x41001950> 36 02/28/08 12:38:56.091 thread finished <0x2ab39ecfdb40> 35 02/28/08 12:38:56.091 SerialConnection ------------- asa 3 <0x2ab39ecfdb40> 35 02/28/08 12:38:56.091 SerialConnection ------------- asa 4 <0x2ab39ecfdb40> 35 02/28/08 12:38:56.091 -------- 4 <0x2ab39ecfdb40> 35 02/28/08 12:38:56.359 SerialConnection ------------- 3 <0x2ab39ecfdb40> 35 02/28/08 12:38:56.359 SerialConnection --- destructor <0x2ab39ecfdb40> 35 02/28/08 12:38:56.359 SerialConnection ------------- 4 <0x2ab39ecfdb40> 10 02/28/08 12:38:56.359 Waiting for message queue thread to quit <0x2ab39ecfdb40> 10 02/28/08 12:38:56.359 Socket m_Socket 7/0x667590 Command_Impl1 Dev #33 m_bQuit=1 <0x2ab39ecfdb40> 10 02/28/08 12:38:56.359 Socket m_Socket 7/0x667590 Command_Impl1 Dev #33 m_bQuit=1 <0x2ab39ecfdb40> 13 02/28/08 12:38:56.359 Socket::Close() m_Socket 4 <0x2ab39ecfdb40> 13 02/28/08 12:38:56.359 Socket::Close() m_Socket 4 closesocket: 0 <0x2ab39ecfdb40> 13 02/28/08 12:38:56.360 Socket::Close() m_Socket 5 <0x2ab39ecfdb40> 13 02/28/08 12:38:56.360 Socket::Close() m_Socket 5 closesocket: 0 <0x2ab39ecfdb40> 10 02/28/08 12:38:56.360 Message queue thread quit <0x2ab39ecfdb40> 10 02/28/08 12:38:56.360 Message queue thread joined <0x2ab39ecfdb40> 10 02/28/08 12:38:56.360 About to call kill spawned devices <0x2ab39ecfdb40> 10 02/28/08 12:38:56.360 Need to kill 0 child devices <0x2ab39ecfdb40> 10 02/28/08 12:38:56.360 Killing completed. <0x2ab39ecfdb40> 13 02/28/08 12:38:56.361 Socket::~Socket(): deleting socket @0x67bb60 Event Dev #33 (socket id in destructor: m_Socket: -1) <0x2ab39ecfdb40> 13 02/28/08 12:38:56.361 Socket::~Socket(): deleting socket @0x67f560 Event Dev #33 (socket id in destructor: m_Socket: -1) <0x2ab39ecfdb40> 10 02/28/08 12:38:56.361 ~Command_Impl finished <0x2ab39ecfdb40> 13 02/28/08 12:38:56.361 ~HandleRequestSocket 0x667590 device: 33 ip: 127.0.0.1 <0x2ab39ecfdb40> 13 02/28/08 12:38:56.361 RequestSocket::Disconnect 0x667590 device: 33 <0x2ab39ecfdb40> 05 02/28/08 12:38:56.361 void ClientSocket::Disconnect() on this socket: 0x667590 (m_Socket: 7) <0x2ab39ecfdb40> 13 02/28/08 12:38:56.361 Socket::Close() m_Socket 7 <0x2ab39ecfdb40> 13 02/28/08 12:38:56.361 Socket::Close() m_Socket 7 closesocket: 0 <0x2ab39ecfdb40> 13 02/28/08 12:38:56.361 Socket::~Socket(): deleting socket @0x667590 Command_Impl1 Dev #33 (socket id in destructor: m_Socket: -1) <0x2ab39ecfdb40> 10 02/28/08 12:38:56.361 Device: 33 ending <0x2ab39ecfdb40> Return code: 0 2 02/28/08 12:38:56 33 (spawning-device) Shutting down... count=1/50 dev=33 Thu Feb 28 12:38:56 EST 2008 Shutdown == ATTEMPT FRESH START == 1 02/28/08 12:42:27 /usr/pluto/bin/Spawn_Device.sh 33 (spawning-device) 12262 Dev: 33; Already Running list: 15,16,17,18,28, == FRESH START == 1 02/28/08 12:42:27 /usr/pluto/bin/Spawn_Device.sh 33 (spawning-device) device: 33 ip: localhost cmd_line: ZWave 0 02/28/08 12:42:27 33 (spawning-device) Entering 33 ========== NEW LOG SECTION ========== 1 02/28/08 12:42:27 33 (spawning-device) Starting... 1 1 02/28/08 12:42:27 33 (spawning-device) Found /usr/pluto/bin/ZWave 10 02/28/08 12:42:27.297 Device: 33 starting. Connecting to: localhost <0x2b23631fcb40> 10 02/28/08 12:42:27.300 Setting timeout for socket 4 to 20 <0x2b23631fcb40> 10 02/28/08 12:42:27.387 Socket::SendMessage type 5 id 37 from 33 to -1000 <0x2b23631fcb40> 10 02/28/08 12:42:27.442 TranslateSerialUSB found /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-5/1-5:1.0/ttyUSB0/ttyUSB0, returning /dev/ttyUSB0 <0x2b23631fcb40> 36 02/28/08 12:42:27.443 Using serial port: ttyUSB0. <0x2b23631fcb40> 36 02/28/08 12:42:27.456 SerialConnection::connect init serial mutex <0x2b23631fcb40> 36 02/28/08 12:42:27.456 receive thread created OK!!!! <0x2b23631fcb40> 35 02/28/08 12:42:27.456 entry point receiveFunction <0x41001950> 35 02/28/08 12:42:27.662 ++++++++++++ ZWave is connected <0x2b23631fcb40> 36 02/28/08 12:42:27.663 ### Run Current Job <0x41802950> 36 02/28/08 12:42:27.718 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:42:27.718 SerialConnection::send len = 2 buf = 0x00 0x15 <0x41802950> 36 02/28/08 12:42:27.719 SerialConnection::send unlock serial mutex <0x41802950> 05 02/28/08 12:42:32.030 ### Go to timeout queue <0x41802950> 05 02/28/08 12:42:32.030 ### execute the next job from timeout queue <0x41802950> 05 02/28/08 12:42:32.030 ZWJobInitialize::timeoutHandler <0x41802950> 36 02/28/08 12:42:32.086 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:42:32.190 SerialConnection::send len = 2 buf = 0x00 0x15 <0x41802950> 36 02/28/08 12:42:32.190 SerialConnection::send unlock serial mutex <0x41802950> 05 02/28/08 12:42:37.018 ### Go to timeout queue <0x41802950> 05 02/28/08 12:42:37.018 ### execute the next job from timeout queue <0x41802950> 05 02/28/08 12:42:37.018 ZWJobInitialize::timeoutHandler <0x41802950> 36 02/28/08 12:42:37.074 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:42:37.118 SerialConnection::send len = 2 buf = 0x00 0x15 <0x41802950> 36 02/28/08 12:42:37.118 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:42:37.454 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:42:37.454 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:42:37.454 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:42:37.454 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:42:37.454 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:42:37.454 receiveCommand::begin <0x41802950> 35 02/28/08 12:42:37.454 buffer.size()= 18 <0x41802950> 35 02/28/08 12:42:37.454 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:42:37.454 SerialConnection : received command len = 15 buf = 0x01 0x15 0x5a 0x2d 0x57 0x61 0x76 0x65 0x20 0x32 0x2e 0x32 0x34 0x00 0x01 <0x41802950> 35 02/28/08 12:42:37.454 ZWJobInitialize len = 15 buf = 0x01 0x15 0x5a 0x2d 0x57 0x61 0x76 0x65 0x20 0x32 0x2e 0x32 0x34 0x00 0x01 <0x41802950> 35 02/28/08 12:42:37.454 ZWJobGetVersion len = 15 buf = 0x01 0x15 0x5a 0x2d 0x57 0x61 0x76 0x65 0x20 0x32 0x2e 0x32 0x34 0x00 0x01 <0x41802950> 35 02/28/08 12:42:37.455 Z-Wave 2.24 <0x41802950> 36 02/28/08 12:42:37.510 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:42:37.510 SerialConnection::send len = 2 buf = 0x00 0x20 <0x41802950> 36 02/28/08 12:42:37.510 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:42:37.734 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:42:37.734 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:42:37.734 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:42:37.734 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:42:37.734 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:42:37.734 receiveCommand::begin <0x41802950> 35 02/28/08 12:42:37.734 buffer.size()= 10 <0x41802950> 35 02/28/08 12:42:37.734 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:42:37.734 SerialConnection : received command len = 7 buf = 0x01 0x20 0x00 0x01 0x14 0x7f 0x01 <0x41802950> 35 02/28/08 12:42:37.734 ZWJobInitialize len = 7 buf = 0x01 0x20 0x00 0x01 0x14 0x7f 0x01 <0x41802950> 35 02/28/08 12:42:37.734 ZWJobGetID len = 7 buf = 0x01 0x20 0x00 0x01 0x14 0x7f 0x01 <0x41802950> 36 02/28/08 12:42:37.790 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:42:37.790 SerialConnection::send len = 2 buf = 0x00 0x02 <0x41802950> 36 02/28/08 12:42:37.790 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:42:38.074 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:42:38.074 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:42:38.074 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:42:38.074 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:42:38.074 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:42:38.074 receiveCommand::begin <0x41802950> 35 02/28/08 12:42:38.074 buffer.size()= 39 <0x41802950> 35 02/28/08 12:42:38.074 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:42:38.074 SerialConnection : received command len = 36 buf = 0x01 0x02 0x04 0x00 0x1d 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x01 0x02 <0x41802950> 35 02/28/08 12:42:38.074 ZWJobInitialize len = 36 buf = 0x01 0x02 0x04 0x00 0x1d 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x01 0x02 <0x41802950> 35 02/28/08 12:42:38.074 ZWJobGetInitData len = 36 buf = 0x01 0x02 0x04 0x00 0x1d 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x01 0x02 <0x41802950> 36 02/28/08 12:42:38.130 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:42:38.130 SerialConnection::send len = 3 buf = 0x00 0x52 0x01 <0x41802950> 36 02/28/08 12:42:38.130 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:42:38.354 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:42:38.354 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:42:38.354 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:42:38.354 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:42:38.354 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:42:38.354 receiveCommand::begin <0x41802950> 35 02/28/08 12:42:38.354 buffer.size()= 6 <0x41802950> 35 02/28/08 12:42:38.354 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:42:38.354 SerialConnection : received command len = 3 buf = 0x01 0x52 0x01 <0x41802950> 35 02/28/08 12:42:38.354 ZWJobInitialize len = 3 buf = 0x01 0x52 0x01 <0x41802950> 35 02/28/08 12:42:38.354 ZWJobGetSUC len = 3 buf = 0x01 0x52 0x01 <0x41802950> 36 02/28/08 12:42:38.411 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:42:38.411 SerialConnection::send len = 2 buf = 0x00 0x56 <0x41802950> 36 02/28/08 12:42:38.411 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:42:38.690 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:42:38.690 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:42:38.690 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:42:38.690 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:42:38.690 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:42:38.690 receiveCommand::begin <0x41802950> 35 02/28/08 12:42:38.690 buffer.size()= 6 <0x41802950> 35 02/28/08 12:42:38.690 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:42:38.690 SerialConnection : received command len = 3 buf = 0x01 0x56 0x00 <0x41802950> 35 02/28/08 12:42:38.690 ZWJobInitialize len = 3 buf = 0x01 0x56 0x00 <0x41802950> 35 02/28/08 12:42:38.690 ZWJobGetSUC len = 3 buf = 0x01 0x56 0x00 <0x41802950> 36 02/28/08 12:42:38.746 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:42:38.746 SerialConnection::send len = 3 buf = 0x00 0x41 0x01 <0x41802950> 36 02/28/08 12:42:38.746 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:42:38.970 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:42:38.970 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:42:38.970 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:42:38.970 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:42:38.970 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:42:38.970 receiveCommand::begin <0x41802950> 35 02/28/08 12:42:38.970 buffer.size()= 11 <0x41802950> 35 02/28/08 12:42:38.970 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:42:38.970 SerialConnection : received command len = 8 buf = 0x01 0x41 0xca 0x06 0x00 0x02 0x02 0x01 <0x41802950> 35 02/28/08 12:42:38.970 ZWJobInitialize len = 8 buf = 0x01 0x41 0xca 0x06 0x00 0x02 0x02 0x01 <0x41802950> 35 02/28/08 12:42:38.970 ZWJobGetNodeProtocolInfo len = 8 buf = 0x01 0x41 0xca 0x06 0x00 0x02 0x02 0x01 <0x41802950> 35 02/28/08 12:42:38.970 ----- INIT ---- 3 <0x41802950> 35 02/28/08 12:42:38.970 ----- INIT ---- 1 <0x41802950> 35 02/28/08 12:42:38.970 ----- INIT ---- 2 <0x41802950> 36 02/28/08 12:42:38.970 ## Current Job Finished --- Left = 0 <0x41802950> 36 02/28/08 12:42:38.979 ZWave::ReportChildDevices trying to get list of devices <0x42003950> 36 02/28/08 12:42:38.979 ZWave::ReportChildDevices got: <0x42003950> 36 02/28/08 12:42:38.979 <0x42003950> 10 02/28/08 12:42:38.979 Socket::SendMessage type 2 id 54 from 33 to -1001 <0x42003950> 10 02/28/08 12:42:38.980 Connect OK <0x2b23631fcb40> 05 02/28/08 12:42:38.980 Creating child 34 <0x2b23631fcb40> 10 02/28/08 12:42:38.980 Got CreateEvent for unknown type 1820. <0x2b23631fcb40> 05 02/28/08 12:42:38.981 Note: Device manager has attached a device of type 1820 that this has no custom event handler for. It will not fire events. <0x2b23631fcb40> 10 02/28/08 12:42:38.981 Got CreateCommand for unknown type 1820. <0x2b23631fcb40> 05 02/28/08 12:42:38.981 Note: Device manager has attached a device of type 1820 that this has no custom handler for. This is normal for IR. <0x2b23631fcb40> 10 02/28/08 12:42:38.981 Requesthandler 0x667590 (device: 33) runThread now running <0x43005950> 10 02/28/08 12:42:41.156 Receive string: <0x43005950> 10 02/28/08 12:42:41.156 Received 0x667590 device: 33 <0x43005950> 10 02/28/08 12:42:43.542 Receive string: <0x43005950> 10 02/28/08 12:42:43.542 Received 0x667590 device: 33 <0x43005950> 10 02/28/08 12:42:44.565 Receive string: <0x43005950> 10 02/28/08 12:42:44.565 Received 0x667590 device: 33 <0x43005950> 10 02/28/08 12:42:45.581 Receive string: <0x43005950> 10 02/28/08 12:42:45.581 Received 0x667590 device: 33 <0x43005950> 10 02/28/08 12:43:41.796 Receive string: <0x43005950> 10 02/28/08 12:43:41.796 Received 0x667590 device: 33 <0x43005950> 10 02/28/08 12:43:42.984 Receive string: <0x43005950> 10 02/28/08 12:43:42.984 Received 0x667590 device: 33 <0x43005950> 10 02/28/08 12:43:44.000 Receive string: <0x43005950> 10 02/28/08 12:43:44.000 Received 0x667590 device: 33 <0x43005950> 10 02/28/08 12:43:45.017 Receive string: <0x43005950> 10 02/28/08 12:43:45.017 Received 0x667590 device: 33 <0x43005950> 10 02/28/08 12:45:46.318 Receive string: <0x43005950> 10 02/28/08 12:45:46.318 Received 0x667590 device: 33 <0x43005950> 10 02/28/08 12:45:48.724 Receive string: MESSAGE 72 <0x43005950> 10 02/28/08 12:45:48.724 Received MESSAGE 72 0x667590 device: 33 <0x43005950> 10 02/28/08 12:45:48.724 Received Message type 1 ID 757 from 20 to 33 (device: 33) resp 3 <0x43005950> 36 02/28/08 12:45:48.729 ZWave::DownloadConfiguration trying to get list of devices <0x43806950> 35 02/28/08 12:45:48.729 -------- 3 <0x43806950> 35 02/28/08 12:45:48.729 SerialConnection ------------- asa 1 <0x43806950> 35 02/28/08 12:45:48.836 exit receiveFunction : nr. of reads 655 <0x41001950> 35 02/28/08 12:45:48.836 SerialConnection ------------- asa 2 <0x43806950> 36 02/28/08 12:45:48.836 waiting for thread to finish <0x43806950> 36 02/28/08 12:45:48.836 thread finished <0x43806950> 35 02/28/08 12:45:48.836 SerialConnection ------------- asa 3 <0x43806950> 35 02/28/08 12:45:48.836 SerialConnection ------------- asa 4 <0x43806950> 35 02/28/08 12:45:48.836 -------- 4 <0x43806950> 36 02/28/08 12:45:48.849 SerialConnection::connect init serial mutex <0x43806950> 36 02/28/08 12:45:48.849 receive thread created OK!!!! <0x43806950> 35 02/28/08 12:45:48.849 entry point receiveFunction <0x40800950> 35 02/28/08 12:45:49.052 ++++++++++++ ZWave is connected <0x43806950> 36 02/28/08 12:45:49.064 ### Run Current Job <0x41802950> 36 02/28/08 12:45:49.116 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:45:49.116 SerialConnection::send len = 7 buf = 0x00 0x03 0x01 0x02 0x01 0x01 0x21 <0x41802950> 36 02/28/08 12:45:49.116 SerialConnection::send unlock serial mutex <0x41802950> 36 02/28/08 12:45:49.672 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:45:49.672 SerialConnection::send len = 3 buf = 0x00 0x42 0x01 <0x41802950> 36 02/28/08 12:45:49.672 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:45:49.724 size too small 1 <0x41802950> 35 02/28/08 12:45:49.776 size too small 1 <0x41802950> 35 02/28/08 12:45:49.828 size too small 1 <0x41802950> 35 02/28/08 12:45:49.880 size too small 2 <0x41802950> 35 02/28/08 12:45:49.932 size too small 2 <0x41802950> 35 02/28/08 12:45:49.984 size too small 2 <0x41802950> 35 02/28/08 12:45:50.036 size too small 2 <0x41802950> 35 02/28/08 12:45:50.088 size too small 2 <0x41802950> 35 02/28/08 12:45:50.140 size too small 2 <0x41802950> 35 02/28/08 12:45:50.192 size too small 2 <0x41802950> 35 02/28/08 12:45:50.244 size too small 2 <0x41802950> 35 02/28/08 12:45:50.296 size too small 2 <0x41802950> 35 02/28/08 12:45:50.348 size too small 2 <0x41802950> 35 02/28/08 12:45:50.400 size too small 2 <0x41802950> 35 02/28/08 12:45:50.454 size too small 2 <0x41802950> 35 02/28/08 12:45:50.508 size too small 2 <0x41802950> 35 02/28/08 12:45:50.560 size too small 2 <0x41802950> 35 02/28/08 12:45:50.614 size too small 2 <0x41802950> 35 02/28/08 12:45:50.668 size too small 2 <0x41802950> 35 02/28/08 12:45:50.720 size too small 2 <0x41802950> 35 02/28/08 12:45:50.775 size too small 2 <0x41802950> 35 02/28/08 12:45:50.828 size too small 2 <0x41802950> 35 02/28/08 12:45:50.880 size too small 2 <0x41802950> 35 02/28/08 12:45:50.932 size too small 2 <0x41802950> 35 02/28/08 12:45:50.987 size too small 2 <0x41802950> 35 02/28/08 12:45:51.039 size too small 2 <0x41802950> 35 02/28/08 12:45:51.094 size too small 2 <0x41802950> 35 02/28/08 12:45:51.147 size too small 2 <0x41802950> 35 02/28/08 12:45:51.199 size too small 2 <0x41802950> 35 02/28/08 12:45:51.255 size too small 2 <0x41802950> 35 02/28/08 12:45:51.307 size too small 2 <0x41802950> 35 02/28/08 12:45:51.359 size too small 2 <0x41802950> 35 02/28/08 12:45:51.415 size too small 2 <0x41802950> 35 02/28/08 12:45:51.468 size too small 2 <0x41802950> 35 02/28/08 12:45:51.520 size too small 2 <0x41802950> 35 02/28/08 12:45:51.571 size too small 2 <0x41802950> 35 02/28/08 12:45:51.623 size too small 2 <0x41802950> 35 02/28/08 12:45:51.675 size too small 2 <0x41802950> 35 02/28/08 12:45:51.728 size too small 2 <0x41802950> 35 02/28/08 12:45:51.783 size too small 2 <0x41802950> 35 02/28/08 12:45:51.835 size too small 2 <0x41802950> 35 02/28/08 12:45:51.887 size too small 2 <0x41802950> 35 02/28/08 12:45:51.939 size too small 2 <0x41802950> 35 02/28/08 12:45:51.991 size too small 2 <0x41802950> 35 02/28/08 12:45:52.043 size too small 2 <0x41802950> 35 02/28/08 12:45:52.095 size too small 2 <0x41802950> 35 02/28/08 12:45:52.147 size too small 2 <0x41802950> 35 02/28/08 12:45:52.204 size too small 2 <0x41802950> 35 02/28/08 12:45:52.259 size too small 2 <0x41802950> 35 02/28/08 12:45:52.311 size too small 2 <0x41802950> 35 02/28/08 12:45:52.363 size too small 2 <0x41802950> 35 02/28/08 12:45:52.415 size too small 2 <0x41802950> 35 02/28/08 12:45:52.467 size too small 2 <0x41802950> 35 02/28/08 12:45:52.519 size too small 2 <0x41802950> 35 02/28/08 12:45:52.571 size too small 2 <0x41802950> 35 02/28/08 12:45:52.623 size too small 2 <0x41802950> 35 02/28/08 12:45:52.675 size too small 2 <0x41802950> 35 02/28/08 12:45:52.727 size too small 2 <0x41802950> 35 02/28/08 12:45:52.779 size too small 2 <0x41802950> 35 02/28/08 12:45:52.831 size too small 2 <0x41802950> 35 02/28/08 12:45:52.883 size too small 2 <0x41802950> 35 02/28/08 12:45:52.935 size too small 2 <0x41802950> 10 02/28/08 12:45:56.027 Socket::SendMessage type 2 id 55 from 33 to -1001 <0x43806950> 05 02/28/08 12:45:56.035 -------------------------- Job Timeout _________ <0x41802950> 35 02/28/08 12:45:57.555 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:45:57.555 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:45:57.555 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:45:57.555 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:45:57.555 receiveCommand::begin <0x41802950> 35 02/28/08 12:45:57.555 buffer.size()= 6 <0x41802950> 35 02/28/08 12:45:57.555 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:45:57.556 SerialConnection : received command len = 3 buf = 0x00 0x42 0x01 <0x41802950> 10 02/28/08 12:51:02.501 Receive string: MESSAGE 73 <0x43005950> 10 02/28/08 12:51:02.501 Received MESSAGE 73 0x667590 device: 33 <0x43005950> 10 02/28/08 12:51:02.501 Received Message type 7 ID 1 from 0 to 33 (device: 33) resp 0 <0x43005950> 05 02/28/08 12:51:02.501 Got a reload command from 0  <0x43005950> 10 02/28/08 12:51:02.757 Command_Impl::OnReload 33 <0x43005950> 10 02/28/08 12:51:02.757 Socket m_Socket 7/0x667590 Command_Impl1 Dev #33 m_bQuit=1 <0x43005950> 10 02/28/08 12:51:02.757 Requesthandler 0x667590 (device: 33) Closing request handler connection <0x43005950> 13 02/28/08 12:51:02.757 Exiting BeginHandleRequestThread thread... <0x43005950> 13 02/28/08 12:51:02.758 Exiting MessageQueueThread_DCECI thread... <0x42804950> 35 02/28/08 12:51:02.758 -------- 3 <0x2b23631fcb40> 35 02/28/08 12:51:02.758 SerialConnection ------------- asa 1 <0x2b23631fcb40> 35 02/28/08 12:51:02.866 SerialConnection ------------- asa 2 <0x2b23631fcb40> 36 02/28/08 12:51:02.866 waiting for thread to finish <0x2b23631fcb40> 35 02/28/08 12:51:02.956 exit receiveFunction : nr. of reads 1022 <0x40800950> 36 02/28/08 12:51:02.957 thread finished <0x2b23631fcb40> 35 02/28/08 12:51:02.957 SerialConnection ------------- asa 3 <0x2b23631fcb40> 35 02/28/08 12:51:02.957 SerialConnection ------------- asa 4 <0x2b23631fcb40> 35 02/28/08 12:51:02.957 -------- 4 <0x2b23631fcb40> 35 02/28/08 12:51:03.224 SerialConnection ------------- 3 <0x2b23631fcb40> 35 02/28/08 12:51:03.224 SerialConnection --- destructor <0x2b23631fcb40> 35 02/28/08 12:51:03.224 SerialConnection ------------- 4 <0x2b23631fcb40> 10 02/28/08 12:51:03.224 Waiting for message queue thread to quit <0x2b23631fcb40> 10 02/28/08 12:51:03.224 Socket m_Socket 7/0x667590 Command_Impl1 Dev #33 m_bQuit=1 <0x2b23631fcb40> 10 02/28/08 12:51:03.224 Socket m_Socket 7/0x667590 Command_Impl1 Dev #33 m_bQuit=1 <0x2b23631fcb40> 13 02/28/08 12:51:03.224 Socket::Close() m_Socket 4 <0x2b23631fcb40> 13 02/28/08 12:51:03.224 Socket::Close() m_Socket 4 closesocket: 0 <0x2b23631fcb40> 13 02/28/08 12:51:03.224 Socket::Close() m_Socket 5 <0x2b23631fcb40> 13 02/28/08 12:51:03.224 Socket::Close() m_Socket 5 closesocket: 0 <0x2b23631fcb40> 10 02/28/08 12:51:03.224 Message queue thread quit <0x2b23631fcb40> 10 02/28/08 12:51:03.225 Message queue thread joined <0x2b23631fcb40> 10 02/28/08 12:51:03.225 About to call kill spawned devices <0x2b23631fcb40> 10 02/28/08 12:51:03.225 Need to kill 0 child devices <0x2b23631fcb40> 10 02/28/08 12:51:03.225 Killing completed. <0x2b23631fcb40> 13 02/28/08 12:51:03.226 Socket::~Socket(): deleting socket @0x67bb60 Event Dev #33 (socket id in destructor: m_Socket: -1) <0x2b23631fcb40> 13 02/28/08 12:51:03.226 Socket::~Socket(): deleting socket @0x67f560 Event Dev #33 (socket id in destructor: m_Socket: -1) <0x2b23631fcb40> 10 02/28/08 12:51:03.226 ~Command_Impl finished <0x2b23631fcb40> 13 02/28/08 12:51:03.226 ~HandleRequestSocket 0x667590 device: 33 ip: 127.0.0.1 <0x2b23631fcb40> 13 02/28/08 12:51:03.226 RequestSocket::Disconnect 0x667590 device: 33 <0x2b23631fcb40> 05 02/28/08 12:51:03.226 void ClientSocket::Disconnect() on this socket: 0x667590 (m_Socket: 7) <0x2b23631fcb40> 13 02/28/08 12:51:03.226 Socket::Close() m_Socket 7 <0x2b23631fcb40> 13 02/28/08 12:51:03.226 Socket::Close() m_Socket 7 closesocket: 0 <0x2b23631fcb40> 13 02/28/08 12:51:03.226 Socket::~Socket(): deleting socket @0x667590 Command_Impl1 Dev #33 (socket id in destructor: m_Socket: -1) <0x2b23631fcb40> 10 02/28/08 12:51:03.226 Device: 33 ending <0x2b23631fcb40> Return code: 2 2 02/28/08 12:51:03 33 (spawning-device) Device requests restart... count=1/50 dev=33 Thu Feb 28 12:51:03 EST 2008 Restart ========== NEW LOG SECTION ========== 1 02/28/08 12:51:11 33 (spawning-device) Starting... 1 1 02/28/08 12:51:11 33 (spawning-device) Found /usr/pluto/bin/ZWave 10 02/28/08 12:51:11.381 Device: 33 starting. Connecting to: localhost <0x2b384c87fb40> 10 02/28/08 12:51:11.386 Setting timeout for socket 4 to 20 <0x2b384c87fb40> 10 02/28/08 12:51:11.475 Socket::SendMessage type 5 id 37 from 33 to -1000 <0x2b384c87fb40> 10 02/28/08 12:51:11.679 TranslateSerialUSB found /sys/devices/pci0000:00/0000:00:0b.0/usb1/1-5/1-5:1.0/ttyUSB0/ttyUSB0, returning /dev/ttyUSB0 <0x2b384c87fb40> 36 02/28/08 12:51:11.680 Using serial port: ttyUSB0. <0x2b384c87fb40> 36 02/28/08 12:51:11.690 SerialConnection::connect init serial mutex <0x2b384c87fb40> 36 02/28/08 12:51:11.691 receive thread created OK!!!! <0x2b384c87fb40> 35 02/28/08 12:51:11.691 entry point receiveFunction <0x41001950> 35 02/28/08 12:51:11.895 ++++++++++++ ZWave is connected <0x2b384c87fb40> 36 02/28/08 12:51:11.895 ### Run Current Job <0x41802950> 36 02/28/08 12:51:11.955 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:51:11.955 SerialConnection::send len = 2 buf = 0x00 0x15 <0x41802950> 36 02/28/08 12:51:11.955 SerialConnection::send unlock serial mutex <0x41802950> 05 02/28/08 12:51:16.003 ### Go to timeout queue <0x41802950> 05 02/28/08 12:51:16.003 ### execute the next job from timeout queue <0x41802950> 05 02/28/08 12:51:16.003 ZWJobInitialize::timeoutHandler <0x41802950> 36 02/28/08 12:51:16.059 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:51:16.107 SerialConnection::send len = 2 buf = 0x00 0x15 <0x41802950> 36 02/28/08 12:51:16.107 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:51:16.443 size too small 1 <0x41802950> 35 02/28/08 12:51:16.499 size too small 1 <0x41802950> 35 02/28/08 12:51:16.555 size too small 1 <0x41802950> 35 02/28/08 12:51:16.611 size too small 1 <0x41802950> 35 02/28/08 12:51:16.667 size too small 1 <0x41802950> 05 02/28/08 12:51:21.034 ### Go to timeout queue <0x41802950> 05 02/28/08 12:51:21.034 ### execute the next job from timeout queue <0x41802950> 05 02/28/08 12:51:21.034 ZWJobInitialize::timeoutHandler <0x41802950> 36 02/28/08 12:51:21.090 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:51:21.090 SerialConnection::send len = 2 buf = 0x00 0x15 <0x41802950> 36 02/28/08 12:51:21.090 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:51:21.370 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:51:21.370 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:51:21.370 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:51:21.370 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:51:21.370 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:51:21.371 receiveCommand::begin <0x41802950> 35 02/28/08 12:51:21.371 buffer.size()= 18 <0x41802950> 35 02/28/08 12:51:21.371 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:51:21.371 SerialConnection : received command len = 15 buf = 0x01 0x15 0x5a 0x2d 0x57 0x61 0x76 0x65 0x20 0x32 0x2e 0x32 0x34 0x00 0x01 <0x41802950> 35 02/28/08 12:51:21.371 ZWJobInitialize len = 15 buf = 0x01 0x15 0x5a 0x2d 0x57 0x61 0x76 0x65 0x20 0x32 0x2e 0x32 0x34 0x00 0x01 <0x41802950> 35 02/28/08 12:51:21.371 ZWJobGetVersion len = 15 buf = 0x01 0x15 0x5a 0x2d 0x57 0x61 0x76 0x65 0x20 0x32 0x2e 0x32 0x34 0x00 0x01 <0x41802950> 35 02/28/08 12:51:21.371 Z-Wave 2.24 <0x41802950> 36 02/28/08 12:51:21.426 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:51:21.426 SerialConnection::send len = 2 buf = 0x00 0x20 <0x41802950> 36 02/28/08 12:51:21.426 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:51:21.650 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:51:21.650 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:51:21.650 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:51:21.650 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:51:21.651 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:51:21.651 receiveCommand::begin <0x41802950> 35 02/28/08 12:51:21.651 buffer.size()= 10 <0x41802950> 35 02/28/08 12:51:21.651 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:51:21.651 SerialConnection : received command len = 7 buf = 0x01 0x20 0x00 0x01 0x14 0x7f 0x01 <0x41802950> 35 02/28/08 12:51:21.651 ZWJobInitialize len = 7 buf = 0x01 0x20 0x00 0x01 0x14 0x7f 0x01 <0x41802950> 35 02/28/08 12:51:21.651 ZWJobGetID len = 7 buf = 0x01 0x20 0x00 0x01 0x14 0x7f 0x01 <0x41802950> 36 02/28/08 12:51:21.706 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:51:21.706 SerialConnection::send len = 2 buf = 0x00 0x02 <0x41802950> 36 02/28/08 12:51:21.706 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:51:21.986 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:51:21.986 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:51:21.986 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:51:21.986 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:51:21.986 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:51:21.987 receiveCommand::begin <0x41802950> 35 02/28/08 12:51:21.987 buffer.size()= 39 <0x41802950> 35 02/28/08 12:51:21.987 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:51:21.987 SerialConnection : received command len = 36 buf = 0x01 0x02 0x04 0x00 0x1d 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x01 0x02 <0x41802950> 35 02/28/08 12:51:21.987 ZWJobInitialize len = 36 buf = 0x01 0x02 0x04 0x00 0x1d 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x01 0x02 <0x41802950> 35 02/28/08 12:51:21.987 ZWJobGetInitData len = 36 buf = 0x01 0x02 0x04 0x00 0x1d 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x01 0x02 <0x41802950> 36 02/28/08 12:51:22.042 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:51:22.042 SerialConnection::send len = 3 buf = 0x00 0x52 0x01 <0x41802950> 36 02/28/08 12:51:22.042 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:51:22.266 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:51:22.266 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:51:22.266 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:51:22.266 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:51:22.266 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:51:22.267 receiveCommand::begin <0x41802950> 35 02/28/08 12:51:22.267 buffer.size()= 6 <0x41802950> 35 02/28/08 12:51:22.267 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:51:22.267 SerialConnection : received command len = 3 buf = 0x01 0x52 0x01 <0x41802950> 35 02/28/08 12:51:22.267 ZWJobInitialize len = 3 buf = 0x01 0x52 0x01 <0x41802950> 35 02/28/08 12:51:22.267 ZWJobGetSUC len = 3 buf = 0x01 0x52 0x01 <0x41802950> 36 02/28/08 12:51:22.322 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:51:22.322 SerialConnection::send len = 2 buf = 0x00 0x56 <0x41802950> 36 02/28/08 12:51:22.322 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:51:22.602 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:51:22.602 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:51:22.602 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:51:22.602 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:51:22.602 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:51:22.603 receiveCommand::begin <0x41802950> 35 02/28/08 12:51:22.603 buffer.size()= 6 <0x41802950> 35 02/28/08 12:51:22.603 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:51:22.603 SerialConnection : received command len = 3 buf = 0x01 0x56 0x00 <0x41802950> 35 02/28/08 12:51:22.603 ZWJobInitialize len = 3 buf = 0x01 0x56 0x00 <0x41802950> 35 02/28/08 12:51:22.603 ZWJobGetSUC len = 3 buf = 0x01 0x56 0x00 <0x41802950> 36 02/28/08 12:51:22.658 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 12:51:22.658 SerialConnection::send len = 3 buf = 0x00 0x41 0x01 <0x41802950> 36 02/28/08 12:51:22.658 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 12:51:22.882 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 12:51:22.882 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 12:51:22.882 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 12:51:22.882 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 12:51:22.882 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 12:51:22.883 receiveCommand::begin <0x41802950> 35 02/28/08 12:51:22.883 buffer.size()= 11 <0x41802950> 35 02/28/08 12:51:22.883 receiveCommand: eat another command <0x41802950> 35 02/28/08 12:51:22.883 SerialConnection : received command len = 8 buf = 0x01 0x41 0xca 0x06 0x00 0x02 0x02 0x01 <0x41802950> 35 02/28/08 12:51:22.883 ZWJobInitialize len = 8 buf = 0x01 0x41 0xca 0x06 0x00 0x02 0x02 0x01 <0x41802950> 35 02/28/08 12:51:22.883 ZWJobGetNodeProtocolInfo len = 8 buf = 0x01 0x41 0xca 0x06 0x00 0x02 0x02 0x01 <0x41802950> 35 02/28/08 12:51:22.883 ----- INIT ---- 3 <0x41802950> 35 02/28/08 12:51:22.883 ----- INIT ---- 1 <0x41802950> 35 02/28/08 12:51:22.883 ----- INIT ---- 2 <0x41802950> 36 02/28/08 12:51:22.883 ## Current Job Finished --- Left = 0 <0x41802950> 36 02/28/08 12:51:22.891 ZWave::ReportChildDevices trying to get list of devices <0x42003950> 36 02/28/08 12:51:22.891 ZWave::ReportChildDevices got: <0x42003950> 36 02/28/08 12:51:22.891 <0x42003950> 10 02/28/08 12:51:22.891 Socket::SendMessage type 2 id 54 from 33 to -1001 <0x42003950> 10 02/28/08 12:51:22.893 Connect OK <0x2b384c87fb40> 05 02/28/08 12:51:22.893 Creating child 34 <0x2b384c87fb40> 10 02/28/08 12:51:22.893 Got CreateEvent for unknown type 1820. <0x2b384c87fb40> 05 02/28/08 12:51:22.893 Note: Device manager has attached a device of type 1820 that this has no custom event handler for. It will not fire events. <0x2b384c87fb40> 10 02/28/08 12:51:22.893 Got CreateCommand for unknown type 1820. <0x2b384c87fb40> 05 02/28/08 12:51:22.893 Note: Device manager has attached a device of type 1820 that this has no custom handler for. This is normal for IR. <0x2b384c87fb40> 10 02/28/08 12:51:22.893 Requesthandler 0x667590 (device: 33) runThread now running <0x43005950> 10 02/28/08 12:51:29.688 Receive string: <0x43005950> 10 02/28/08 12:51:29.688 Received 0x667590 device: 33 <0x43005950> 10 02/28/08 13:02:38.108 Receive string: MESSAGE 81 <0x43005950> 10 02/28/08 13:02:38.108 Received MESSAGE 81 0x667590 device: 33 <0x43005950> 10 02/28/08 13:02:38.108 Received Message type 1 ID 760 from 0 to 33 (device: 33) resp 0 <0x43005950> 36 02/28/08 13:02:38.108 ZWave::CMD_Send_Command_To_Child <0x43005950> 36 02/28/08 13:02:38.108 Sending Off - 1 <0x43005950> 36 02/28/08 13:02:38.112 ### Run Current Job <0x41802950> 36 02/28/08 13:02:38.164 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 13:02:38.164 SerialConnection::send len = 9 buf = 0x00 0x13 0x01 0x03 0x25 0x01 0x00 0x05 0x01 <0x41802950> 36 02/28/08 13:02:38.164 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 13:02:38.268 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 13:02:38.268 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 13:02:38.268 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 13:02:38.268 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 13:02:38.268 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 13:02:38.268 receiveCommand::begin <0x41802950> 35 02/28/08 13:02:38.268 buffer.size()= 6 <0x41802950> 35 02/28/08 13:02:38.268 receiveCommand: eat another command <0x41802950> 35 02/28/08 13:02:38.268 SerialConnection : received command len = 3 buf = 0x01 0x13 0x01 <0x41802950> 35 02/28/08 13:02:38.268 ZWJobSwitchChangeLevel: len = 3 buf = 0x01 0x13 0x01 <0x41802950> 35 02/28/08 13:02:38.588 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 13:02:38.588 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 13:02:38.588 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 13:02:38.588 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 13:02:38.588 receiveCommand::begin <0x41802950> 35 02/28/08 13:02:38.588 buffer.size()= 7 <0x41802950> 35 02/28/08 13:02:38.588 receiveCommand: eat another command <0x41802950> 35 02/28/08 13:02:38.588 SerialConnection : received command len = 4 buf = 0x00 0x13 0x01 0x01 <0x41802950> 35 02/28/08 13:02:38.588 ZWJobSwitchChangeLevel: len = 4 buf = 0x00 0x13 0x01 0x01 <0x41802950> 35 02/28/08 13:02:38.588 ZWJobSwitchChangeLevel: processData the tx status is here <0x41802950> 05 02/28/08 13:02:38.588 command not ack, device not reachable <0x41802950> 36 02/28/08 13:02:38.588 ## Current Job Finished --- Left = 0 <0x41802950> 10 02/28/08 13:02:54.296 Receive string: MESSAGE 81 <0x43005950> 10 02/28/08 13:02:54.296 Received MESSAGE 81 0x667590 device: 33 <0x43005950> 10 02/28/08 13:02:54.296 Received Message type 1 ID 760 from 0 to 33 (device: 33) resp 0 <0x43005950> 36 02/28/08 13:02:54.297 ZWave::CMD_Send_Command_To_Child <0x43005950> 36 02/28/08 13:02:54.297 Sending Off - 1 <0x43005950> 36 02/28/08 13:02:54.299 ### Run Current Job <0x41802950> 36 02/28/08 13:02:54.351 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 13:02:54.351 SerialConnection::send len = 9 buf = 0x00 0x13 0x01 0x03 0x25 0x01 0x00 0x05 0x02 <0x41802950> 36 02/28/08 13:02:54.351 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 13:02:54.558 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 13:02:54.559 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 13:02:54.559 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 13:02:54.559 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 13:02:54.559 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 13:02:54.559 receiveCommand::begin <0x41802950> 35 02/28/08 13:02:54.559 buffer.size()= 6 <0x41802950> 35 02/28/08 13:02:54.559 receiveCommand: eat another command <0x41802950> 35 02/28/08 13:02:54.559 SerialConnection : received command len = 3 buf = 0x01 0x13 0x01 <0x41802950> 35 02/28/08 13:02:54.559 ZWJobSwitchChangeLevel: len = 3 buf = 0x01 0x13 0x01 <0x41802950> 35 02/28/08 13:02:54.870 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 13:02:54.871 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 13:02:54.871 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 13:02:54.871 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 13:02:54.871 receiveCommand::begin <0x41802950> 35 02/28/08 13:02:54.871 buffer.size()= 7 <0x41802950> 35 02/28/08 13:02:54.871 receiveCommand: eat another command <0x41802950> 35 02/28/08 13:02:54.871 SerialConnection : received command len = 4 buf = 0x00 0x13 0x02 0x01 <0x41802950> 35 02/28/08 13:02:54.871 ZWJobSwitchChangeLevel: len = 4 buf = 0x00 0x13 0x02 0x01 <0x41802950> 35 02/28/08 13:02:54.871 ZWJobSwitchChangeLevel: processData the tx status is here <0x41802950> 05 02/28/08 13:02:54.871 command not ack, device not reachable <0x41802950> 36 02/28/08 13:02:54.871 ## Current Job Finished --- Left = 0 <0x41802950> 10 02/28/08 13:03:51.576 Receive string: MESSAGE 81 <0x43005950> 10 02/28/08 13:03:51.576 Received MESSAGE 81 0x667590 device: 33 <0x43005950> 10 02/28/08 13:03:51.576 Received Message type 1 ID 760 from 0 to 33 (device: 33) resp 0 <0x43005950> 36 02/28/08 13:03:51.576 ZWave::CMD_Send_Command_To_Child <0x43005950> 36 02/28/08 13:03:51.576 Sending Off - 1 <0x43005950> 36 02/28/08 13:03:51.624 ### Run Current Job <0x41802950> 36 02/28/08 13:03:51.678 SerialConnection::send lock serial mutex <0x41802950> 35 02/28/08 13:03:51.710 SerialConnection::send len = 9 buf = 0x00 0x13 0x01 0x03 0x25 0x01 0x00 0x05 0x03 <0x41802950> 36 02/28/08 13:03:51.711 SerialConnection::send unlock serial mutex <0x41802950> 35 02/28/08 13:03:52.046 SerialConnection::hasCommand() popping ACK <0x41802950> 35 02/28/08 13:03:52.046 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 13:03:52.047 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 13:03:52.047 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 13:03:52.047 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 13:03:52.047 receiveCommand::begin <0x41802950> 35 02/28/08 13:03:52.047 buffer.size()= 6 <0x41802950> 35 02/28/08 13:03:52.047 receiveCommand: eat another command <0x41802950> 35 02/28/08 13:03:52.047 SerialConnection : received command len = 3 buf = 0x01 0x13 0x01 <0x41802950> 35 02/28/08 13:03:52.047 ZWJobSwitchChangeLevel: len = 3 buf = 0x01 0x13 0x01 <0x41802950> 35 02/28/08 13:03:52.358 SerialConnection::hasCommand() front is SOF <0x41802950> 35 02/28/08 13:03:52.358 SerialConnection::hasCommand lock serial mutex <0x41802950> 35 02/28/08 13:03:52.358 SerialConnection::hasCommand wrote ack <0x41802950> 35 02/28/08 13:03:52.358 SerialConnection::hasCommand unlock serial mutex <0x41802950> 35 02/28/08 13:03:52.359 receiveCommand::begin <0x41802950> 35 02/28/08 13:03:52.359 buffer.size()= 7 <0x41802950> 35 02/28/08 13:03:52.359 receiveCommand: eat another command <0x41802950> 35 02/28/08 13:03:52.359 SerialConnection : received command len = 4 buf = 0x00 0x13 0x03 0x01 <0x41802950> 35 02/28/08 13:03:52.359 ZWJobSwitchChangeLevel: len = 4 buf = 0x00 0x13 0x03 0x01 <0x41802950> 35 02/28/08 13:03:52.359 ZWJobSwitchChangeLevel: processData the tx status is here <0x41802950> 05 02/28/08 13:03:52.359 command not ack, device not reachable <0x41802950> 36 02/28/08 13:03:52.359 ## Current Job Finished --- Left = 0 <0x41802950>