Just started logging "Timed out trying to read data from the socket stream!"

[radilly]

This morning I noticed that uploads to my web server were occurring mostly at 2 minutes intervals, where 1 minute is typical.

About 3 hours ago I started seeing "Timed out trying to read data from the socket stream!" in the MXdiags log. A lot of them. CMX (3.9.1) had been running for about 3 days and this seemed to have started at 9AM here - on the hour. As far as I know nothing on the Pi or with my network changed recently. I chatted with my hosting provider to see if they had any outages or changed any policies - but they checked logs and said everything looked find on their side. I ran FTP from the command line and didn't seem to have any issues. Also, on the hosted server I could see files were getting updated - I run "watch ls -alt --full-time", and I can see the files updating.

I turned on FTP logging and could spot any obvious issues - though I'm not terribly familiar and there is a lot of output. I was looking for a correlation between the 2 logs by doing a "tail -f" on each side-by-side. What I noticed was when I saw the message as issue in the MXdiags log, I seemed to see 3 messages in the FTP log:
Status: Disposing FtpSocketStream...
Status: Disposing FtpSocketStream...
Status: Disposing FtpSocketStream...

That seemed to be the only time I saw those 3 repeated lines in the FTP log, i.e. when "Timed out trying to read data from the socket stream!" occurred in the MXdiags log.

Scanning the MXdiags log I also noticed a periodic instance of this message:
Warning, previous web update is still in progress, first chance, skipping this interval
That seems suspiciously related to the 2 minute intervals on updates - but this isn't consistent.

viewtopic.php?p=134421 caught my eye when searching, but that seemed to be the result of a firewall issue. There's certainly nothing I did explicitly with firewalling this morning.

Appreciate any thoughts-

Might be of interest how I added a timestamp prefix to the ftp log...

Code: Select all

tail -f /home/pi/CumulusMX/ftplog.txt | while read LINE ; do echo "`date +'%T.%N '` ${LINE}" ; done | tee -a ftplog_a.txt

[mcrossley]

I can't really tell anything from that short bit of log, things had already gone wrong. Can you post the full mxdiags and ftp log file please.

The difficulty reading the FTP log is that both the realtime and interval processes are logging to it and their messages get intermingled. Maybe I'll look at creating separate FTP logs to make reading them simpler.

From memory all the previous cases of this sort of error - timed out - have been the network, firewalls, IDS software, or the server.

[radilly]

I posted logs to https://dilly.family/temp/20201201_FTP_Issue/ - I thought they might be large to attach. I did restart, and then reboot the Pi today, so the diags log for the period is in several parts. And I didn't leave ftp logging continuously- I turned it on and off several times because it looked repetitious after a while.

Now, I find this interesting. The issue stopped at 5 PM local. Noticeably abruptly. In the log fragment below, the dividing line seems evident - at the line "Hour changed:17".

Code: Select all

2020-12-01 16:55:16.753 FTP[Int]: Error uploading /home/pi/CumulusMX/web/status.html to status.html : Timed out trying to read data from the socket stream!
2020-12-01 16:55:28.171 FTP[176]: Error uploading web/realtimegauges.txt to realtimegauges.txt : Timed out trying to read data from the socket stream!
2020-12-01 16:55:41.866 FTP[177]: Attempting realtime FTP connect to host ftp.dilly.family on port 21
2020-12-01 16:55:43.208 FTP[177]: Realtime FTP connected
2020-12-01 16:56:16.767 FTP[Int]: Error uploading /home/pi/CumulusMX/web/status.html to status.html : Timed out trying to read data from the socket stream!
2020-12-01 16:56:28.135 FTP[178]: Error uploading web/realtimegauges.txt to realtimegauges.txt : Timed out trying to read data from the socket stream!
2020-12-01 16:56:41.866 FTP[179]: Attempting realtime FTP connect to host ftp.dilly.family on port 21
2020-12-01 16:56:43.245 FTP[179]: Realtime FTP connected
2020-12-01 16:57:16.947 FTP[Int]: Error uploading /home/pi/CumulusMX/web/status.html to status.html : Timed out trying to read data from the socket stream!
2020-12-01 16:58:17.323 FTP[Int]: Error uploading /home/pi/CumulusMX/web/status.html to status.html : Timed out trying to read data from the socket stream!
2020-12-01 17:00:00.018 Hour changed:17
2020-12-01 17:00:00.019 Calculating sunrise and sunset times
2020-12-01 17:00:00.020 Sunrise: 07:24:38
2020-12-01 17:00:00.021 Sunset : 16:54:40
2020-12-01 17:00:00.022 Tomorrow sunrise: 07:25:37
2020-12-01 17:00:00.022 Tomorrow sunset : 16:54:28
2020-12-01 17:00:00.159 DoLogFile: Writing log entry for 01/12/2020 17:00:00
2020-12-01 17:00:00.160 DoLogFile: Written log entry for 01/12/2020 17:00:00
2020-12-01 17:00:00.163 Writing today.ini, LastUpdateTime = 01/12/2020 17:00:00 raindaystart = 13.51181100984 rain counter = 13.52362203345
2020-12-01 17:00:00.163 Latest reading: 2170: 01 3E B1 00 5A 0A 80 E6 25 1F 29 00 0A 79 04 80
2020-12-01 17:00:01.008 WU Response: OK: success

2020-12-01 17:00:04.885 WeatherCloud Response: OK: 200
2020-12-01 17:05:00.983 WU Response: OK: success

2020-12-01 17:10:00.117 DoLogFile: Writing log entry for 01/12/2020 17:10:00
2020-12-01 17:10:00.120 DoLogFile: Written log entry for 01/12/2020 17:10:00
2020-12-01 17:10:00.126 Writing today.ini, LastUpdateTime = 01/12/2020 17:10:00 raindaystart = 13.51181100984 rain counter = 13.52362203345
2020-12-01 17:10:00.127 Latest reading: 2170: 0B 3D B2 00 59 0A 80 E8 25 1B 22 00 0C 79 04 80
2020-12-01 17:10:00.921 WU Response: OK: success

2020-12-01 17:10:05.135 WeatherCloud Response: OK: 200
2020-12-01 17:15:01.087 WU Response: OK: success

This behavior similarly seems to have begun at hour 9 - almost exactly 8 hours before it stopped.

Code: Select all

2020-12-01 08:50:00.354 Latest reading: 2060: 15 39 BF 00 5D 0A 80 C2 25 14 1F 00 0A 79 04 80
2020-12-01 08:50:01.205 WU Response: OK: success

2020-12-01 08:50:17.469 WeatherCloud Response: OK: 200
2020-12-01 08:55:01.183 WU Response: OK: success

2020-12-01 09:00:00.262 Hour changed:9
2020-12-01 09:00:00.263 Calculating sunrise and sunset times
2020-12-01 09:00:00.264 Sunrise: 07:24:38
2020-12-01 09:00:00.264 Sunset : 16:54:40
2020-12-01 09:00:00.265 Tomorrow sunrise: 07:25:37
2020-12-01 09:00:00.265 Tomorrow sunset : 16:54:28
2020-12-01 09:00:00.379 DoLogFile: Writing log entry for 01/12/2020 09:00:00
2020-12-01 09:00:00.380 DoLogFile: Written log entry for 01/12/2020 09:00:00
2020-12-01 09:00:00.383 Writing today.ini, LastUpdateTime = 01/12/2020 09:00:00 raindaystart = 13.51181100984 rain counter = 13.52362203345
2020-12-01 09:00:00.383 Latest reading: 2070: 01 39 BF 00 5D 0A 80 C3 25 1F 25 00 0A 79 04 80
2020-12-01 09:00:00.971 WU Response: OK: success

2020-12-01 09:00:02.827 WeatherCloud Response: OK: 200
2020-12-01 09:01:51.579 FTP[204]: Error uploading web/realtimegauges.txt to realtimegauges.txt : Timed out trying to read data from the socket stream!
2020-12-01 09:02:05.606 FTP[205]: Attempting realtime FTP connect to host ftp.dilly.family on port 21
2020-12-01 09:02:06.465 FTP[205]: Realtime FTP connected
2020-12-01 09:02:28.647 FTP[Int]: Error uploading web/humdata.json to /humdata.json : Timed out trying to read data from the socket stream!
2020-12-01 09:02:45.169 FTP[Int]: Error uploading web/raindata.json to /raindata.json : Timed out trying to read data from the socket stream!

The abruptness at the top of the hour is what caused me to check with the server hosting - I thought it possible that they had changed some policy regarding FTP at that hour. Seems a little peculiar that it started and stopped on a hour boundary.

I'll have to think about how I might monitor for a reoccurrence. I just happened stumble onto it this morning.

Thanks-

[radilly]

Oh. I hadn't realized the FTP log was already merged. I was trying to observe any correlation between them.

If the records in the FTP log that are in the way are of the form:
"2020-12-01 13:31:12.016FTP[24]..."
I could easily filter these out-

[mcrossley]

The problem with the FTP log is that, yes I can write messages to it, and I format those the same as the MXdiags log (I've been looking at this today, and I'll improve it for the next release (but one!)). But the FTP client itself writes to the ftplog, and I have no control over the format it uses. And having checked, the FTP client uses a static logging method so all instances (interval and realtime in our case) will use the same log file - no control over that either.

[radilly]

The problem with the FTP log is that, yes I can write messages to it, and I format those the same as the MXdiags log (I've been looking at this today, and I'll improve it for the next release (but one!)).

For what it's worth, I like the time-stamped diags lines in the log. Easily filtered out with grep and a regex for the timestamp. When I was working in distributed and asynchronous computing, synching clocks across servers and merging logs got considerable attention. That's why I added a one-liner to prefix the ftp log with timestamps, not realizing that the diags messages already gave some "snych points" between logs.

Overnight - just after midnight (local) - I saw 15 messages over about as many minutes like
FTP[Int]: Error connecting ftp - Could not resolve host 'ftp....'
Nothing since ... about 9 hours.

I believe all my other scripts upload via scp, and yesterday they looked to be working fine. I'll have to look through some other overnight logs. It seems I occasionally suffer a brief DNS glitch, but it' seems odd that I could find any other instances of this message across the logs I had handy (a month's worth).