LinuxMCE Forums
General => Users => Topic started by: davegravy on March 02, 2010, 05:53:31 am
-
This problem started immediately after apt-get updating to the latest build. I assume it is related to these changes http://svn.linuxmce.org/trac.cgi/ticket/620 (http://svn.linuxmce.org/trac.cgi/ticket/620).
All my zwave devices (lights) have ceased to function. I have reloaded, rebooted, removed and replaced my MCV Zwave dongle, gone through the setup, reloaded, rebooted - nothing has resolved the issue.
Here is my zwave log during a router reload: http://pastebin.com/mypBjfm6 (http://pastebin.com/mypBjfm6)
The DCERouter.log is huge (3+ MB) so if you think a section would be useful, let me know what you need.
Thanks in advance,
Dave
-
I did an sqlcvs update on the dce repository, reloaded the router, no luck.
-
I can't see any problems with the log, maybe you can post the log after you try to turn on or off some lights?
Edit: BTW, the "BAD PARAMETER" in the log can be ignored.
Edit: ok, found the problem.
sambuca
-
You didn't say you fixed the problem but I assume the zwave update yesterday was to resolve this. I ran the update today, rebooted and the problem persists. Gotta run to work now but I'll post logs later today.
-
I just finished a full reinstall and the problem remains. I did however make a new discovery: if I repeatedly select a lighting command (sometimes it takes 30 or 40 clicks) the command eventually suceeds. Sometimes if I click a few times and wait 30 seconds to a minute, the command succeeds, other times not.
All other functions of the core (play media, send ir and rs232 commands, etc) have normal responsiveness.
I'll post logs of what's happening shortly.
-
Here's the log for one command execution:
36 03/11/10 10:02:39.803 Received command for child <0xb6911b90>
36 03/11/10 10:02:39.803 OFF RECEIVED FOR CHILD 4 <0xb6911b90>
40 03/11/10 10:02:39.806 Sending job 0x9cd8aa0 (cb 27) - 0x1 0xa 0x0 0x13 0x4 0x3 0x20 0x1 0x0 0x5 0x1b 0xde (#\n#### #####) <0xb7913b90>
41 03/11/10 10:02:39.814 0x1 0x4 0x1 0x13 0x1 0xe8 (######) <0xb7913b90>
36 03/11/10 10:02:39.814 ZW_SEND delivered to Z-Wave stack <0xb7913b90>
41 03/11/10 10:02:40.194 0x1 0x5 0x0 0x13 0x1b 0x1 0xf3 (#######) <0xb7913b90>
36 03/11/10 10:02:40.194 ZW_SEND Response with callback 27 received <0xb7913b90>
36 03/11/10 10:02:40.194 Error: ZW_SEND failed, retrying <0xb7913b90>
40 03/11/10 10:02:40.294 Sending job 0x9cd8aa0 (cb 27) - 0x1 0xa 0x0 0x13 0x4 0x3 0x20 0x1 0x0 0x5 0x1b 0xde (#\n#### #####) <0xb7913b90>
41 03/11/10 10:02:40.302 0x1 0x4 0x1 0x13 0x1 0xe8 (######) <0xb7913b90>
36 03/11/10 10:02:40.302 ZW_SEND delivered to Z-Wave stack <0xb7913b90>
41 03/11/10 10:02:40.314 0x1 0x5 0x0 0x13 0x1b 0x0 0xf2 (#######) <0xb7913b90>
36 03/11/10 10:02:40.314 ZW_SEND Response with callback 27 received <0xb7913b90>
36 03/11/10 10:02:40.314 ZW_SEND was successful, removing job <0xb7913b90>
10 03/11/10 10:02:44.286 Receive string: MESSAGE 75 <0xb6911b90>
10 03/11/10 10:02:44.287 Received MESSAGE 75 0x9ca6040 device: 33 <0xb6911b90>
10 03/11/10 10:02:44.287 Received Message type 1 ID 193 from 44 to 37 (device: 33) resp 0 <0xb 6911b90>
36 03/11/10 10:02:44.287 Received command for child <0xb6911b90>
36 03/11/10 10:02:44.287 OFF RECEIVED FOR CHILD 4 <0xb6911b90>
40 03/11/10 10:02:44.314 Sending job 0x9cd8cc0 (cb 28) - 0x1 0xa 0x0 0x13 0x4 0x3 0x20 0x1 0x0 0x5 0x1c 0xd9 (#\n#### #####) <0xb7913b90>
41 03/11/10 10:02:44.322 0x1 0x4 0x1 0x13 0x1 0xe8 (######) <0xb7913b90>
36 03/11/10 10:02:44.322 ZW_SEND delivered to Z-Wave stack <0xb7913b90>
41 03/11/10 10:02:44.826 0x1 0x5 0x0 0x13 0x1c 0x1 0xf4 (#######) <0xb7913b90>
36 03/11/10 10:02:44.826 ZW_SEND Response with callback 28 received <0xb7913b90>
36 03/11/10 10:02:44.826 Error: ZW_SEND failed, retrying <0xb7913b90>
40 03/11/10 10:02:44.926 Sending job 0x9cd8cc0 (cb 28) - 0x1 0xa 0x0 0x13 0x4 0x3 0x20 0x1 0x0 0x5 0x1c 0xd9 (#\n#### #####) <0xb7913b90>
41 03/11/10 10:02:44.934 0x1 0x4 0x1 0x13 0x1 0xe8 (######) <0xb7913b90>
36 03/11/10 10:02:44.934 ZW_SEND delivered to Z-Wave stack <0xb7913b90>
41 03/11/10 10:02:45.358 0x1 0x5 0x0 0x13 0x1c 0x1 0xf4 (#######) <0xb7913b90>
36 03/11/10 10:02:45.358 ZW_SEND Response with callback 28 received <0xb7913b90>
36 03/11/10 10:02:45.358 Error: ZW_SEND failed, retrying <0xb7913b90>
40 03/11/10 10:02:45.458 Sending job 0x9cd8cc0 (cb 28) - 0x1 0xa 0x0 0x13 0x4 0x3 0x20 0x1 0x0 0x5 0x1c 0xd9 (#\n#### #####) <0xb7913b90>
41 03/11/10 10:02:45.466 0x1 0x4 0x1 0x13 0x1 0xe8 (######) <0xb7913b90>
36 03/11/10 10:02:45.466 ZW_SEND delivered to Z-Wave stack <0xb7913b90>
41 03/11/10 10:02:45.930 0x1 0x5 0x0 0x13 0x1c 0x1 0xf4 (#######) <0xb7913b90>
36 03/11/10 10:02:45.930 ZW_SEND Response with callback 28 received <0xb7913b90>
36 03/11/10 10:02:45.930 Error: ZW_SEND failed, retrying <0xb7913b90>
40 03/11/10 10:02:46.030 Sending job 0x9cd8cc0 (cb 28) - 0x1 0xa 0x0 0x13 0x4 0x3 0x20 0x1 0x0 0x5 0x1c 0xd9 (#\n#### #####) <0xb7913b90>
41 03/11/10 10:02:46.038 0x1 0x4 0x1 0x13 0x1 0xe8 (######) <0xb7913b90>
36 03/11/10 10:02:46.038 ZW_SEND delivered to Z-Wave stack <0xb7913b90>
41 03/11/10 10:02:46.462 0x1 0x5 0x0 0x13 0x1c 0x1 0xf4 (#######) <0xb7913b90>
36 03/11/10 10:02:46.462 ZW_SEND Response with callback 28 received <0xb7913b90>
36 03/11/10 10:02:46.462 Error: ZW_SEND failed, removing job after three tries <0xb7913b90>
36 03/11/10 10:03:16.562 We have been idle for 30 seconds, polling device states <0xb7913b90>
40 03/11/10 10:03:16.662 Sending job 0x9cd8ee0 (cb 29) - 0x1 0x9 0x0 0x13 0xff 0x2 0x20 0x2 0x5 0x1d 0x22 (###### ###") <0xb7913b90>
41 03/11/10 10:03:16.667 0x1 0x4 0x1 0x13 0x1 0xe8 (######) <0xb7913b90>
36 03/11/10 10:03:16.667 ZW_SEND delivered to Z-Wave stack <0xb7913b90>
41 03/11/10 10:03:16.690 0x1 0x5 0x0 0x13 0x1d 0x0 0xf4 (#######) <0xb7913b90>
36 03/11/10 10:03:16.690 ZW_SEND Response with callback 29 received <0xb7913b90>
36 03/11/10 10:03:16.690 ZW_SEND was successful, removing job <0xb7913b90>
41 03/11/10 10:03:16.714 0x1 0x9 0x0 0x4 0x0 0x4 0x3 0x20 0x3 0x63 0xb5 (####### #c#) <0xb7913b90>
36 03/11/10 10:03:16.714 FUNC_ID_APPLICATION_COMMAND_HANDLER: <0xb7913b90>
36 03/11/10 10:03:16.714 COMMAND_CLASS_BASIC - <0xb7913b90>
36 03/11/10 10:03:16.714 Got basic report from node 4, value: 99 <0xb7913b90>
40 03/11/10 10:03:16.814 Sending job 0x9cd9100 (cb 30) - 0x1 0x9 0x0 0x13 0xff 0x2 0x31 0x4 0x5 0x1e 0x36 (######1###6) <0xb7913b90>
41 03/11/10 10:03:16.818 0x1 0x4 0x1 0x13 0x1 0xe8 (######) <0xb7913b90>
36 03/11/10 10:03:16.818 ZW_SEND delivered to Z-Wave stack <0xb7913b90>
41 03/11/10 10:03:16.842 0x1 0x5 0x0 0x13 0x1e 0x0 0xf7 (#######) <0xb7913b90>
36 03/11/10 10:03:16.842 ZW_SEND Response with callback 30 received <0xb7913b90>
36 03/11/10 10:03:16.842 ZW_SEND was successful, removing job <0xb7913b90>
Here's another one:
36 03/11/10 10:07:35.892 Received command for child <0xb6911b90>
36 03/11/10 10:07:35.892 OFF RECEIVED FOR CHILD 4 <0xb6911b90>
40 03/11/10 10:07:35.922 Sending job 0x9cdb960 (cb 49) - 0x1 0xa 0x0 0x13 0x4 0x3 0x20 0x1 0x0 0x5 0x31 0xf4 (#\n#### ###1#) <0xb7913b90>
41 03/11/10 10:07:35.930 0x1 0x4 0x1 0x13 0x1 0xe8 (######) <0xb7913b90>
36 03/11/10 10:07:35.930 ZW_SEND delivered to Z-Wave stack <0xb7913b90>
41 03/11/10 10:07:36.010 0x1 0x5 0x0 0x13 0x31 0x0 0xd8 (####1##) <0xb7913b90>
36 03/11/10 10:07:36.010 ZW_SEND Response with callback 49 received <0xb7913b90>
36 03/11/10 10:07:36.010 ZW_SEND was successful, removing job <0xb7913b90>
Sometimes it works after one try, other times after two, sometimes it fails after three attempts.
I'm going to start a ticket.
-
Hi
From your log it seems there is some problem sending the ZWave command. I'm not familiar with that part of the ZWave code, but as it sometimes work and sometimes not, I would say its more of a communications issue than a code issue.
Hari is the person behind the ZWave driver so maybe he can help with interpreting the logs.
best regards,
sambuca
-
Thanks Sambuca.
Below is is the 33_ZWave.log and DCERouter.log during a failed command.
DCERouter.log:
21 03/11/10 13:30:44.473 lock(0x8247e40) (>34646) interceptor: DCERouter.cpp:884 <0x7e1cbb90>
21 03/11/10 13:30:44.473 acquired(0x8247e40) #0 (>34646) interceptor DCERouter.cpp:884 <0x7e1cbb90>
21 03/11/10 13:30:44.473 unlock(0x8247e40) #0 (>34646) interceptor: DCERouter.cpp:884 <0x7e1cbb90>
10 03/11/10 13:30:44.473 DCERouter calling message interceptor for msg type 1 id 193, device 8 <0x7e1cbb90>
10 03/11/10 13:30:44.474 Executed query UPDATE Device SET State='OFF/0',psc_mod=psc_mod WHERE PK_Device=37 (0 rows) <0x7e1cbb90>
21 03/11/10 13:30:44.474 lock(0x8295bfc) (>34648) Lighting Mutex: Lighting_Plugin.cpp:446 <0x7e1cbb90>
21 03/11/10 13:30:44.474 acquired(0x8295bfc) #0 (>34648) Lighting Mutex Lighting_Plugin.cpp:446 <0x7e1cbb90>
21 03/11/10 13:30:44.474 unlock(0x8295bfc) #0 (>34648) Lighting Mutex: Lighting_Plugin.cpp:446 <0x7e1cbb90>
21 03/11/10 13:30:44.474 removed from map (0x8295bfc) #0 (>34648) Lighting Mutex: Lighting_Plugin.cpp:446 was: 107 size, now 106 Rel: Y Got: Y <0x7e1cbb90>
21 03/11/10 13:30:44.474 removed from map (0x8247e40) #0 (>34646) interceptor: DCERouter.cpp:884 was: 106 size, now 105 Rel: Y Got: Y <0x7e1cbb90>
08 03/11/10 13:30:44.474 Received Message from 44 (Windows XP PC/tablet (Horiz) / Home Theater) to Table Lamp(37), type 1 id 193 Command:Off, retry none, parameters: <0x7e1cbb90>
08 03/11/10 13:30:44.475 Parameter 97(PK_Pipe): <0x7e1cbb90>
21 03/11/10 13:30:44.475 lock(0x8247e7c) (>34649) messagequeue: DCERouter.cpp:1847 <0x7e1cbb90>
21 03/11/10 13:30:44.475 acquired(0x8247e7c) #0 (>34649) messagequeue DCERouter.cpp:1847 <0x7e1cbb90>
10 03/11/10 13:30:44.475 AddMessageToQueue(ProcessQueue) adding message from 44 to -2002 type 1 id 193 to queue size was: 0 <0x7e1cbb90>
21 03/11/10 13:30:44.475 unlock(0x8247e7c) #0 (>34649) messagequeue: DCERouter.cpp:1847 <0x7e1cbb90>
21 03/11/10 13:30:44.475 end cond wait DCERouter.cpp:1862 (0x8247e7c) <0xb6d21b90>
10 03/11/10 13:30:44.475 ProcessQueue woke up with size: 1 <0xb6d21b90>
10 03/11/10 13:30:44.475 ProcessQueue sending message from 44 to -2002 type 1 id 193 to queue now size: 0 <0xb6d21b90>
21 03/11/10 13:30:44.475 unlock(0x8247e7c) #0 (>2) messagequeue: DCERouter.cpp:1862 <0xb6d21b90>
10 03/11/10 13:30:44.475 ProcessQueue Calling realsendmessage from queue <0xb6d21b90>
10 03/11/10 13:30:44.475 begin realsendmessage before lock <0xb6d21b90>
21 03/11/10 13:30:44.475 lock(0x8247e04) (>34650) core: DCERouter.cpp:2140 <0xb6d21b90>
21 03/11/10 13:30:44.475 acquired(0x8247e04) #0 (>34650) core DCERouter.cpp:2140 <0xb6d21b90>
10 03/11/10 13:30:44.475 realsendmessage from 44 to 37 type 1 id 193 <0xb6d21b90>
21 03/11/10 13:30:44.475 unlock(0x8247e04) #0 (>34650) core: DCERouter.cpp:2140 <0xb6d21b90>
10 03/11/10 13:30:44.475 realsendmessage after core release from 44 to 37 type 1 id 193 <0xb6d21b90>
21 03/11/10 13:30:44.475 lock(0x8247c98) (>34651) listener Router Dev #0: ../DCE/SocketListener.h:96 <0xb6d21b90>
21 03/11/10 13:30:44.475 acquired(0x8247c98) #0 (>34651) listener Router Dev #0 ../DCE/SocketListener.h:96 <0xb6d21b90>
21 03/11/10 13:30:44.475 unlock(0x8247c98) #0 (>34651) listener Router Dev #0: ../DCE/SocketListener.h:96 <0xb6d21b90>
21 03/11/10 13:30:44.475 removed from map (0x8247c98) #0 (>34651) listener Router Dev #0: ../DCE/SocketListener.h:96 was: 108 size, now 107 Rel: Y Got: Y <0xb6d21b90>
10 03/11/10 13:30:44.475 realsendmessage before device conn mutex from 44 to 37 type 1 id 193 <0xb6d21b90>
13 03/11/10 13:30:44.475 Ready to send message type 1 id 193 to 33 ZWave on socket 130(0x83387d0) using lock: 0x83388b4 <0xb6d21b90>
21 03/11/10 13:30:44.475 lock(0x83388c4) (>34652) connection Incoming_Conn Socket 157 127.0.0.1 dev 33: DCERouter.cpp:2198 Device 33 ZWave <0xb6d21b90>
21 03/11/10 13:30:44.475 acquired(0x83388c4) #0 (>34652) connection Incoming_Conn Socket 157 127.0.0.1 dev 33 DCERouter.cpp:2198 Device 33 ZWave <0xb6d21b90>
10 03/11/10 13:30:44.475 realsendmessage after device conn mutex from 44 to 37 type 1 id 193 <0xb6d21b90>
10 03/11/10 13:30:44.475 Socket::SendMessage type 1 id 193 from 44 to 37 <0xb6d21b90>
13 03/11/10 13:30:44.476 Response 1 to realsendmessage type 1 id 193 socket 157 using lock: 0x83388b4 expected response: 0 <0xb6d21b90>
13 03/11/10 13:30:44.476 Got response: 1 to message type 1 id 193 to 33 ZWave on socket 157 using lock: 0x83388b4 <0xb6d21b90>
13 03/11/10 13:30:44.476 No response expected. returning <0xb6d21b90>
21 03/11/10 13:30:44.476 unlock(0x83388c4) #0 (>34652) connection Incoming_Conn Socket 157 127.0.0.1 dev 33: DCERouter.cpp:2198 Device 33 ZWave <0xb6d21b90>
21 03/11/10 13:30:44.476 removed from map (0x83388c4) #0 (>34652) connection Incoming_Conn Socket 157 127.0.0.1 dev 33: DCERouter.cpp:2198 Device 33 ZWave was: 108 size, now 107 Rel: Y Got: Y <0xb6d21b90>
21 03/11/10 13:30:44.476 removed from map (0x8247e04) #0 (>34650) core: DCERouter.cpp:2140 was: 107 size, now 106 Rel: Y Got: Y <0xb6d21b90>
21 03/11/10 13:30:44.476 relocking (0x8247e7c) (>2) <0xb6d21b90>
21 03/11/10 13:30:44.476 lock(0x8247e7c) (>2) messagequeue: DCERouter.cpp:1862 <0xb6d21b90>
21 03/11/10 13:30:44.476 acquired(0x8247e7c) #0 (>2) messagequeue DCERouter.cpp:1862 <0xb6d21b90>
10 03/11/10 13:30:44.476 ProcessQueue finished Calling realsendmessage from queue <0xb6d21b90>
10 03/11/10 13:30:44.476 ProcessQueue going to sleep <0xb6d21b90>
21 03/11/10 13:30:44.476 start cond wait DCERouter.cpp:1862 (0x8247e7c) <0xb6d21b90>
10 03/11/10 13:30:44.476 AddMessageToQueue(ProcessQueue) sent broadcast <0x7e1cbb90>
21 03/11/10 13:30:44.476 removed from map (0x8247e7c) #0 (>34649) messagequeue: DCERouter.cpp:1847 was: 106 size, now 105 Rel: Y Got: Y <0x7e1cbb90>
21 03/11/10 13:30:50.000 end cond timed at 1268332250.23000 wait result: 110 AlarmManager.cpp:102 (0x9822d174) <0x969fcb90>
21 03/11/10 13:30:50.000 unlock(0x9822d174) #0 (>3496) alarm: AlarmManager.cpp:102 <0x969fcb90>
12 03/11/10 13:30:50.000 Calling callback for alarm 0x9822d130 id 5 param=(nil) entry->when: 1268332250 time: 1268332249 <0x969fcb90>
21 03/11/10 13:30:50.000 lock(0xa3c299d4) (>34655) Media Plugin: MythTV_PlugIn.cpp:2730 <0x969fcb90>
21 03/11/10 13:30:50.000 acquired(0xa3c299d4) #0 (>34655) Media Plugin MythTV_PlugIn.cpp:2730 <0x969fcb90>
21 03/11/10 13:30:50.000 lock(0xa3c299d4) (>34656) Media Plugin: MythBackEnd_Socket.cpp:181 <0x969fcb90>
21 03/11/10 13:30:50.000 acquired(0xa3c299d4) #1 (>34656) Media Plugin MythBackEnd_Socket.cpp:181 <0x969fcb90>
21 03/11/10 13:30:50.000 unlock(0xa3c299d4) #1 (>34656) Media Plugin: MythBackEnd_Socket.cpp:181 <0x969fcb90>
21 03/11/10 13:30:50.000 removed from map (0xa3c299d4) #1 (>34656) Media Plugin: MythBackEnd_Socket.cpp:181 was: 108 size, now 107 Rel: Y Got: Y <0x969fcb90>
21 03/11/10 13:30:50.000 lock(0xa3c299d4) (>34658) Media Plugin: MythBackEnd_Socket.cpp:59 <0x969fcb90>
21 03/11/10 13:30:50.001 acquired(0xa3c299d4) #1 (>34658) Media Plugin MythBackEnd_Socket.cpp:59 <0x969fcb90>
21 03/11/10 13:30:50.001 lock(0xa3c299d4) (>34659) Media Plugin: MythBackEnd_Socket.cpp:204 <0x969fcb90>
21 03/11/10 13:30:50.001 acquired(0xa3c299d4) #2 (>34659) Media Plugin MythBackEnd_Socket.cpp:204 <0x969fcb90>
21 03/11/10 13:30:50.001 unlock(0xa3c299d4) #2 (>34659) Media Plugin: MythBackEnd_Socket.cpp:204 <0x969fcb90>
21 03/11/10 13:30:50.001 removed from map (0xa3c299d4) #2 (>34659) Media Plugin: MythBackEnd_Socket.cpp:204 was: 109 size, now 108 Rel: Y Got: Y <0x969fcb90>
21 03/11/10 13:30:50.054 unlock(0xa3c299d4) #1 (>34658) Media Plugin: MythBackEnd_Socket.cpp:59 <0x969fcb90>
21 03/11/10 13:30:50.054 removed from map (0xa3c299d4) #1 (>34658) Media Plugin: MythBackEnd_Socket.cpp:59 was: 108 size, now 107 Rel: Y Got: Y <0x969fcb90>
10 03/11/10 13:30:50.054 MythTV_PlugIn::ConfirmMasterBackendOk got 39390 <0x969fcb90>
35 03/11/10 13:30:50.054 MythBackEnd_Socket::ProcessIncomingString 39390 <0x969fcb90>
12 03/11/10 13:30:50.054 Cancel Alarm by type: 5 <0x969fcb90>
21 03/11/10 13:30:50.054 lock(0x9822d174) (>34677) alarm: AlarmManager.cpp:309 <0x969fcb90>
21 03/11/10 13:30:50.054 acquired(0x9822d174) #0 (>34677) alarm AlarmManager.cpp:309 <0x969fcb90>
21 03/11/10 13:30:50.054 end cond timed at 1268332250.54103000 wait result: 0 AlarmManager.cpp:102 (0x9822d174) <0x961fbb90>
12 03/11/10 13:30:50.054 Alarm manager notified of a change <0x961fbb90>
21 03/11/10 13:30:50.054 start cond 0x9822d1ac timed wait till 1268333885.0 now 1268332250.54175000 AlarmManager.cpp:102 (0x9822d174) <0x961fbb90>
21 03/11/10 13:30:50.054 unlock(0x9822d174) #0 (>34677) alarm: AlarmManager.cpp:309 <0x969fcb90>
21 03/11/10 13:30:50.054 removed from map (0x9822d174) #0 (>34677) alarm: AlarmManager.cpp:309 was: 108 size, now 107 Rel: Y Got: Y <0x969fcb90>
10 03/11/10 13:30:50.054 AlarmManager::AddRelativeAlarm current time 1268332250 delay 30 type 5 <0x969fcb90>
10 03/11/10 13:30:50.054 AlarmManager::AddAbsoluteAlarm time 1268332280 type 5 <0x969fcb90>
21 03/11/10 13:30:50.054 lock(0x9822d174) (>34678) alarm: AlarmManager.cpp:185 <0x969fcb90>
21 03/11/10 13:30:50.054 acquired(0x9822d174) #0 (>34678) alarm AlarmManager.cpp:185 <0x969fcb90>
21 03/11/10 13:30:50.055 end cond timed at 1268332250.54526000 wait result: 0 AlarmManager.cpp:102 (0x9822d174) <0x961fbb90>
12 03/11/10 13:30:50.055 Alarm manager notified of a change <0x961fbb90>
21 03/11/10 13:30:50.055 start cond 0x9822d1ac timed wait till 1268332280.0 now 1268332250.54593000 AlarmManager.cpp:102 (0x9822d174) <0x961fbb90>
21 03/11/10 13:30:50.055 unlock(0x9822d174) #0 (>34678) alarm: AlarmManager.cpp:185 <0x969fcb90>
21 03/11/10 13:30:50.055 removed from map (0x9822d174) #0 (>34678) alarm: AlarmManager.cpp:185 was: 108 size, now 107 Rel: Y Got: Y <0x969fcb90>
21 03/11/10 13:30:50.055 unlock(0xa3c299d4) #0 (>34655) Media Plugin: MythTV_PlugIn.cpp:2730 <0x969fcb90>
21 03/11/10 13:30:50.055 removed from map (0xa3c299d4) #0 (>34655) Media Plugin: MythTV_PlugIn.cpp:2730 was: 107 size, now 106 Rel: Y Got: Y <0x969fcb90>
21 03/11/10 13:30:50.055 relocking (0x9822d174) (>3496) <0x969fcb90>
21 03/11/10 13:30:50.055 lock(0x9822d174) (>3496) alarm: AlarmManager.cpp:102 <0x969fcb90>
21 03/11/10 13:30:50.055 acquired(0x9822d174) #0 (>3496) alarm AlarmManager.cpp:102 <0x969fcb90>
21 03/11/10 13:30:50.055 start cond 0x9822d1ac timed wait till 1268333885.0 now 1268332250.54882000 AlarmManager.cpp:102 (0x9822d174) <0x969fcb90>
33_ZWave.log:
36 03/11/10 13:30:44.476 Received command for child <0xb6911b90>
36 03/11/10 13:30:44.476 OFF RECEIVED FOR CHILD 4 <0xb6911b90>
40 03/11/10 13:30:44.570 Sending job 0x9d48168 (cb 100) - 0x1 0xa 0x0 0x13 0x4 0x3 0x20 0x1 0x0 0x5 0x64 0xa1 (#\n#### ###d#) <0xb7913b90>
41 03/11/10 13:30:44.578 0x1 0x4 0x1 0x13 0x1 0xe8 (######) <0xb7913b90>
36 03/11/10 13:30:44.578 ZW_SEND delivered to Z-Wave stack <0xb7913b90>
41 03/11/10 13:30:45.042 0x1 0x5 0x0 0x13 0x64 0x1 0x8c (####d##) <0xb7913b90>
36 03/11/10 13:30:45.042 ZW_SEND Response with callback 100 received <0xb7913b90>
36 03/11/10 13:30:45.042 Error: ZW_SEND failed, retrying <0xb7913b90>
40 03/11/10 13:30:45.142 Sending job 0x9d48168 (cb 100) - 0x1 0xa 0x0 0x13 0x4 0x3 0x20 0x1 0x0 0x5 0x64 0xa1 (#\n#### ###d#) <0xb7913b90>
41 03/11/10 13:30:45.150 0x1 0x4 0x1 0x13 0x1 0xe8 (######) <0xb7913b90>
36 03/11/10 13:30:45.150 ZW_SEND delivered to Z-Wave stack <0xb7913b90>
41 03/11/10 13:30:45.554 0x1 0x5 0x0 0x13 0x64 0x1 0x8c (####d##) <0xb7913b90>
36 03/11/10 13:30:45.554 ZW_SEND Response with callback 100 received <0xb7913b90>
36 03/11/10 13:30:45.554 Error: ZW_SEND failed, retrying <0xb7913b90>
40 03/11/10 13:30:45.654 Sending job 0x9d48168 (cb 100) - 0x1 0xa 0x0 0x13 0x4 0x3 0x20 0x1 0x0 0x5 0x64 0xa1 (#\n#### ###d#) <0xb7913b90>
41 03/11/10 13:30:45.662 0x1 0x4 0x1 0x13 0x1 0xe8 (######) <0xb7913b90>
36 03/11/10 13:30:45.662 ZW_SEND delivered to Z-Wave stack <0xb7913b90>
41 03/11/10 13:30:46.086 0x1 0x5 0x0 0x13 0x64 0x1 0x8c (####d##) <0xb7913b90>
36 03/11/10 13:30:46.086 ZW_SEND Response with callback 100 received <0xb7913b90>
36 03/11/10 13:30:46.086 Error: ZW_SEND failed, retrying <0xb7913b90>
40 03/11/10 13:30:46.189 Sending job 0x9d48168 (cb 100) - 0x1 0xa 0x0 0x13 0x4 0x3 0x20 0x1 0x0 0x5 0x64 0xa1 (#\n#### ###d#) <0xb7913b90>
41 03/11/10 13:30:46.198 0x1 0x4 0x1 0x13 0x1 0xe8 (######) <0xb7913b90>
36 03/11/10 13:30:46.198 ZW_SEND delivered to Z-Wave stack <0xb7913b90>
41 03/11/10 13:30:46.702 0x1 0x5 0x0 0x13 0x64 0x1 0x8c (####d##) <0xb7913b90>
36 03/11/10 13:30:46.702 ZW_SEND Response with callback 100 received <0xb7913b90>
36 03/11/10 13:30:46.702 Error: ZW_SEND failed, removing job after three tries <0xb7913b90>
-
Hi
To verify, you could try installing an older ZWave release.
Run:
apt-get install pluto-zwave-lighting=2.0.0.44.10020322733
will get you the version before the multi-instance fixes.
Reload or reboot and test again.
best regards,
sambuca
-
Hi
To verify, you could try installing an older ZWave release.
Run:
apt-get install pluto-zwave-lighting=2.0.0.44.10020322733
will get you the version before the multi-instance fixes.
Reload or reboot and test again.
best regards,
sambuca
Tried to do the above but it complained about not being able to find that version.
I removed my peripherals (uiirt, USB->serial adapter) and moved the zwave dongle to a different USB port, deleted the zwave device, and rebooted. I haven't tested thoroughly yet, but for the few minutes I played with it before going to work this morning, it was working consistently.
Assuming this fixed the problem, I welcome advice on isolating the source of the conflict so we can keep this from effecting future users.
-
wget http://deb.linuxmce.org/ubuntu/pluto-zwave-lighting_2.0.0.44.10020322733_i386.deb
dpkg -i --force-all pluto-zwave-lighting_2.0.0.44.10020322733_i386.deb
and try again. My money is on the fact that you will still see the problems.
-
received DCE command:
36 03/11/10 13:30:44.476 Received command for child <0xb6911b90>
36 03/11/10 13:30:44.476 OFF RECEIVED FOR CHILD 4 <0xb6911b90>
telling the z-wave dongle to send a (ZW_SEND == 0x13) BASIC command to node 0x04, callback ID 100 (0x64):
40 03/11/10 13:30:44.570 Sending job 0x9d48168 (cb 100) - 0x1 0xa 0x0 0x13 0x4 0x3 0x20 0x1 0x0 0x5 0x64 0xa1 (#\n#### ###d#) <0xb7913b90>
z-wave dongle did receive the command and acknowledges it, so everything is fine from the driver side:
41 03/11/10 13:30:44.578 0x1 0x4 0x1 0x13 0x1 0xe8 (######) <0xb7913b90>
36 03/11/10 13:30:44.578 ZW_SEND delivered to Z-Wave stack <0xb7913b90>
we receive the response for the send command (callback 0x64):
41 03/11/10 13:30:45.042 0x1 0x5 0x0 0x13 0x64 0x1 0x8c (####d##) <0xb7913b90>
36 03/11/10 13:30:45.042 ZW_SEND Response with callback 100 received <0xb7913b90>
it tells us FAILED. This has nothing to do with the driver side, we delivered a correct command but the send attempt failed. The only thing we can do is to retry:
36 03/11/10 13:30:45.042 Error: ZW_SEND failed, retrying <0xb7913b90>
this looks like a network problem, maybe bad routing or a broken device. I'd rebuild the network from scratch. Make sure to reset all nodes before including them again. Start with always listening devices in close proximity to the dongle. Add battery powered devices after including all other nodes.
br Hari
-
Thanks hari. Very strange, i did a clean install without any USB peripherals except the z-stick, and then added my uirt and USB->rs232 adapter post-install and the problem has vanished. Obviously nothing wrong with the driver - is it possible the z-stick was acknowledging the commands but failed to transmit them due to a USB bus conflict of some sort?
-
Randomly this problem began happening to me again today. Unplugging all USB peripherals except the Aeon Z-wave device fixed it.
Any ideas?