« previous next »
Pages: [1]

Author Topic: Zwave Devices Problem (Since Update 2010-02-28 22812)  (Read 8120 times)

davegravy

  • Addicted
  • *
  • Posts: 551
    • View Profile
Zwave Devices Problem (Since Update 2010-02-28 22812)
« 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.

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
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
Logged

davegravy

  • Addicted
  • *
  • Posts: 551
    • View Profile
Re: Zwave Devices Problem (Since Update 2010-02-28 22812)
« Reply #1 on: March 02, 2010, 07:00:18 am »
I did an sqlcvs update on the dce repository, reloaded the router, no luck.
« Last Edit: March 02, 2010, 07:10:33 am by davegravy »
Logged

sambuca

  • Guru
  • ****
  • Posts: 462
    • View Profile
Re: Zwave Devices Problem (Since Update 2010-02-28 22812)
« Reply #2 on: March 02, 2010, 07:44:28 am »
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
« Last Edit: March 02, 2010, 09:26:04 am by sambuca »
Logged

davegravy

  • Addicted
  • *
  • Posts: 551
    • View Profile
Re: Zwave Devices Problem (Since Update 2010-02-28 22812)
« Reply #3 on: March 08, 2010, 03:22:56 pm »
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.
Logged

davegravy

  • Addicted
  • *
  • Posts: 551
    • View Profile
Re: Zwave Devices Problem (Since Update 2010-02-28 22812)
« Reply #4 on: March 11, 2010, 03:21:50 pm »
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.
Logged

davegravy

  • Addicted
  • *
  • Posts: 551
    • View Profile
Re: Zwave Devices Problem (Since Update 2010-02-28 22812)
« Reply #5 on: March 11, 2010, 04:09:13 pm »
Here's the log for one command execution:

Code: [Select]
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:

Code: [Select]
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.
Logged

sambuca

  • Guru
  • ****
  • Posts: 462
    • View Profile
Re: Zwave Devices Problem (Since Update 2010-02-28 22812)
« Reply #6 on: March 11, 2010, 07:28:58 pm »
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
Logged

davegravy

  • Addicted
  • *
  • Posts: 551
    • View Profile
Re: Zwave Devices Problem (Since Update 2010-02-28 22812)
« Reply #7 on: March 11, 2010, 07:48:31 pm »
Thanks Sambuca.

Below is is the 33_ZWave.log and DCERouter.log during a failed command.

DCERouter.log:

Code: [Select]
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:

Code: [Select]
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>
Logged

sambuca

  • Guru
  • ****
  • Posts: 462
    • View Profile
Re: Zwave Devices Problem (Since Update 2010-02-28 22812)
« Reply #8 on: March 12, 2010, 08:08:11 am »
Hi

To verify, you could try installing an older ZWave release.
Run:
Code: [Select]
apt-get install pluto-zwave-lighting=2.0.0.44.10020322733will get you the version before the multi-instance fixes.

Reload or reboot and test again.

best regards,
sambuca
Logged

davegravy

  • Addicted
  • *
  • Posts: 551
    • View Profile
Re: Zwave Devices Problem (Since Update 2010-02-28 22812)
« Reply #9 on: March 12, 2010, 03:27:25 pm »

Quote from: sambuca on March 12, 2010, 08:08:11 am
Hi

To verify, you could try installing an older ZWave release.
Run:
Code: [Select]
apt-get install pluto-zwave-lighting=2.0.0.44.10020322733will 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. 
Logged

Marie.O

  • Administrator
  • LinuxMCE God
  • *****
  • Posts: 3676
  • Wastes Life On LinuxMCE Since 2007
    • View Profile
    • My Home
Re: Zwave Devices Problem (Since Update 2010-02-28 22812)
« Reply #10 on: March 12, 2010, 10:01:23 pm »
Code: [Select]
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.
Logged

hari

  • Administrator
  • LinuxMCE God
  • *****
  • Posts: 2428
    • View Profile
    • ago control
Re: Zwave Devices Problem (Since Update 2010-02-28 22812)
« Reply #11 on: March 13, 2010, 12:22:47 pm »
received DCE command:
Code: [Select]
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):
Code: [Select]
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:
Code: [Select]
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):
Code: [Select]
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:
Code: [Select]
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
« Last Edit: March 13, 2010, 12:28:06 pm by hari »
Logged
rock your home - http://www.agocontrol.com home automation

davegravy

  • Addicted
  • *
  • Posts: 551
    • View Profile
Re: Zwave Devices Problem (Since Update 2010-02-28 22812)
« Reply #12 on: March 13, 2010, 06:07:01 pm »
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? 
Logged

davegravy

  • Addicted
  • *
  • Posts: 551
    • View Profile
Re: Zwave Devices Problem (Since Update 2010-02-28 22812)
« Reply #13 on: May 07, 2010, 04:32:18 am »
Randomly this problem began happening to me again today. Unplugging all USB peripherals except the Aeon Z-wave device fixed it.

Any ideas?
Logged
Pages: [1]
« previous next »
 

Sitemap