MX via VirtualVP - trouble maintaining data flow

[freddie]

Since approximately release 3013, MX data flow keeps freezing. Last message displayed in VirtualVP virtual console is:

"Sent response for unknown command"

It happens about 90 seconds after a restart - after the archive data has been retrieved, and the loop data downloads have started.

There is no indication (in the Virtual VP console or in the MXDiags that the connection has dropped.

I would like to help to debug this.

MXDiags is attached.

20150129-202720.txt

[steve]

I'll have to add some more logging of the packets - I need to do this for the issue with the WiFi connector reported in another thread. Is it not possible to get VVP to actually show the unknown command that it's complaining about? The only things I've added recently are to read and set the clock, but those happen just after startup anyway. You do have LOOP2 disabled, yes?

[steve]

I've been doing some experimenting with VVP, and I see the same thing, and I think I have fixed it. One thing I don't understand is that VVP seems to recognise the command to read the clock, but doesn't seem to be able to read it from the console:

11:17:41:530 Info - Virtual Console5: Received Get Time
11:17:41:545 Verbose - VpConsole: Queueing Wake Up Console
11:17:41:545 Verbose - VpConsole: Queueing Get Time
11:17:41:592 Verbose - VpConsole: WakeUp send not needed (console already awake)
11:17:41:608 Info - VpConsole: Sending Get Time
11:17:42:029 Info - VpConsole: No response received for Get Time

I don't know if it was the introduction of reading the clock that started to make things go wrong, but I'll fix the code (the problem isn't with the 'get time' command itself) and see if that improves things.

[freddie]

I'll have to add some more logging of the packets

That would be really useful.

Is it not possible to get VVP to actually show the unknown command that it's complaining about?

I'll look into it, and get back to you.

You do have LOOP2 disabled, yes?

Definitely yes - following our earlier conversations!!

[freddie]

Sorry, I only just noticed your earlier post after I sent mine. I thought I'd sent it earlier but it was just sat there in a browser tab!!

[freddie]

MX just ran from 11:24 to 12:38 without stopping. I had the debug window open on VVP, but it must have a small buffer, as the last commands to/from the MX virtual console were long gone Do you need me to repeat the experiment to try and catch the commands in the debug log? Or was your earlier discovery sufficient to explain the problem and solve it?

[steve]

I didn't do too much testing, but to begin with I was regularly getting the 'unknown command' messages, and when I did the change I was no longer seeing them. It did continue fetching data in both cases for several minutes, though. I'll have the new build available later today, so the maybe the best thing to do would be to wait for that and see what happens.

[freddie]

maybe the best thing to do would be to wait for that and see what happens.

Okay I will do that. Many thanks to you for your speedy response to the issues with MX.

[steve]

If you'd like to give 3017 a try when you have chance, it might be an improvement.

[freddie]

If you'd like to give 3017 a try when you have chance, it might be an improvement.

I installed 3017 late last night. The restart was just after midnight. I checked VVP to see that the connection had been made, then I logged off. Looking at http://www.hosiene.co.uk/weather-test/trends.htm this morning, it appears that no data flowed until 0400. Isn't that when the clock reset command is sent? I will attach MXdiags in a bit when I get up (sending this from my phone).

[steve]

I checked VVP to see that the connection had been made, then I logged off

Had VVP started sending LOOP packets to MX?

What version of VVP are you using? What firmware version does your console have?

[freddie]

Had VVP started sending LOOP packets to MX?

I think so.

What version of VVP are you using?

1.25 (Sep 2010)

What firmware version does your console have?

3.12 (2013)

Here's the diags file:

20150131-001602.txt

[steve]

It seems that sometimes VVP is sending additional characters as part of the protocol exchange for downloading the archive data:

2015-01-31 00:16:11.543 Received response to DMPAFT, sending date and time
2015-01-31 00:16:11.544 3F-1E-06-00-0A-C3
2015-01-31 00:16:12.044 Received 0x06
2015-01-31 00:16:12.044 ACK received
2015-01-31 00:16:12.044 Response:
10 00 1F 01 73 9B
2015-01-31 00:16:12.045
2015-01-31 00:16:12.045 Reading data: 16 pages , offset = 287
bad CRC

The result is what looks like a bad CRC, but it's actually because the data is now off by a byte. I've added more logging, and I can see this sometimes when I start up MX using VVP:

2015-01-31 10:51:16.853 Received response to DMPAFT, sending date and time
2015-01-31 10:51:16.853 3F-1E-15-04-1C-67
2015-01-31 10:51:17.368 Received 0x0F
2015-01-31 10:51:17.368 Received 0x33
2015-01-31 10:51:17.368 Received 0x0A
2015-01-31 10:51:17.368 Received 0x1F
2015-01-31 10:51:17.368 Received 0x01
2015-01-31 10:51:17.368 Received 0x73
2015-01-31 10:51:17.368 Received 0x5D
2015-01-31 10:51:17.368 Received 0x03
2015-01-31 10:51:17.368 Received 0x0A
2015-01-31 10:51:17.368 Received 0x0D
2015-01-31 10:51:17.368 Received 0x06
2015-01-31 10:51:17.368 ACK received
2015-01-31 10:51:17.368 Response:
06 01 00 03 00 23
2015-01-31 10:51:17.368
2015-01-31 10:51:17.368 Reading data: 262 pages , offset = 768
2015-01-31 10:51:17.368 Data: B2-00-3F-1E-0B-04-9B-01-9C-01-9A-01-00-00-00-00-7A-71-20-00-70-00-75-02-36-50-24-2F-0F-0F-FF-00-25-00-FF-87-FF-FF-FF-FF-FF-FF-FF-FF-00-FF-FF-FF-FF-FF-FF-FF-FF-FF-3F-1E-10-04-9A-01-9B-01-9A-01-00-00-00-00-76-71-1D-00-70-00-73-02-36-55-27-30-0F-0F-FF-00-21-00-FF-87-FF-FF-FF-FF-FF-FF-FF-FF-00-FF-FF-FF-FF-FF-FF-FF-FF-FF-3F-1E-15-04-9B-01-9B-01-9A-01-00-00-00-00-71-71-28-00-6F-00-71-02-36-4F-2C-3A-00-0F-FF-00-33-00-FF-87-FF-FF-FF-FF-FF-FF-FF-FF-00-FF-FF-FF-FF-FF-FF-FF-FF-FF-3F-1E-1A-04-9E-01-9E-01-9A-01-00-00-00-00-76-71-38-00-6F-00-71-02-36-4F-28-39-00-0F-FF-00-48-00-FF-87-FF-FF-FF-FF-FF-FF-FF-FF-00-FF-FF-FF-FF-FF-FF-FF-FF-FF-36-1E-37-05-A5-01-A6-01-A5-01-00-00-00-00-3E-75-50-00-72-00-71-02-36-50-15-1C-08-08-FF-00-51-00-FF-2C-FF-FF-FF-FF-FF-FF-FF-FF-00-FF-FF-FF-FF-FF-FF-FF-FF-FF-FF-FF-FF-FF-34
bad CRC

That first 06 isn't part of the response, so everything after that is off by a byte. I have no idea why this happens.

In my case it carries on and received the loop data OK, but I'm guessing that in your case everything was still out of sync until it set the clock.

[steve]

Ah, hold on, maybe this is data left over from the previous connection. The stuff that Boris (Meteobridge) said I needed to discard

[steve]

I give up. I've added code to send a CR to stop any loop data, and then read data from the socket until nothing has arrived for 200ms. But still I get extra/garbage data later on:

2015-01-31 11:23:03.791 Station type = Davis
2015-01-31 11:23:03.791 LOOP2 disabled
2015-01-31 11:23:03.791 IP address = 127.0.0.1 Port = 5511
2015-01-31 11:23:03.791 Connected OK
2015-01-31 11:23:03.791 Flushing input stream
2015-01-31 11:23:03.994 Received 0x0A
2015-01-31 11:23:04.197 Received 0x0D
2015-01-31 11:23:04.400 Last update time = 31/01/2015 11:20:00
2015-01-31 11:23:04.400 Setting console time
2015-01-31 11:23:05.429 Received 0x0A
2015-01-31 11:23:05.429 Received 0x0D
2015-01-31 11:23:05.429 Received 0x06
2015-01-31 11:23:05.429 ACK received
2015-01-31 11:23:05.944 Received 0x06
2015-01-31 11:23:05.944 ACK received
2015-01-31 11:23:05.944 Reading console time
2015-01-31 11:23:06.974 Received 0x0A
2015-01-31 11:23:06.974 Received 0x0D
2015-01-31 11:23:06.974 No ACK
2015-01-31 11:23:06.974 Start reading archive data
2015-01-31 11:23:06.974 Reading archive data
2015-01-31 11:23:06.974 Loading last N hour data from data logs: 31/01/2015 11:20:00
2015-01-31 11:23:07.161 Loaded 13 entries to last hour data list
2015-01-31 11:23:07.364 Loaded 37 entries to last 3 hour data list
2015-01-31 11:23:07.535 Loaded 289 entries to last 24 hour data list
2015-01-31 11:23:07.785 Loaded 2016 entries to recent data list
2015-01-31 11:23:07.785 Get Archive Data
2015-01-31 11:23:07.785 Rollover hour = 9
2015-01-31 11:23:07.785 Last Archive Date: 31/01/2015 11:20:00
2015-01-31 11:23:07.785 Date: 7743
2015-01-31 11:23:07.785 Time: 1120
2015-01-31 11:23:07.801 624 web tags initialised
2015-01-31 11:23:07.879 HTML root path = D:\Cumulus\interface
2015-01-31 11:23:07.925 Starting web socket server on port 8002
2015-01-31 11:23:08.815 Received response to DMPAFT, sending date and time
2015-01-31 11:23:08.815 3F-1E-60-04-EB-CB
2015-01-31 11:23:09.329 Received 0x07
2015-01-31 11:23:09.329 Received 0x17
2015-01-31 11:23:09.329 Received 0x0B
2015-01-31 11:23:09.329 Received 0x1F
2015-01-31 11:23:09.329 Received 0x01
2015-01-31 11:23:09.329 Received 0x73
2015-01-31 11:23:09.329 Received 0xA7
2015-01-31 11:23:09.329 Received 0x47
2015-01-31 11:23:09.329 Received 0x0A
2015-01-31 11:23:09.329 Received 0x0D
2015-01-31 11:23:09.329 Received 0x06
2015-01-31 11:23:09.329 ACK received
2015-01-31 11:23:09.329 Response:06-00-02-00-00-6E
2015-01-31 11:23:09.329 Reading data: 6 pages , offset = 2
2015-01-31 11:23:09.329 Data: C2-00-36-1E-7D-05-A1-01-A2-01-A1-01-00-00-00-00-37-75-38-00-73-00-75-02-37-51-13-1C-08-08-FF-00-3E-00-FF-2C-FF-FF-FF-FF-FF-FF-FF-FF-00-FF-FF-FF-FF-FF-FF-FF-FF-FF-36-1E-82-05-A0-01-A1-01-A0-01-00-00-00-00-33-75-2D-00-72-00-78-02-37-51-13-1A-08-08-FF-00-31-00-FF-2C-FF-FF-FF-FF-FF-FF-FF-FF-00-FF-FF-FF-FF-FF-FF-FF-FF-FF-36-1E-87-05-A0-01-A0-01-9F-01-00-00-00-00-30-75-27-00-71-00-7C-02-37-51-12-19-08-08-FF-00-28-00-FF-2C-FF-FF-FF-FF-FF-FF-FF-FF-00-FF-FF-FF-FF-FF-FF-FF-FF-FF-36-1E-8C-05-9F-01-9F-01-9E-01-00-00-00-00-2B-75-23-00-73-00-80-02-37-51-14-18-08-08-FF-00-25-00-FF-2C-FF-FF-FF-FF-FF-FF-FF-FF-00-FF-FF-FF-FF-FF-FF-FF-FF-FF-36-1E-91-05-9E-01-9F-01-9E-01-00-00-00-00-2A-75-23-00-72-00-85-02-37-51-11-18-08-08-FF-00-27-00-FF-2C-FF-FF-FF-FF-FF-FF-FF-FF-00-FF-FF-FF-FF-FF-FF-FF-FF-FF-FF-FF-FF-FF-F7
bad CRC

What's all that stuff in response to the DMPAFT date and time? Someone please tell me what's going on...

Edit: It's the clock time finally turning up!