Index out of bounds

[Sneezy24]

A couple of weeks ago I realised that I was way down level on CumulusMX (3.8.?) so decided to upgrade.

Station is a WMR200 - everything was working fine, but thought going to the latest level would be good.

Downloaded the pi image, installed fine, copied my old dat over, worked fine for a couple of days, so then went to what was the latest (3.11.4 b3133).

Ran fine again for a couple of days, then appeared to stop getting data. Restarted Cumulus, all good again.

Ran fine for another 2-3 days, stopped again. Restarted Cumulus, enables logging.

Ran fine, stopped just after 02:00 this morning.

Log reports and 'Index out of bounds'

2021-07-12 02:04:57.373 Sending heartbeat
2021-07-12 02:05:00.475 Current CPU temp = 39.2°C
2021-07-12 02:05:03.186 Data read loop: The operation has timed out.
2021-07-12 02:05:08.445 Realtime[222]: Start cycle
2021-07-12 02:05:08.446 Realtime[222]: Creating realtime.txt
2021-07-12 02:05:08.447 Realtime[222]: Processing realtime file - realtimegauges.txt
2021-07-12 02:05:08.987 Realtime[222]: Uploading - realtime.txt
2021-07-12 02:05:09.146 Realtime[222]: Uploading - realtimegauges.txt
2021-07-12 02:05:09.313 Realtime[222]: End cycle
2021-07-12 02:05:09.322 Data read loop: The operation has timed out.
2021-07-12 02:05:12.322 Data read loop: The operation has timed out.
2021-07-12 02:05:15.323 Data read loop: The operation has timed out.
2021-07-12 02:05:18.945 Data read loop: The operation has timed out.
2021-07-12 02:05:23.322 Data read loop: The operation has timed out.
2021-07-12 02:05:27.373 Sending heartbeat
2021-07-12 02:05:30.378 Data read loop: The operation has timed out.
2021-07-12 02:05:33.378 Data read loop: The operation has timed out.
2021-07-12 02:05:38.445 Realtime[223]: Start cycle
2021-07-12 02:05:38.446 Realtime[223]: Creating realtime.txt
2021-07-12 02:05:38.447 Realtime[223]: Processing realtime file - realtimegauges.txt
2021-07-12 02:05:38.945 Data read loop: The operation has timed out.
2021-07-12 02:05:38.989 Realtime[223]: Uploading - realtime.txt
2021-07-12 02:05:39.139 Realtime[223]: Uploading - realtimegauges.txt
2021-07-12 02:05:39.296 Realtime[223]: End cycle
2021-07-12 02:05:41.946 Data read loop: The operation has timed out.
2021-07-12 02:05:48.945 Data read loop: The operation has timed out.
2021-07-12 02:05:53.930 Data read loop: The operation has timed out.
2021-07-12 02:05:57.373 Sending heartbeat
2021-07-12 02:06:00.478 *** Data input appears to have stopped
2021-07-12 02:06:00.479 Current CPU temp = 39.2°C
2021-07-12 02:06:03.185 Data read loop: The operation has timed out.
2021-07-12 02:06:08.410 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:08.425 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:08.441 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:08.458 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:08.473 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:08.489 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:08.505 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:11.506 Data read loop: The operation has timed out.
2021-07-12 02:06:14.506 Data read loop: The operation has timed out.
2021-07-12 02:06:15.908 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:15.921 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:15.937 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:15.953 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:16.270 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:16.281 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:16.297 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:16.313 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:19.314 Data read loop: The operation has timed out.
2021-07-12 02:06:22.314 Data read loop: The operation has timed out.
2021-07-12 02:06:25.315 Data read loop: The operation has timed out.
2021-07-12 02:06:25.895 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:25.913 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:25.929 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:25.945 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:27.373 Sending heartbeat
2021-07-12 02:06:27.381 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:29.933 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:29.945 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:29.961 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:29.977 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:29.993 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:30.270 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:30.281 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:30.297 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:30.313 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:33.314 Data read loop: The operation has timed out.
2021-07-12 02:06:35.895 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:35.913 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:35.929 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:35.945 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:38.945 Data read loop: The operation has timed out.
2021-07-12 02:06:41.950 Data read loop: The operation has timed out.
2021-07-12 02:06:44.951 Data read loop: The operation has timed out.
2021-07-12 02:06:45.895 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:45.913 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:45.929 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:45.945 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:48.946 Data read loop: The operation has timed out.
2021-07-12 02:06:50.884 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:50.897 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:50.913 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:50.929 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:53.929 Data read loop: The operation has timed out.
2021-07-12 02:06:55.894 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:55.905 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:55.921 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:55.937 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:06:57.373 Sending heartbeat
2021-07-12 02:06:57.377 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:07:00.152 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:07:00.169 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:07:00.185 Data read loop: Index was outside the bounds of the array.
2021-07-12 02:07:00.484 *** Data input appears to have stopped
2021-07-12 02:07:00.485 Current CPU temp = 39.7°C
2021-07-12 02:07:01.394 Data read loop: Index was outside the bounds of the array.

Any ideas??

[mcrossley]

It looks like some sort of issue with the stations connectivity. Can you do things like change the cables?

Also switch on debug and data logging and see if that provides any additional information (I don't really hold out much hope though).

[Sneezy24]

Thanks Mark,

I've since looked at syslog and noticed I was getting low voltage warnings.

I've replaced the PSU and USB cable and they have gone away.

I'll see if the 'Index' error comes back.

Logging is enabled.

Mick

[Sneezy24]

After months of zero problems, this has come back again!

It happens 3-4 times a week, no pattern, various times of day and night.

2021-10-08 00:26:16.899 Data read loop: Index was outside the bounds of the array.
2021-10-08 00:26:16.899 Calling Read
2021-10-08 00:26:19.900 Data read loop: The operation has timed out.
2021-10-08 00:26:19.900 Calling Read
2021-10-08 00:26:22.901 Data read loop: The operation has timed out.
2021-10-08 00:26:22.901 Calling Read
2021-10-08 00:26:23.788 Sending heartbeat
2021-10-08 00:26:23.792 Bytes read 9 = 01 D1 3B 8C 00 00 CE 02
2021-10-08 00:26:23.792 Data read loop: Index was outside the bounds of the array.
2021-10-08 00:26:23.793 Calling Read
2021-10-08 00:26:26.793 Data read loop: The operation has timed out.
2021-10-08 00:26:26.793 Calling Read
2021-10-08 00:26:26.907 Bytes read 9 = 01 D7 3B 8C 00 00 CE 02
2021-10-08 00:26:26.907 Data read loop: Index was outside the bounds of the array.
2021-10-08 00:26:26.908 Calling Read
2021-10-08 00:26:26.923 Bytes read 9 = 01 10 3B 8C 00 00 CE 02
2021-10-08 00:26:26.923 Data read loop: Index was outside the bounds of the array.
2021-10-08 00:26:26.923 Calling Read
2021-10-08 00:26:26.939 Bytes read 9 = 07 1A 00 08 0A 15 00 DF
2021-10-08 00:26:26.939 Data read loop: Index was outside the bounds of the array.
2021-10-08 00:26:26.939 Calling Read
2021-10-08 00:26:26.955 Bytes read 9 = 07 00 3B 8C 00 00 CE 02
2021-10-08 00:26:26.955 Data read loop: Index was outside the bounds of the array.
2021-10-08 00:26:26.955 Calling Read
2021-10-08 00:26:29.782 Bytes read 9 = 01 D3 3B 8C 00 00 CE 02
2021-10-08 00:26:29.782 Data read loop: Index was outside the bounds of the array.
2021-10-08 00:26:29.783 Calling Read
2021-10-08 00:26:29.795 Bytes read 9 = 01 10 3B 8C 00 00 CE 02
2021-10-08 00:26:29.795 Data read loop: Index was outside the bounds of the array.
2021-10-08 00:26:29.795 Calling Read
2021-10-08 00:26:29.811 Bytes read 9 = 07 1A 00 08 0A 15 06 0C

A restart of cumulus fixes it until the next time!

Currently on 3.13.3 b3148 (I know b3149 is out).

I have made zero changes to the station, cables, Pi, PSU.

Checked SYSLOG, no low voltage warnings that I can see.

Any ideas? Any more logs I can take?

Station is WMR200.

[mcrossley]

How the WMR data is read is a bit unfamiliar to me, it is hard to tell from that snippet but it looks like the station starts sending 1 byte packets (the length is the first byte printed) which generally seem to mean that the station is saying history data is now available. However the decode appears to be going awry.

The WR200 only starts recording history data if a program is not connected, so was MX disconnected before these events?

[Sneezy24]

No disconnect, the WMR console and Pi and permanently connected and share the same power feed - nothing else on the short extension lead from the wall socket.

Any other logs that would be useful???

[mcrossley]

Not really, your console either stops sending data altogether, or appears to disconnect for while then starts sending historic data packets to catch-up the missed data which CMX will not process unless it is restarted. At the moment it looks like an issue either with the physical connection, USB ports sleeping, or a sick console.

[Sneezy24]

Still getting this intermittently, no apparent pattern to it.

I have changed:

- Raspberry PSU and cable
- USB cable from WMR200 to Pi
- New batteries in the WMR200

Doing a restart of Cumulus sorts it out until next time.

I have set an alarm so I get a mail when this happens (stopped sending data), is there any way I can trigger off this to restart Cumulus without needing to SSH to the Pi??

[Sneezy24]

Strange - the new batteries in the WMR console has lengthened the time between 'hits'.

I have also been playing with a script that runs every 15 mins (via Cron) and checks the log for errors. If found, it restarts Cumulus.

So far, so good.

[mcrossley]

... is there any way I can trigger off this to restart Cumulus without needing to SSH to the Pi??

Not currently, the restart option was not ported across from Cumulus 1, I suspect partly because it is harder to do cross platform. It is further complicated now by CMX being able to run as a service or interactively cross platform.