RainNet8 doing strange things

[dhanford]

Larry,

I know you are a Maestro owner... are you using a Rain8 UPB with Maestro?

Thanks,
Dave

[lpitman]

Not at this time, the Rain8Net devices are only set up in my lab, as we are doing some remodeling and never got around to deploying them in a real life setup. I am curious though, because I have a number of customers using this plug-in without complaint, but I am always willing to investigate any possible flaws or compatiblity issues.

[lpitman]

The 2.2.0.8 version works fine here in my lab, but I did make a couple of changes to aid in debugging and using the output in a log file.

Anyway here is the new version I promised (2.2.0.9). I have tested this version and it works fine using a USB->Edgeport8.

1.) Please shut down (disable) old plugin and delete the devices from the status page.

2.) Copy Rain8Net.dll from this zip into your HS directory.

3.) Enable new plugin (HS might not recognize until restart).

Let me know how it goes.

[MarkHargrove]

Larry,

>Windows Version: Windows Server 2003, current SPs and Hot Fixes

>HS version: 2.2.0.66

>How is the Rain8Net connected: direct serial port (COM5)

>Have you tried the Rain8Net configuration program from WGL Designs? This helps verify connectivity to the device: Not yet, but I will tonight.

>Thanks for your help... No problem! Thanks for looking at the issue.

I'll load and try the new plugin tonight and report back later this evening.

-M.

[MarkHargrove]

Larry,

The new version of the plugin (2.2.0.9) is installed. I see no difference in behavior. The log is below:

6/4/2008 10:01:15 PM~Entering InitHW()....
6/4/2008 10:01:15 PM~Entering InitDevices()...
6/4/2008 10:01:15 PM~Entering EnumerateDevices()...
6/4/2008 10:01:15 PM~Found a plug-in device at \9
6/4/2008 10:01:15 PM~Found a plug-in device at \5
6/4/2008 10:01:15 PM~Found a plug-in device at \6
6/4/2008 10:01:15 PM~Found a plug-in device at \4
6/4/2008 10:01:15 PM~Found a plug-in device at \3
6/4/2008 10:01:15 PM~Found a plug-in device at \2
6/4/2008 10:01:15 PM~Found a plug-in device at \1
6/4/2008 10:01:15 PM~Found a plug-in device at \8
6/4/2008 10:01:15 PM~Found a plug-in device at \7
6/4/2008 10:01:15 PM~Entering CreateDevices()....
6/4/2008 10:01:15 PM~***************************************
6/4/2008 10:01:15 PM~Rain8Net Debug Enabled.
6/4/2008 10:01:15 PM~Rain8Net Debug Logging to AppDirPath\Logs\VWS.log.
6/4/2008 10:01:15 PM~Rain8Net HS-Version: 2.2.0.66
6/4/2008 10:01:15 PM~Rain8Net Plug-In Version: 2.2.0.9
6/4/2008 10:01:15 PM~***************************************
6/4/2008 10:01:15 PM~Entering InitCommon()....
6/4/2008 10:01:15 PM~Entering InitRain8Net()....
6/4/2008 10:01:15 PM~Entering ComPort()....
6/4/2008 10:06:38 PM~Entering ButtonPressEx()....
6/4/2008 10:06:38 PM~In ButtonPressEx for Rain8Net - Zone-1, button pressed is On
6/4/2008 10:06:38 PM~Entering SetRain8Zone()....
6/4/2008 10:06:38 PM~SetRain8Zone()...Unit: 1 ...Name: Zone-1 ...Zone-1 - ON
6/4/2008 10:06:38 PM~Entering Rain8Send()....
6/4/2008 10:06:38 PM~Rain8Send()...Sending:--> @
1
6/4/2008 10:06:38 PM~SetRain8Zone()...Rain8Send(ON) returned Failed
6/4/2008 10:06:46 PM~Entering ButtonPressEx()....
6/4/2008 10:06:46 PM~In ButtonPressEx for Rain8Net - Zone-1, button pressed is Off
6/4/2008 10:06:46 PM~Rain8Net ButtonPressEx Off for Zone-1
6/4/2008 10:06:46 PM~Entering SetRain8Zone()....
6/4/2008 10:06:46 PM~SetRain8Zone()...Unit: 1 ...Name: Zone-1 ...Zone-1 - OFF
6/4/2008 10:06:46 PM~Number of Valves On = 0
6/4/2008 10:06:56 PM~Entering ButtonPressEx()....
6/4/2008 10:06:56 PM~In ButtonPressEx for Rain8Net - All Zones, button pressed is Off
6/4/2008 10:06:56 PM~Rain8Net ButtonPressEx Off for All Zones
6/4/2008 10:06:56 PM~Entering Rain8AllOFF()....
6/4/2008 10:06:56 PM~Rain8AllOff()...Sent - All OFF command.

One thing of perhaps relevant note: the log file that is supposedly opened in the trace above (6/4/2008 10:01:15 PM~Rain8Net Debug Logging to AppDirPath\Logs\VWS.log.) -- well, there is no such file created in the referenced directory ("C:\Program Files\HomeSeer 2\Logs\") -- only the usual Rain8Net.log file that I copied the trace from above.

-M.

[lpitman]

Sorry, the VWS.log is left over from a cut and paste of the logging statement that was implemented in another plug-in, it should read Rain8Net.log....

I will be curious about the standalone WGL Designs program, the plugin does work here just fine and I could not make it fail, but I will continue to examine.

[MarkHargrove]

The WGL "Rain8Net & Relay8Net Configure.exe" program works just fine -- it reports "Rain8Net module found", and clicking the "Read Module" button results in a dialog box that reports "Good Read". Clicking the "Load Module" button reports "Good Download".

The WGL "Rain8Net & Relay8Net demo (V3.0)" also works fine. "Test All" turns on all relays in sequence" "All off" and "Global all off" turn all relays off. Indvidually turning a relay on and off works correctly.

The "Rain8Net Timer V1.0" works correctly as well.

I'm logging the exact same errors as noted before after switching back to letting HS2 and the plugin control the Rain8Net device.

[lpitman]

OK, I'll keep looking into it, I am just puzzled, because I can not get it to fail here, even after multiple iterations of ON's and Off's. If I could catch it in the act, then maybe I would have something to go on.

[MarkHargrove]

Larry,

If you can modify your plugin to provide a bit more detail in the log file, I think we can get to the bottom of what's going on.

Using the DockLight utility (from www.docklight.de), I've been able to verify that the Rain8Net device is responding correctly to commands on its serial port. Using the three-byte command protocol documented on WGL's web site, I exercised all facets of the device that I can (I don't have a rain gauge or a flow meter, but I was able to test all other commands and status requests). In all cases, the the Rain8Net device behaves properly. I was running Docklight from the HomeSeer PC, so I also know that the COM port is working correctly.

As I'm sure you know, the Rain8Net protocol acknowledges a command by echoing the command string itself back (for all direct commands except for the "Global All Off" command string).

In looking at the debug log, I see the following:

6/7/2008 5:22:59 PM - Rain8Net Debug - Rain8Send()...Sending:--> @1
6/7/2008 5:22:59 PM - Rain8Net Error - Rain8Send() Failed - Response was:--> @1

This makes me curious: why is the Rain8Send() function indicating failure when the response appears to match the command sent (as it should)?

Also, as noted previously, the command actually does succeed -- the relay turns on when the command is sent.

It would help with debugging if the OFF command would tell us what string it is sending to the Rain8Net in the same way the on command does. The fact that it doesn't strongly suggests that either (1) the code path for the ON and OFF commands is different (which seems weird to me), or (2), something is preventing the Rain8Send() function from being called at all when OFF is commanded, thus also preventing any debug output from the function. In any case, it's curious that there is no debug output from Rain8Send() when commanding the relay OFF.

I'm also not seeing any debug output from Rain8Send() when the "All Off" command is clicked.

It might be helpful if you could add debug code to log the exact sequences sent and received from the Rain8Net device, and it would also help (me anyway) if you'd print the strings in hex instead of ascii in the log files.

I'm sure I can also arrange remote access to my HS box for you if that will help track down what's going on. For example, I can install Visual Studio 2005 (or 2008) directly on the HS box and let you CrossLoop in to debug for yourself.

-M.

[lpitman]

OK, lets try this version, a bit more debug. Version 2.2.0.11 and I'll include a log file of the test on my machine.

[MarkHargrove]

Larry,

Here's the trace from the my log after turning valve one on and then off:

6/8/2008 11:51:16 PM  - Rain8Net Debug - Entering ButtonPressEx()....
6/8/2008 11:51:16 PM  - Rain8Net Debug - In ButtonPressEx for Rain8Net - Zone-1, button pressed is On
6/8/2008 11:51:16 PM  - Rain8Net Debug - Entering SetRain8Zone()....
6/8/2008 11:51:16 PM  - Rain8Net Debug - SetRain8Zone()...Unit: 1 ...Name: Zone-1 ...Zone-1 - ON
6/8/2008 11:51:16 PM  - Rain8Net Debug - SetRain8Zone()-->Rain8Send( @
1 )
6/8/2008 11:51:16 PM  - Rain8Net Debug - SetRain8Zone()..Sending 3-Bytes-->Rain8Send( Mode = &H40, Unit = &H1, On + Valve: &H31 )
6/8/2008 11:51:16 PM  - Rain8Net Debug - Entering Rain8Send()....
6/8/2008 11:51:16 PM  - Rain8Net Debug - Rain8Send()...Sending Byte1:--> &H40
6/8/2008 11:51:16 PM  - Rain8Net Debug - Rain8Send()...Sending Byte2:--> &H1
6/8/2008 11:51:16 PM  - Rain8Net Debug - Rain8Send()...Sending Byte3:--> &H31
6/8/2008 11:51:16 PM  - Rain8Net Debug - Rain8Send() BytesToRead = 2
6/8/2008 11:51:16 PM  - Rain8Net Debug - Rain8Send()...Response was:--> &H40 &H1 &H31
6/8/2008 11:51:16 PM  - Rain8Net Debug - Number of Valves On = 1
6/8/2008 11:51:32 PM  - Rain8Net Debug - Entering ButtonPressEx()....
6/8/2008 11:51:32 PM  - Rain8Net Debug - In ButtonPressEx for Rain8Net - Zone-1, button pressed is Off
6/8/2008 11:51:32 PM  - Rain8Net Debug - Rain8Net ButtonPressEx Off for Zone-1
6/8/2008 11:51:32 PM  - Rain8Net Debug - Entering SetRain8Zone()....
6/8/2008 11:51:32 PM  - Rain8Net Debug - SetRain8Zone()...Unit: 1 ...Name: Zone-1 ...Zone-1 - OFF
6/8/2008 11:51:32 PM  - Rain8Net Debug - SetRain8Zone()-->Rain8Send( @
A )
6/8/2008 11:51:32 PM  - Rain8Net Debug - SetRain8Zone()..Sending 3-Bytes-->Rain8Send( Mode = &H40, Unit = &H1, Off + Valve: &H31 )
6/8/2008 11:51:32 PM  - Rain8Net Debug - Entering Rain8Send()....
6/8/2008 11:51:32 PM  - Rain8Net Debug - Rain8Send()...Sending Byte1:--> &H40
6/8/2008 11:51:32 PM  - Rain8Net Debug - Rain8Send()...Sending Byte2:--> &H1
6/8/2008 11:51:32 PM  - Rain8Net Debug - Rain8Send()...Sending Byte3:--> &H41
6/8/2008 11:51:32 PM  - Rain8Net Debug - Rain8Send() BytesToRead = 2
6/8/2008 11:51:32 PM  - Rain8Net Error - Rain8Send() Failed - iValve Response was:-->  

6/8/2008 11:51:32 PM  - Rain8Net Debug - SetRain8Zone()...Rain8Send(OFF) returned Failed

There is one issue that is probably just a typo -- let's dispose of that first. Note that in the OFF command sequence that starts at 11:51:32 it says:

6/8/2008 11:51:32 PM - Rain8Net Debug - SetRain8Zone()..Sending 3-Bytes-->Rain8Send( Mode = &H40, Unit = &H1, Off + Valve: &H31 )

This is wrong; the off command (for valve 1) is &H41. But the very next debug output shows:

6/8/2008 11:51:32 PM - Rain8Net Debug - Rain8Send()...Sending Byte1:--> &H40
6/8/2008 11:51:32 PM - Rain8Net Debug - Rain8Send()...Sending Byte2:--> &H1
6/8/2008 11:51:32 PM - Rain8Net Debug - Rain8Send()...Sending Byte3:--> &H41

...which correctly shows you're sending &H41.

Now for the peculiar part. The Rain8Net is supposed to return 3 bytes to ACK a command -- specifically, the three bytes you send as a command. In your example log file that's exactly what happens. But note what happens in my log file when I turn on Valve 1:

6/8/2008 11:51:16 PM - Rain8Net Debug - Rain8Send() BytesToRead = 2
6/8/2008 11:51:16 PM - Rain8Net Debug - Rain8Send()...Response was:--> &H40 &H1 &H31

Something is wacky here -- it says there are two bytes to read, but then it reads three bytes. And when the valve is turned off:

6/8/2008 11:51:32 PM - Rain8Net Debug - Rain8Send() BytesToRead = 2
6/8/2008 11:51:32 PM - Rain8Net Error - Rain8Send() Failed - iValve Response was:-->

Again, only two bytes to read, but it appears to read only 1 byte (hard to tell; there could be spaces in the response. As a matter of practice when I'm debugging I tend to do things like

[COLOR=darkgreen][COLOR=darkgreen]print "The string is -->" & theString & "<--"[/COLOR][/COLOR]

...so there is no ambiguity about spaces in strings).

Further, I noted that the ON command worked te first time withoug logging an error -- but only that once. I'm not showing the later logfile, but in subsquent attempts to turn on a valve the Rain8Send() function fails with the same message as we see in the 'OFF' example above (the iValve response looks identical to the error message above). In all cases, BytesToRead is reporting 2 instead of 3.

This has now got me stumped because I cannot think of a way to do any deeper debugging. Any ideas?

-M.

[lpitman]

Hey Mark,

The log showing:

6/8/2008 11:51:32 PM - Rain8Net Debug - Rain8Send()...Sending Byte1:--> &H40
6/8/2008 11:51:32 PM - Rain8Net Debug - Rain8Send()...Sending Byte2:--> &H1
6/8/2008 11:51:32 PM - Rain8Net Debug - Rain8Send()...Sending Byte3:--> &H41

6/8/2008 11:51:16 PM - Rain8Net Debug - Rain8Send() BytesToRead = 2

This was added to help debug, because I wanted to know if the ACK was coming back in 3-bytes as you indicated.

6/8/2008 11:51:16 PM - Rain8Net Debug - Rain8Send()...Response was:--> &H40 &H1 &H31

The response was changed from reading a string from the serial port response, to reading and comparing individual bytes that result is what you see above???

The ACK is compared byte by byte in the response check and will log byte by byte failures. So my first impression is that the BytesToRead is slow, I can verify this by moving that statement down in the code.

Did you get an opportunity to view my log file?