ZWave ERROR: Dropping command, no callback received after three resends

[esev]

Does anyone else get this error in their ZWave log?

   No callback received: await_callback: 105 timer: 31 <0xb7136b90>
   No callback received: await_callback: 105 timer: 31 <0xb7136b90>
   No callback received: await_callback: 105 timer: 31 <0xb7136b90>
   ERROR: Dropping command, no callback received after three resends <0xb7136b90>

I have the Tricklestar 300ZW and see these from time to time.  It seems once I start getting this error it continues till I reboot the computer.  While this error is occurring LinuxMCE is unable to control any ZWave devices.

Just curious if anyone else has seen this. Is it limited to the Tricklestar dongle? Is there any way to prevent it?

[huh]

I get this too- on my aeon labs mi casa verde z-wave stick:

05      10/25/10 21:10:12.554           ^[[33;1mNo callback received: await_callback: 201 timer: 31^[[0m <0xb7253b90>
05      10/25/10 21:28:06.314           ^[[33;1mNo callback received: await_callback: 51 timer: 31^[[0m <0xb7253b90>
05      10/25/10 23:10:51.874           ^[[33;1mNo callback received: await_callback: 145 timer: 31^[[0m <0xb7253b90>


My lamppost automatically shuts off at 22:00.  As you can see, I had errors before and after, but I just confirmed that the light shut off.  Don't know if it was at 22:00, but don't doubt that it was.

Here is the start of my file:
05      10/25/10 8:23:04.167            ^[[33;1mGoing to rotate logs...^[[0m <0xb6251b90>
05      10/25/10 8:27:35.131            ^[[33;1mGoing to rotate logs...^[[0m <0xb6251b90>
05      10/25/10 8:30:40.158            ^[[33;1mNo callback received: await_callback: 71 timer: 31^[[0m <0xb7253b90>
05      10/25/10 8:46:31.967            ^[[33;1mNo callback received: await_callback: 164 timer: 31^[[0m <0xb7253b90>
05      10/25/10 8:48:37.426            ^[[33;1mNo callback received: await_callback: 176 timer: 31^[[0m <0xb7253b90>

Going through the zipped files for the last 6 days, all of them have between about 7:30 and 8:30 that line about rotating the logs.  After that there are 15 to 25 lines of "No callback received" stretching across the day in what seems to be random intervals.  I can't imagine a z-wave device that we would use at those times.

They do not stop my lamppost from turning on at sunset and off at 10:00.

FWIW

[sambuca]

Hari will have to confirm, but if I've understood correctly, a missing callback means that the ZWave driver couldn't receive a confirmation for the message it sent. This might be caused by communication problems, like having radio interference or too far distance between nodes.

br,
sambuca

[esev]

I suspected communications problems at first too.  But my ZWave dongle has nearly direct line-of-sight to the closest device, and the two are less than 20ft away from each other.  The weird thing is that the errors go away immediately after a reboot.

The errors are always in a set of four: three await_callback and one Dropping command.  They will continue this way for hours, sometimes going back to normal on their own.  When everything is working fine I don't get any errors except for an occasional single await_callback.

I'm happy to try resetting my devices and moving the ZWave dongle to one of my Media Directors (will this work?) just to see if being in a different part of the house has any effect.

I should also mention, the last time I got these errors I issued a "#788 StatusReport" to the ZWave plugin.  I stopped getting these errors after sending that command.  I think that is because implementation of the StatusReport command Soft-Resets the dongle.  I've only tried this one time however, so it might have just been a coincidence that things started working again.

[esev]

Maybe sending the Soft-Reset does work.  I just noticed I was getting these error messages again.  I sent the StatusReport command to the ZWave device and, after the 30sec device polling was complete, the system went back to normal.

I'll enable debugging on the pl2303 module and also crank up the logging on the ZWave device.  Maybe between the logs I be able to catch something out of the ordinary going on.

Failing that, Hari, would you mind if I submit a patch to do a Soft-Reset if all devices fail to respond to the poll that takes place every 30 seconds?

[hari]

hi Eric,

Yes, the soft reset is triggered by that dce command. If I remember correctly I did implement that for domodude to test. I've never seen that device hang myself, but I'm using a seluxit dongle as primary device.

I'd appreciate such a patch as i did never find the time to implement it myself, and domodude was working around with a script that parsed the logs and used messagesend to reset the device when seeing a bunch of those messages in the logs..

The poll is probably the wrong place as this can be deactivated with a dce command.. Detecting excessive miss of callback (maybe a counter) would probably work...

Br, keep up the great work,
Hari

[esev]

Hari,

Thanks for the reply.  With the full debugging turned on, I'm seeing some weird things.  For example, I see the ZWave dongle send a message to the driver at the same time the ZWave driver sends a message to the dongle.  This is causing an issue as in Serial.cpp line 95 all the data in the input buffers is flushed when a message is transmitted to the dongle.  This causes a message from the dongle to be missed in the driver and sometimes winds up in a ERROR! Out of frame flow!! message.

Is there a reason for flushing the input buffer like that?  I'm hesitant to touch that code because it might be there to handle a special case with another ZWave dongle.

I haven't gotten into the infinite retry state yet with full debugging turned on.  Still waiting...

Thanks!
Eric

[esev]

Hari,

I finally got the error to occur again.  However I cannot find anything telling in the logs that would indicate why it is failing.  Again, performing the soft-reset cleared things up.  If you'd like to take a look at the logs for yourself, you can download them from: http://esev.com/zwave.tar.bz2  Both the ZWave and kernel debugging logs are included.

One thing that did arrise from the logs is that when this issue occurs the ZWave controller is sending back notifications that the message cannot be sent to the ZWave stack: i.e. "ERROR: ZW_SEND could not be delivered to Z-Wave stack" shows up in the logs.

Since I cannot see any other obvious way to fix this, I'm using your suggestion of a counter to trigger a soft-reset after receiving two consecutive ZW_SEND delivery errors.  I chose two because the retry limit of a job is currently set to 3.  My thought was that if the reset was successful, the third retry would still have a chance to work.  To do this, however, I needed to insert the soft-reset job at the beginning of the ZWSendQueue.

Let me know if this will be acceptable.  I've attached a preliminary patch.  I'll wait to confirm this works before posting it to a ticket on Trac.  I can add the "Out of frame flow" fix from my previous post to this patch too, if you'd like.

TIA
Eric

[Kooma]

I'm having a bit similar situation here with the Selexit dongle. Everything works perfect, except when using timed events to control lights, sometimes an excessive repetition of the command is broadcasted. It occurs about once every millisecond. Reloading the router gets things back to normal. The system may work several days OK yet sometimes this erroneous function takes place within a day.


The DCE router log shows (this goes on until reloading):

Code: [Select]

08      10/27/10 0:30:01.565            Received Message from 12 (Event Plug-in / ) to 503 (Lights (dim) - MH / ), type 1 id 193 Command:Off, retry none, parameters: <0x9f7fab90>
08      10/27/10 0:30:01.565              Parameter 97(PK_Pipe):  <0x9f7fab90>
08      10/27/10 0:30:01.566            Received Message from 12 (Event Plug-in / ) to 503 (Lights (dim) - MH / ), type 1 id 193 Command:Off, retry none, parameters: <0x9f7fab90>
08      10/27/10 0:30:01.566              Parameter 97(PK_Pipe):  <0x9f7fab90>
08      10/27/10 0:30:01.568            Received Message from 12 (Event Plug-in / ) to 503 (Lights (dim) - MH / ), type 1 id 193 Command:Off, retry none, parameters: <0x9f7fab90>

I hope this helps in finding out what is going on.

/Kooma

[hari]

I'm having a bit similar situation here with the Selexit dongle. Everything works perfect, except when using timed events to control lights, sometimes an excessive repetition of the command is broadcasted. It occurs about once every millisecond. Reloading the router gets things back to normal. The system may work several days OK yet sometimes this erroneous function takes place within a day.


The DCE router log shows (this goes on until reloading):

Code: [Select]

08      10/27/10 0:30:01.565            Received Message from 12 (Event Plug-in / ) to 503 (Lights (dim) - MH / ), type 1 id 193 Command:Off, retry none, parameters: <0x9f7fab90>
08      10/27/10 0:30:01.565              Parameter 97(PK_Pipe):  <0x9f7fab90>
08      10/27/10 0:30:01.566            Received Message from 12 (Event Plug-in / ) to 503 (Lights (dim) - MH / ), type 1 id 193 Command:Off, retry none, parameters: <0x9f7fab90>
08      10/27/10 0:30:01.566              Parameter 97(PK_Pipe):  <0x9f7fab90>
08      10/27/10 0:30:01.568            Received Message from 12 (Event Plug-in / ) to 503 (Lights (dim) - MH / ), type 1 id 193 Command:Off, retry none, parameters: <0x9f7fab90>

I hope this helps in finding out what is going on.

/Kooma

iirc this is a problem with the event plugin and not the zwave driver.. but i cannot remember the exact thread where this was discussed..

br Hari

[hari]

Hari,

Thanks for the reply.  With the full debugging turned on, I'm seeing some weird things.  For example, I see the ZWave dongle send a message to the driver at the same time the ZWave driver sends a message to the dongle.  This is causing an issue as in Serial.cpp line 95 all the data in the input buffers is flushed when a message is transmitted to the dongle.  This causes a message from the dongle to be missed in the driver and sometimes winds up in a ERROR! Out of frame flow!! message.

I'm not sure if I can follow..

Is there a reason for flushing the input buffer like that?  I'm hesitant to touch that code because it might be there to handle a special case with another ZWave dongle.

no afaict there is no special case for other dongles. I was just using the existing serial routines as I was too lazy to write my own...

br Hari

[hari]

regarding the patches, please visit us in #linuxmce-devel to get your svn account set up. Possy will create the account with your password hash.

br Hari

[davegravy]

I get the ZW_send periodically with the Aeon Labs Z-stick. See thread http://forum.linuxmce.org/index.php?topic=9739.0

Unplugging my other USB devices consistently fixes the problem. The better fix I've found is to unplug the Aeon, delete the ZWave devices from webadmin, reboot, replug the Aeon, and then go through the setup wizard from scratch. I don't claim to understand why either of these procedures work.

It hasn't died on me in a month or so which is the longest it's gone without problems.

[esev]

Unplugging my other USB devices consistently fixes the problem.

Davegravy,

Which other USB devices do you have?  Maybe we have one in common that is causing this issue.  I've got the USB_UIRT, Hauppauge HD-PVR, Gyration GYR4101US in addition to my Tricklestar ZWave.

[davegravy]

Unplugging my other USB devices consistently fixes the problem.

Davegravy,

Which other USB devices do you have?  Maybe we have one in common that is causing this issue.  I've got the USB_UIRT, Hauppauge HD-PVR, Gyration GYR4101US in addition to my Tricklestar ZWave.

I have the USB_UIRT, Aeon Labs Z-stick, and a USB->Serial RS232 adapter.