HG on RasPi crashed for no reason

[bkenobi]

I've had my Raspi up and running well for quite some time and out of the blue it had a crash.  The only thing that's changed recently is that we had a power failure last weekend (10/25-10/26) that caused an uncontrolled shutdown.  However, this crash occurred on 10/28, so I can't say it's related to that.

Code: [Select]

2014-10-28T06:47:28.8100210-07:00       HomeAutomation.X10      A4      -      Status.Level     1
2014-10-28T06:47:28.8114240-07:00       HomeAutomation.HomeGenie.Automation    84       Automation Program      X10 Auto Bright Kennel light<br>A4 set to 100%
[06:47:28.814106] X10 ! Collection was modified; enumeration operation may not execute.
[06:47:28.815255] X10 !   at System.Collections.Generic.List`1+Enumerator[XTenLib.X10Module].MoveNext () [0x00000] in <filename unknown>:0
  at XTenLib.XTenManager.ModulesOn (System.String housecode) [0x00000] in <filename unknown>:0
  at XTenLib.XTenManager.ReaderThreadLoop () [0x00000] in <filename unknown>:0
[06:47:29.314762] X10 < 04 6A
[06:47:29.562232] X10 ! Thread was being aborted
[06:47:29.563423] X10 !   at (wrapper managed-to-native) System.Threading.WaitHandle:WaitAll_internal (System.Threading.WaitHandle[],int,bool)
  at System.Threading.WaitHandle.WaitAll (System.Threading.WaitHandle[] waitHandles, Int32 millisecondsTimeout, Boolean exitContext) [0x00000] in <filename unknown>:0
  at XTenLib.Drivers.CM15.ReadData () [0x00000] in <filename unknown>:0
  at XTenLib.XTenManager.ReaderThreadLoop () [0x00000] in <filename unknown>:0
2014-10-28T06:47:38.7884830-07:00       HomeAutomation.HomeGenie.Automation    35       Automation Program      Program.Status  Running
2014-10-28T06:47:39.0739330-07:00       HomeAutomation.HomeGenie.Automation    35       Automation Program      Program.Status  Idle

That's the last data saved to my log of mono output.  I don't see anything that would cause a crash at the time of shutdown but 10 seconds earlier there was an error.

I've looked at the remainder of the mono log and I'm seeing a lot of errors that are similar to this one.  I don't know what it means, but I'm happy to provide any details that could help nail down the error of the cause.

[bkenobi]

I haven't seen any other crashes, so perhaps this was an anomaly.  I'm seeing lots of error messages in my mono log recently though.  I can't say that this is related or just a coincidence.  I would like to fix any errors so as not to knowingly let them remain.  I will log these on github.  The errors I'm seeing are as follows.  I'm running r415 currently.

I believe this is in the "Set to 100% when switched on" code:

Code: [Select]

2014-11-03T18:26:01.4585020-08:00 HomeAutomation.HomeGenie.Automation 84 Automation Program Runtime.Error TC:   at System.Collections.Generic.List`1+Enumerator[HomeGenie.Data.ModuleParameter].MoveNext () [0x00000] in <filename unknown>:0    at HomeGenie.Automation.Scripting.ProgramHelper.Setup (System.Action functionBlock) [0x00000] in <filename unknown>:0
I assume this is 2 linked errors related to WU:

Code: [Select]

2014-11-03T22:28:22.2114650-08:00 HomeAutomation.HomeGenie.Automation NetHelper Error getting response stream (ReadDone1): ReceiveFailure Exception.StackTrace   at System.Net.HttpWebRequest.EndGetResponse (IAsyncResult asyncResult) [0x00000] in <filename unknown>:0
  at System.Net.HttpWebRequest.GetResponse () [0x00000] in <filename unknown>:0
  at System.Net.WebClient.GetWebResponse (System.Net.WebRequest request) [0x00000] in <filename unknown>:0
  at System.Net.WebClient.ReadAll (System.Net.WebRequest request, System.Object userToken) [0x00000] in <filename unknown>:0
  at System.Net.WebClient.DownloadDataCore (System.Uri address, System.Object userToken) [0x00000] in <filename unknown>:0
2014-11-03T22:28:22.2403510-08:00 HomeAutomation.HomeGenie.Automation 34 Automation Program Weather Underground ERROR! Unable to get data from service.
`string' does not contain a definition for `moon_phase'

This is a similar error, but the first part is slightly different.  I was getting this error prior to 11/3:

Code: [Select]

2014-10-31T17:22:08.4779400-07:00 HomeAutomation.HomeGenie.Automation NetHelper The request timed out Exception.StackTrace   at System.Net.HttpWebRequest.EndGetResponse (IAsyncResult asyncResult) [0x00000] in <filename unknown>:0
  at System.Net.HttpWebRequest.GetResponse () [0x00000] in <filename unknown>:0
  at System.Net.WebClient.GetWebResponse (System.Net.WebRequest request) [0x00000] in <filename unknown>:0
  at System.Net.WebClient.ReadAll (System.Net.WebRequest request, System.Object userToken) [0x00000] in <filename unknown>:0
  at System.Net.WebClient.DownloadDataCore (System.Uri address, System.Object userToken) [0x00000] in <filename unknown>:0
2014-10-31T17:22:08.4823710-07:00 HomeAutomation.HomeGenie.Automation 34 Automation Program Weather Underground ERROR! Unable to get data from service.
`string' does not contain a definition for `moon_phase'
This specific error seems to indicate that HG is looking for a string "moon_phase".  I looked at the WU json data and I'm not seeing that string, so it looks like my weather station doesn't provide that information.

http://api.wunderground.com/api/2e3c54507f556b99/conditions/q/Seattle.json

Code: [Select]

{
  "response": {
  "version":"0.1",
  "termsofService":"http://www.wunderground.com/weather/api/d/terms.html",
  "features": {
  "conditions": 1
  }
}
  , "current_observation": {
"image": {
"url":"http://icons.wxug.com/graphics/wu2/logo_130x80.png",
"title":"Weather Underground",
"link":"http://www.wunderground.com"
},
"display_location": {
"full":"Seattle, WA",
"city":"Seattle",
"state":"WA",
"state_name":"Washington",
"country":"US",
"country_iso3166":"US",
"zip":"98101",
"magic":"1",
"wmo":"99999",
"latitude":"47.61167908",
"longitude":"-122.33325958",
"elevation":"63.00000000"
},
"observation_location": {
"full":"UW Integrated Design Lab, Bullitt Center, Seattle, Washington",
"city":"UW Integrated Design Lab, Bullitt Center, Seattle",
"state":"Washington",
"country":"US",
"country_iso3166":"US",
"latitude":"47.614361",
"longitude":"-122.312439",
"elevation":"404 ft"
},
"estimated": {
},
"station_id":"KWASEATT182",
"observation_time":"Last Updated on November 4, 7:55 AM PST",
"observation_time_rfc822":"Tue, 04 Nov 2014 07:55:36 -0800",
"observation_epoch":"1415116536",
"local_time_rfc822":"Tue, 04 Nov 2014 07:55:37 -0800",
"local_epoch":"1415116537",
"local_tz_short":"PST",
"local_tz_long":"America/Los_Angeles",
"local_tz_offset":"-0800",
"weather":"Overcast",
"temperature_string":"53.5 F (11.9 C)",
"temp_f":53.5,
"temp_c":11.9,
"relative_humidity":"97%",
"wind_string":"From the SSE at 4.0 MPH Gusting to 9.0 MPH",
"wind_dir":"SSE",
"wind_degrees":150,
"wind_mph":4.0,
"wind_gust_mph":"9.0",
"wind_kph":6.4,
"wind_gust_kph":"14.5",
"pressure_mb":"1016",
"pressure_in":"30.00",
"pressure_trend":"+",
"dewpoint_string":"53 F (12 C)",
"dewpoint_f":53,
"dewpoint_c":12,
"heat_index_string":"NA",
"heat_index_f":"NA",
"heat_index_c":"NA",
"windchill_string":"NA",
"windchill_f":"NA",
"windchill_c":"NA",
"feelslike_string":"53.5 F (11.9 C)",
"feelslike_f":"53.5",
"feelslike_c":"11.9",
"visibility_mi":"4.0",
"visibility_km":"6.4",
"solarradiation":"12",
"UV":"0.0","precip_1hr_string":"0.00 in ( 0 mm)",
"precip_1hr_in":"0.00",
"precip_1hr_metric":" 0",
"precip_today_string":"0.07 in (2 mm)",
"precip_today_in":"0.07",
"precip_today_metric":"2",
"icon":"cloudy",
"icon_url":"http://icons.wxug.com/i/c/k/cloudy.gif",
"forecast_url":"http://www.wunderground.com/US/WA/Seattle.html",
"history_url":"http://www.wunderground.com/weatherstation/WXDailyHistory.asp?ID=KWASEATT182",
"ob_url":"http://www.wunderground.com/cgi-bin/findweather/getForecast?query=47.614361,-122.312439",
"nowcast":""
}
}


I'm also seeing issues with OpenWeather (icon is purple until enabled, then it's red), but that's not your code so I'll have to post that in Jan's thread.


Looking at my logs, I also found one instance of some kind of error during X10 operation.  It appears this was triggered right after widget 84 fired, so perhaps it's the same issue as above.

Code: [Select]

2014-10-22T06:58:20.6064030-07:00 HomeAutomation.HomeGenie.Automation 84 Automation Program X10 Auto Bright Kennel light<br>A4 set to 100%
[06:58:20.608944] X10 ! Collection was modified; enumeration operation may not execute.
[06:58:20.610088] X10 !   at System.Collections.Generic.List`1+Enumerator[XTenLib.X10Module].MoveNext () [0x00000] in <filename unknown>:0
  at XTenLib.XTenManager.ModulesOn (System.String housecode) [0x00000] in <filename unknown>:0
  at XTenLib.XTenManager.ReaderThreadLoop () [0x00000] in <filename unknown>:0
[06:58:21.022607] X10 ! Thread was being aborted
[06:58:21.024040] X10 !   at (wrapper managed-to-native) System.Threading.WaitHandle:WaitAll_internal (System.Threading.WaitHandle[],int,bool)
  at System.Threading.WaitHandle.WaitAll (System.Threading.WaitHandle[] waitHandles, Int32 millisecondsTimeout, Boolean exitContext) [0x00000] in <filename unknown>:0
  at XTenLib.Drivers.CM15.ReadData () [0x00000] in <filename unknown>:0
  at XTenLib.XTenManager.ReaderThreadLoop () [0x00000] in <filename unknown>:0
[06:58:21.088869] X10 < 04 6A
[06:58:21.089918] X10 ! The object was used after being disposed.
[06:58:21.092092] X10 !   at System.Runtime.InteropServices.SafeHandle.DangerousGetHandle () [0x00000] in <filename unknown>:0
  at LibUsbDotNet.LudnMonoLibUsb.Internal.MonoUsbTransferContext.Fill (IntPtr buffer, Int32 offset, Int32 count, Int32 timeout) [0x00000] in <filename unknown>:0
  at LibUsbDotNet.Main.UsbTransfer.Fill (System.Object buffer, Int32 offset, Int32 count, Int32 timeout) [0x00000] in <filename unknown>:0
  at LibUsbDotNet.Main.UsbEndpointBase.SubmitAsyncTransfer (System.Object buffer, Int32 offset, Int32 length, Int32 timeout, LibUsbDotNet.Main.UsbTransfer& transferContext) [0x00000] in <filename unknown>:0
  at XTenLib.Drivers.CM15.WriteData (System.Byte[] bytesToSend) [0x00000] in <filename unknown>:0
  at XTenLib.XTenManager.SendMessage (System.Byte[] message) [0x00000] in <filename unknown>:0
[06:58:21.142753] X10 < 06 65 D2
[06:58:21.143700] X10 ! The object was used after being disposed.
[06:58:21.145334] X10 !   at System.Runtime.InteropServices.SafeHandle.DangerousGetHandle () [0x00000] in <filename unknown>:0
  at LibUsbDotNet.LudnMonoLibUsb.Internal.MonoUsbTransferContext.Fill (IntPtr buffer, Int32 offset, Int32 count, Int32 timeout) [0x00000] in <filename unknown>:0
  at LibUsbDotNet.Main.UsbTransfer.Fill (System.Object buffer, Int32 offset, Int32 count, Int32 timeout) [0x00000] in <filename unknown>:0
  at LibUsbDotNet.Main.UsbEndpointBase.SubmitAsyncTransfer (System.Object buffer, Int32 offset, Int32 length, Int32 timeout, LibUsbDotNet.Main.UsbTransfer& transferContext) [0x00000] in <filename unknown>:0
  at XTenLib.Drivers.CM15.WriteData (System.Byte[] bytesToSend) [0x00000] in <filename unknown>:0
  at XTenLib.XTenManager.SendMessage (System.Byte[] message) [0x00000] in <filename unknown>:0

[bkenobi]

Well, HG crashed again.  I'm still not clear on the reason, but it stopped at 20:02 and there was an error at approximately the same time.

Code: [Select]

[20:02:48.861618] X10 > 5A 02 00 6E
[20:02:48.862037] X10 > PLCRX: 5A 02 00 6E
[20:02:48.862329] X10 > FNMAP: 00
[20:02:48.862574] X10 >  DATA: 6E
[20:02:48.863051] X10 >       0) House code = A
[20:02:48.863363] X10 >       0)  Unit code = 2
[20:02:49.309652] X10 > 5A 02 00 62
[20:02:49.310048] X10 > PLCRX: 5A 02 00 62
[20:02:49.310327] X10 > FNMAP: 00
[20:02:49.310579] X10 >  DATA: 62
[20:02:49.311052] X10 >       0) House code = A
[20:02:49.311319] X10 >       0)  Unit code = 3
[20:02:49.757696] X10 > 5A 02 00 6A
[20:02:49.758090] X10 > PLCRX: 5A 02 00 6A
[20:02:49.758376] X10 > FNMAP: 00
[20:02:49.758619] X10 >  DATA: 6A
[20:02:49.759087] X10 >       0) House code = A
[20:02:49.759355] X10 >       0)  Unit code = 4
[20:02:50.206373] X10 > 5A 02 01 62
[20:02:50.206769] X10 > PLCRX: 5A 02 01 62
[20:02:50.207067] X10 > FNMAP: 01
[20:02:50.207312] X10 >  DATA: 62
[20:02:50.207768] X10 >       0) House code = A
[20:02:50.208036] X10 >       0)    Command = ON
2014-11-18T20:02:50.2089860-08:00 HomeAutomation.X10 A4 - Status.Level 1
2014-11-18T20:02:50.2102120-08:00 HomeAutomation.HomeGenie.Automation 84 Automation Program X10 Auto Bright Kennel light<br>A4 set to 100%
[20:02:50.212820] X10 ! Collection was modified; enumeration operation may not execute.
[20:02:50.213747] X10 !   at System.Collections.Generic.List`1+Enumerator[XTenLib.X10Module].MoveNext () [0x00000] in <filename unknown>:0
  at XTenLib.XTenManager.ModulesOn (System.String housecode) [0x00000] in <filename unknown>:0
  at XTenLib.XTenManager.ReaderThreadLoop () [0x00000] in <filename unknown>:0
[20:02:50.717283] X10 < 04 6A
[20:02:50.721400] X10 ! Thread was being aborted
[20:02:50.722481] X10 !   at (wrapper managed-to-native) System.Threading.WaitHandle:WaitAll_internal (System.Threading.WaitHandle[],int,bool)
  at System.Threading.WaitHandle.WaitAll (System.Threading.WaitHandle[] waitHandles, Int32 millisecondsTimeout, Boolean exitContext) [0x00000] in <filename unknown>:0
  at XTenLib.Drivers.CM15.ReadData () [0x00000] in <filename unknown>:0
  at XTenLib.XTenManager.ReaderThreadLoop () [0x00000] in <filename unknown>:0
2014-11-18T20:02:53.2023150-08:00 HomeAutomation.HomeGenie.Automation 35 Automation Program Program.Status Running
2014-11-18T20:02:53.3682420-08:00 HomeAutomation.HomeGenie.Automation 35 Automation Program Program.Status Idle

I am still running an older version of HG, so I'll try updating this evening.  I don't see anything in the update notes to suggest that anything will improve, but it's worth a try.

Suggestions?