CM15PRO - worked with HG but not working of late

[JerryR]

I have been using HG with a Raspberry Pi (Rev B) for some time now and recently I noticed that none of the RF commands are updating in the HG log. I have rebooted, powered off and on and even unplugged the CM15 Pro from my USB hub and back in. Nothing seems to help and I found the following entries in my homegenie/log file...

  at XTenLib.XTenManager.ReaderThreadLoop () [0x00000] in <filename unknown>:0
2015-10-08T06:56:35.4519790-05:00       HomeGenie.System        Console StdOut/StdErr redirect  Console.Output  X10 ! Submit Async Read Failed.
2015-10-08T06:56:35.4529220-05:00       HomeGenie.System        Console StdOut/StdErr redirect  Console.Output  X10 !   at XTenLib.Drivers.CM15.ReadData () [0x00000] in <filename unknown>:0
  at XTenLib.XTenManager.ReaderThreadLoop () [0x00000] in <filename unknown>:0
2015-10-08T06:56:35.4566400-05:00       HomeGenie.System        Console StdOut/StdErr redirect  Console.Output  X10 ! Submit Async Read Failed.
2015-10-08T06:56:35.4575480-05:00       HomeGenie.System        Console StdOut/StdErr redirect  Console.Output  X10 !   at XTenLib.Drivers.CM15.ReadData () [0x00000] in <filename unknown>:0
  at XTenLib.XTenManager.ReaderThreadLoop () [0x00000] in <filename unknown>:0
2015-10-08T06:56:35.4609560-05:00       HomeGenie.System        Console StdOut/StdErr redirect  Console.Output  X10 ! Submit Async Read Failed.
2015-10-08T06:56:35.4618420-05:00       HomeGenie.System        Console StdOut/StdErr redirect  Console.Output  X10 !   at XTenLib.Drivers.CM15.ReadData () [0x00000] in <filename unknown>:0

Does this suggest any specific problem or course of action to run this issue down?
I have not made any changes to my HG setup nor my RPi environment during the time in which it quit working.

Any suggestions are very appreciated.

Jerry

I also get these messages and I have no idea what they are about...

2015-10-08T07:05:55.5206300-05:00       MIG.Gateways.WebServiceGateway  192.168.1.252   hg/html/js/codemirror-4.03/addon/fold/foldcode.js       HTTP    GET
2015-10-08T07:05:55.5392780-05:00       MIG.Gateways.WebServiceGateway  192.168.1.252   hg/html/js/codemirror-4.03/addon/fold/brace-fold.js     HTTP    GET
2015-10-08T07:05:55.5569440-05:00       HomeGenie.System        Console StdOut/StdErr redirect  Console.Output
MIGService ERROR: Object reference not set to an instance of an object
  at MIG.MIGService+<PutWebFileCache>c__AnonStorey2.<>m__0 (MIG.WebFileCache wfc) [0x00000] in <filename unknown>:0
  at System.Collections.Generic.List`1[MIG.WebFileCache].Find (System.Predicate`1 match) [0x00000] in <filename unknown>:0
  at MIG.MIGService.PutWebFileCache (System.String file, System.String content, System.Text.Encoding encoding) [0x00000] in <filename unknown>:0
  at MIG.MIGService.webGateway_ProcessRequest (System.Object gwRequest) [0x00000] in <filename unknown>:0

[JerryR]

Are there some debug options I should turn on to better diagnose this?

[petediscrete]

Activate the logging file in the Configuration - Maintenance section.

[JerryR]

Thanks for the reply! I took a look at the log that can be dumped using that option you referenced. I don't see anything that strikes me as unusual in the contents aside from the object reference that is failing which I mentioned in my first post. When the program starts, I see this:

#Version: 1.0      
#Software: HomeGenie 1.0.0.0      
#Start-Date: 2015-10-08T22:51:10.3241060-05:00      
"#Fields: datetime   source-domain   source-id   description   property   value"      
      
"2015-10-08T22:51:10.1698430-05:00   HomeAutomation.HomeGenie   0   HomeGenie service ready   SystemInfo.HttpPort   8085"      
"2015-10-08T22:51:17.6103220-05:00   HomeAutomation.HomeGenie.Automation   6   Automation Program   Program.Status   Idle"      

Later on in the log I see this

"2015-10-08T22:51:21.6841900-05:00   HomeGenie.System   Console   StdOut/StdErr redirect   Console.Output   X10 < 9B 15 33 0B 18 90 09 02"      
"2015-10-08T22:51:21.6966290-05:00   HomeGenie.System   Console   StdOut/StdErr redirect   Console.Output   X10 < 9B 15 33 0B 18 90 09 02"      
"2015-10-08T22:51:21.7059350-05:00   HomeGenie.System   Console   StdOut/StdErr redirect   Console.Output   X10 < BB 40 00 05 00 14 20 28 24 29"      
"2015-10-08T22:51:21.7094970-05:00   HomeGenie.System   Console   StdOut/StdErr redirect   Console.Output   X10 < 8B"      
"2015-10-08T22:51:21.8641120-05:00   HomeGenie.System   Console   StdOut/StdErr redirect   Console.Output   X10 > 55"      
"2015-10-08T22:51:21.8649470-05:00   HomeGenie.System   Console   StdOut/StdErr redirect   Console.Output   X10 < 00"      
"2015-10-08T22:51:21.8714490-05:00   HomeGenie.System   Console   StdOut/StdErr redirect   Console.Output   X10 > 00 00 00 00 00 00 00 00"      
"2015-10-08T22:51:21.8720320-05:00   HomeGenie.System   Console   StdOut/StdErr redirect   Console.Output   X10 < 00"      

"2015-10-08T22:51:25.3524420-05:00   HomeGenie.UpdateChecker   0   HomeGenie Update Checker   InstallProgress.Update   STARTED"      
"2015-10-08T22:51:23.6012720-05:00   HomeAutomation.HomeGenie.Automation   6   Automation Program   Program.Status   Setup"      
"2015-10-08T22:51:25.6311250-05:00   HomeAutomation.HomeGenie.Automation   7   Automation Program   Program.Status   Setup"      
"2015-10-08T22:51:26.3410890-05:00   HomeAutomation.HomeGenie.Automation   84   Automation Program   Program.Status   Setup"      
"2015-10-08T22:51:26.9056200-05:00   HomeAutomation.HomeGenie.Automation   84   Automation Program   Program.Status   Running"      
"2015-10-08T22:51:27.0396990-05:00   HomeAutomation.HomeGenie.Automation   91   Automation Program   Program.Status   Running"      
"2015-10-08T22:51:22.7737770-05:00   HomeAutomation.HomeGenie.Automation   122   Automation Program   Program.Status   Setup"      
"2015-10-08T22:51:25.7658640-05:00   HomeAutomation.HomeGenie.Automation   122   Automation Program   Program.Status   Running"      
"2015-10-08T22:51:24.3418390-05:00   HomeAutomation.HomeGenie.Automation   142   Automation Program   Program.Status   Setup"      
"2015-10-08T22:51:26.4034760-05:00   HomeAutomation.HomeGenie.Automation   142   Automation Program   Program.Status   Running"      
"2015-10-08T22:51:24.5685000-05:00   HomeAutomation.HomeGenie.Automation   93   Automation Program   Program.Status   Running"      
"2015-10-08T22:51:26.1927970-05:00   HomeAutomation.HomeGenie.Automation   121   Automation Program   Program.Status   Setup"      
"2015-10-08T22:51:27.0582760-05:00   HomeAutomation.HomeGenie.Automation   121   Automation Program   Program.Status   Running"      
"2015-10-08T22:51:23.3507500-05:00   HomeAutomation.HomeGenie.Automation   8   Automation Program   Program.Status   Setup"      
"2015-10-08T22:51:30.7278220-05:00   HomeGenie.UpdateChecker   0   HomeGenie Update Checker   InstallProgress.Update   COMPLETED"      

It seems like the update checker is looking to see if an update is available (which my HG indicates IS available but it seems to complete ok. Then I see some HTML code fetched from MIG.Gateways.WebServiceGateway

After that I see one more round of redirectConsole.OutputX10 messages and then it seems to do nothing after that.

The only error type indication I see is this statement below which is similar to the original post I created...
"2015-10-08T20:06:30.5756000-05:00   HomeGenie.System   Console   StdOut/StdErr redirect   Console.Output     at MIG.Gateways.WebServiceGateway.Worker (System.Object state) [0x00000] in <filename unknown>:0 System.NullReferenceException: Object reference not set to an instance of an object"
"2015-10-08T20:06:30.5765380-05:00   HomeGenie.System   Console   StdOut/StdErr redirect   Console.Output     at MIG.MIGService.webGateway_ProcessRequest (System.Object gwRequest) [0x00000] in <filename unknown>:0 "

It indicates some type of object is being referenced but there is no such instance.

Does any of this help to point in the direction of the problem?
Should I try upgrading HG and see if that fixes it?
Up til now, I have not wanted to upgrade it because it was working well.

Jerry

[JerryR]

Ok, so I upgraded HG using the built in upgrade utility.
Unfortunately it didn't resolve my problem with HG not updating from the CM15 PRO.
As I mentioned, it worked fine in the past - in fact it worked fine until about a week ago and then it seemed to stop talking to the CM15PRO.

I have noticed this error in my logfile:
"2015-10-08T06:56:35.1863290-05:00   HomeGenie.System   Console   StdOut/StdErr redirect   Console.Output   X10 ! Submit Async Read Failed."            
"2015-10-08T06:56:35.2226510-05:00   HomeGenie.System   Console   StdOut/StdErr redirect   Console.Output   X10 !   at XTenLib.Drivers.CM15.ReadData () [0x00000] in <filename unknown>:0 "            
  at XTenLib.XTenManager.ReaderThreadLoop () [0x00000] in <filename unknown>:0             
"2015-10-08T06:56:35.2260650-05:00   HomeGenie.System   Console   StdOut/StdErr redirect   Console.Output   X10 ! Submit Async Read Failed."            
"2015-10-08T06:56:35.2269740-05:00   HomeGenie.System   Console   StdOut/StdErr redirect   Console.Output   X10 !   at XTenLib.Drivers.CM15.ReadData () [0x00000] in <filename unknown>:0 "            
  at XTenLib.XTenManager.ReaderThreadLoop () [0x00000] in <filename unknown>:0             
"2015-10-08T06:56:35.2314410-05:00   HomeGenie.System   Console   StdOut/StdErr redirect   Console.Output   X10 ! Submit Async Read Failed."            
"2015-10-08T06:56:35.2323670-05:00   HomeGenie.System   Console   StdOut/StdErr redirect   Console.Output   X10 !   at XTenLib.Drivers.CM15.ReadData () [0x00000] in <filename unknown>:0 "            
  at XTenLib.XTenManager.ReaderThreadLoop () [0x00000] in <filename unknown>:0       

Do you think this async read failure is indicating a hardware problem?
My CM15a is plugged into a hub and the hub is plugged into my Raspberry Pi.
I think I will try connecting the CM15A directly and see if that helps.

Any tips are surely welcomed.
Jerry      

[JerryR]

I did some digging through the code in x10-lib-dotnet and it appears that my installation is simply having a problem reading data from the CM15.   

I suppose that could be because of a failed USB port in the RaspPi, a failed connection to the powered USB hub I am using, or a bad hub, or finally a bad CM15a.

I plan to try directly connecting my CM15 to my RPi and if that works, I will investigate the hub.

I thought I would leave these comments in the hope that it might help someone else in the future that encounters this same problem.

Kind regards,
Jerry

[petediscrete]

You've fairly well troubleshooted your original problem. The two options I'd select now was to try your CM15Pro on a Windows machine to rule out any problems there. The second option would be to do a fresh install of HG on your PI to rule out any broken packages. I try to avoid USB hubs on the PI in general and the built in HG updater can be flaky sometimes.

[JerryR]

Thank you for the reply.

The read error (Submit Async Read Failed) I was getting seemed like it might be pointing to some type of hardware problem with the CM15 but I wasn't sure.

I did move the CM15 USB connection from the hub to the Pi directly and fiddled with connect/disconnect for both the USB and power connections. It didn't seem to be working regardless of what I tried. However some combination of things did seem to get it working for a few hours over the weekend and then it quit again.

Currently it is not working though it does show up in 'lsusb' and I am not seeing that previous error in the homegenie.log file but the HG doesn't seem to respond to any of the DS10A events. They don't show up in the log and therefore it appears nothing is happening. I did try the online updater - perhaps I should rip it out and reinstall it.... ugh

I liked your idea of trying it with Windows and I will do just that.
You might correct me Pete but I assume you meant for me to test it with HG on Windows ? (or did you have some other program in mind?)

Thanks for your comments and thoughtful suggestions. I will give that a try and let you know how it goes.
I've had this CM15a PRO for quite a long time so maybe it's flaking out but that just seems kind of odd timing-wise and the fact that it does show up in 'lsusb'.

I'll get back to you.
Jerry

[JerryR]

Ok, so I tried the CM15a with AHP on my Windows 7 machine and it works fine.
However, when I try it with HG on the same machine under Win7, I get this error message in the log (and it is not working with my DS10A devices):

Timestamp   Property   Value   Source   Domain
3:08:40.305 PM   Console.Output   System.NullReferenceException: Object reference not set to an instance of an object. at MIG.MIGService.webGateway_ProcessRequest(Object gwRequest) in c:\Users\IEUser\Desktop\HomeGenie\MigFiles\MIG\MIGService.cs:line 477 at MIG.Gateways.WebServiceGateway.Worker(Object state) in c:\Users\IEUser\Desktop\HomeGenie\MigFiles\MIG\Gateways\WebServiceGateway.cs:line 217   Console   HomeGenie.System


Can anyone tell me what this null object reference is about?

Thanks,
Jerry

[petediscrete]

I'm thinking there's a problem with the latest version of HG. Google HG earlier versions and work your way backwards until you find a stable version that works for you. I'm certainly no HG expert but I tend to stick with a version of any application version that works for me. Libusb drivers are notoriously temperamental and they may well be the source of your problem. Again some of the experts may well want to jump in here.

[JerryR]

Pete,

Thanks for hanging in there with me and for your helpful suggestions.
Actually I found that the older 1.0 version was having problems working with my CM15 for some reason - after working many months just fine. I'm not sure what changed.

I tried it under Windows like you suggested and it wasn't working there either.

So, I upgraded to 1.1 in Windows and to my surprise it worked. So then I upgraded my RaspPi to the 1.1 version and it worked too.

Thus I am think I am working again!  Thanks so very much for your help.

Jerry

[JerryR]

Update - I am still finding issues where HG seems to quit talking to the CM15.

Running the 1.1 software, it works sometimes but it is hard to predict why or when it will fail.
It does seem to be indicating some problem with async reading of the USB port when this happens as shown in the previous logs I posted. Those logs were with 1.0 HG.

I have had some limited success by restarting only the CM15. I turn the power off to it leaving my Pi running as well as HG and then sometimes HG will reconnect with the CM15. The amount of time it works after that is widely variable. Over the last few days I found that the connection was lasting merely an hour or two. Today, it has run all day since I reset it this morning around 7AM. So, that's almost 12 hours of successful operation.

I don't know if this could be a problem with the driver talking to the CM15 or something in HG itself (I suspect the driver).
If anyone else is seeing this type of behavior, I would be interested in hearing from you.

Thank you,
Jerry

[petediscrete]

I assume you are plugging the CM15Pro directly into the RPI and not through a powered USB hub.

[bkenobi]

Just as a reference point, I have a CM15A connected directly to my RPi and it has been working fine for close to 2 years.  Is it possible the CM15A is failing?  Could you try it with a different system (Windows + AHP perhaps)?

[petediscrete]

I think the powered USB hubs tend to cause problems particularly when used with x10. Had intermittent problems with one a while back but as soon as I plugged the CM15Pro directly into the RPI haven't had a problem since.