*** Data input appears to have stopped

[hvd51]

Last night build 3092 installed and this morning 11:45 am the report came:

2020-08-24 11: 45: 54.376 LOOP: Expected data not received, expected 99 bytes, got 0
2020-08-24 11: 45: 56.891 LOOP: Receive error - System.IO.IOException: Unable to read data from the transport connection: A connection attempt failed because the connected party did not answer correctly after a certain time, or the connection established failed because the connected host did not respond. ---> System.Net.Sockets.SocketException: A connection attempt failed because the connected party did not answer correctly after a certain time, or the connection made failed because the connected host did not answer
at System.Net.Sockets.Socket.Receive (Byte [] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at System.Net.Sockets.NetworkStream.Read (Byte [] buffer, Int32 offset, Int32 size)
--- End of internal exception stack path ---
at System.Net.Sockets.NetworkStream.Read (Byte [] buffer, Int32 offset, Int32 size)
at CumulusMX.DavisStation.GetAndProcessLoopData (Int32 number)
2020-08-24 11: 46: 22.766 Realtime [123]: 1 rows were affected.
2020-08-24 11: 46: 52.766 Realtime [124]: 1 rows were affected.
2020-08-24 11: 47: 00.704 *** Data input appears to have stopped

etc.

Windows 10: Davis VP2 + Weatherlink IP

Harm
MXdiags files attached the last one is with debug on

[mcrossley]

Thanks for the report. Unfortunately the file with debug data doesn't show a failure.

It appears you experienced some network disconnects. I see after one of them the FTP was trying to reconnect using an IPv6 address and the remote server was rejecting the connection. We have seen this before, if you aren't using IPv6 the solution was to disable IPv6 as it looks like the FTP service at the remote end is only bound to IPv4.

As for the station connection it seems to have got into a state where no data is being downloaded but MX is not detecting that the connection is bad. It is really hard to simulate these situations to test the code, I'll have a look and see what can be done.

Meantime please leave MX running with the debugging enabled and post the log if you get another failure.

[hvd51]

Thanks Marc,

Turned off IPv6 and let CMX run with debug on.

Harm

[hvd51]

@Mark

2020-08-25 12:14:03.208 LOOP: Receive error - System.IO.IOException: Kan geen gegevens lezen uit de transportverbinding: Een verbindingspoging is mislukt omdat de verbonden party niet correct heeft geantwoord na een bepaalde tijd, of de gemaakte verbinding is mislukt omdat de verbonden host niet heeft geantwoord. ---> System.Net.Sockets.SocketException: Een verbindingspoging is mislukt omdat de verbonden party niet correct heeft geantwoord na een bepaalde tijd, of de gemaakte verbinding is mislukt omdat de verbonden host niet heeft geantwoord
bij System.Net.Sockets.Socket.Receive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
bij System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)
--- Einde van intern uitzonderingsstackpad ---
bij System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)
bij CumulusMX.DavisStation.GetAndProcessLoopData(Int32 number)
2020-08-25 12:14:03.724 SendLoopCommand: Sending command - LPS 2 1, attempt 1
2020-08-25 12:14:03.724 SendLoopCommand: Wait for ACK
2020-08-25 12:14:03.724 WaitForACK: Starting
2020-08-25 12:14:04.474 WaitForACK: ACK received
2020-08-25 12:14:04.474 LOOP2: Waiting for LOOP2 data
2020-08-25 12:14:04.474 LOOP2: Data packet is good

This time not followed by *** Data input appears to have stopped

Harm

[HansR]

If I may add my observations to this thread as I think it has similar root cause.
My MXdiags is filled with lines like these but data seem to be correctly written to the monthly and daily log files.

2020-08-25 16:30:32.459 SendLoopCommand: !!! No ack received in response to LOOP 20
2020-08-25 16:31:00.162 Writing log entry for 25-8-2020 16:31:00
2020-08-25 16:31:00.164 Written log entry for 25-8-2020 16:31:00
2020-08-25 16:31:00.170 Writing today.ini, LastUpdateTime = 25-8-2020 16:31:00 raindaystart = 456 rain counter = 458,8
2020-08-25 16:31:10.641 SendLoopCommand: !!! No ack received in response to LOOP 20
2020-08-25 16:31:12.459 SendLoopCommand: !!! No ack received in response to LOOP 20
2020-08-25 16:31:52.452 SendLoopCommand: !!! No ack received in response to LOOP 20
2020-08-25 16:32:00.167 Writing log entry for 25-8-2020 16:32:00
2020-08-25 16:32:00.169 Written log entry for 25-8-2020 16:32:00
2020-08-25 16:32:00.174 Writing today.ini, LastUpdateTime = 25-8-2020 16:32:00 raindaystart = 456 rain counter = 459
2020-08-25 16:32:32.459 SendLoopCommand: !!! No ack received in response to LOOP 20
2020-08-25 16:33:00.163 Writing log entry for 25-8-2020 16:33:00
2020-08-25 16:33:00.164 Written log entry for 25-8-2020 16:33:00
2020-08-25 16:33:00.166 Writing today.ini, LastUpdateTime = 25-8-2020 16:33:00 raindaystart = 456 rain counter = 459,2
2020-08-25 16:33:12.449 SendLoopCommand: !!! No ack received in response to LOOP 20
2020-08-25 16:33:52.441 SendLoopCommand: !!! No ack received in response to LOOP 20
2020-08-25 16:34:00.169 Writing log entry for 25-8-2020 16:34:00
2020-08-25 16:34:00.171 Written log entry for 25-8-2020 16:34:00

[mcrossley]

@Mark

2020-08-25 12:14:03.208 LOOP: Receive error - System.IO.IOException: Kan geen gegevens lezen uit de transportverbinding: Een verbindingspoging is mislukt omdat de verbonden party niet correct heeft geantwoord na een bepaalde tijd, of de gemaakte verbinding is mislukt omdat de verbonden host niet heeft geantwoord. ---> System.Net.Sockets.SocketException: Een verbindingspoging is mislukt omdat de verbonden party niet correct heeft geantwoord na een bepaalde tijd, of de gemaakte verbinding is mislukt omdat de verbonden host niet heeft geantwoord
bij System.Net.Sockets.Socket.Receive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
bij System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)
--- Einde van intern uitzonderingsstackpad ---
bij System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)
bij CumulusMX.DavisStation.GetAndProcessLoopData(Int32 number)
2020-08-25 12:14:03.724 SendLoopCommand: Sending command - LPS 2 1, attempt 1
2020-08-25 12:14:03.724 SendLoopCommand: Wait for ACK
2020-08-25 12:14:03.724 WaitForACK: Starting
2020-08-25 12:14:04.474 WaitForACK: ACK received
2020-08-25 12:14:04.474 LOOP2: Waiting for LOOP2 data
2020-08-25 12:14:04.474 LOOP2: Data packet is good

This time not followed by *** Data input appears to have stopped

Harm

Thanks, as you say it happened twice, and then carried on. I'll take a look at this and see what the code does again. At the very least it should output a message saying what it is doing.

If I may add my observations to this thread as I think it has similar root cause.
My MXdiags is filled with lines like these but data seem to be correctly written to the monthly and daily log files.

Different issue, the ACK from the loop 2 request does seem to be a bit dodgy. I'll have another look at this too and see if its something I'm doing or the console. Its actually the same function that initiates a loop1 or a loop2 request (just the command is different), and it works perfectly every time for loop1 requests.

[pech]

Hi there,

I'm using this thread in order not to open new one for a similar issue.

This is the log report about my "data input appears to have stopped"

2020-08-26 17:05:00.189 Writing log entry for 26/08/2020 17:05:00
2020-08-26 17:05:00.213 Written log entry for 26/08/2020 17:05:00
2020-08-26 17:05:00.215 Writing today.ini, LastUpdateTime = 26/08/2020 17:05:00 raindaystart = 299 rain counter = 299
2020-08-26 17:10:00.316 Writing log entry for 26/08/2020 17:10:00
2020-08-26 17:10:00.356 Written log entry for 26/08/2020 17:10:00
2020-08-26 17:10:00.360 Writing today.ini, LastUpdateTime = 26/08/2020 17:10:00 raindaystart = 299 rain counter = 299
2020-08-26 17:15:00.976 Writing log entry for 26/08/2020 17:15:00
2020-08-26 17:15:01.030 Written log entry for 26/08/2020 17:15:00
2020-08-26 17:15:01.038 Writing today.ini, LastUpdateTime = 26/08/2020 17:15:00 raindaystart = 299 rain counter = 299
2020-08-26 17:15:02.528 WU Response: OK: success

2020-08-26 17:15:04.539 LOOP: Expected data not received, expected 99 bytes, got 0
2020-08-26 17:15:05.540 LOOP: Timed out waiting for LOOP data
!!! Unhandled Exception !!!
System.IO.IOException: The I/O operation has been aborted because of either a thread exit or an application request.

at System.IO.Ports.InternalResources.WinIOError(Int32 errorCode, String str)
at System.IO.Ports.SerialStream.EndRead(IAsyncResult asyncResult)
at System.IO.Ports.SerialStream.ReadByte(Int32 timeout)
at System.IO.Ports.SerialPort.ReadOneChar(Int32 timeout)
at System.IO.Ports.SerialPort.ReadChar()
at CumulusMX.DavisStation.WaitForACK(SerialPort serialPort, Int32 timeoutMs)
at CumulusMX.DavisStation.SendLoopCommand(SerialPort serialPort, String commandString)
at CumulusMX.DavisStation.Start()
at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Threading.ThreadHelper.ThreadStart()
2020-08-26 17:17:00.737 *** Data input appears to have stopped
2020-08-26 17:18:00.938 *** Data input appears to have stopped
2020-08-26 17:19:00.183 *** Data input appears to have stopped
2020-08-26 17:20:00.385 *** Data input appears to have stopped
2020-08-26 17:21:00.536 *** Data input appears to have stopped
2020-08-26 17:22:00.737 *** Data input appears to have stopped

and so for about a day.
I just stopped CumulusMX, restarted and it's working; in attachment the complete log file
Configuraton is Davis VP2, windows 10 running as virtual machine using VMware in a linux server.

Thanks for helping and support

20200825-105622.txt

[mcrossley]

Something went wrong in the serial port code. The new version of MX (3.8.3) should handle this more gracefully and attempt to recover from it.