Issue:   Uploading of session images and files to website by AstroPlan's FTP File Uploader sometimes stalls.

Description.  AstroPlan application has a side role of uploading various session images and files to the website so that the status of a live session can be conveniently established from a single online web page ( Current/Latest Session ).  There has been an ongoing issue whereby every few sessions the uploading stalls, and the page now contains fresh information, and insstead of checking in with this one page, a VNC connection has to be opened to the Observatory Computer to check on the status of a session.

The stall is silent, in that AstroPlan just stops uploading, other AstroPlan facilities and functions work normally.    Extra tracing was added in AstroPlan 1.21.4 (2021-03-18).

In case of the occurrance of the issue during the latest session (S877, 2021-03-28), uploading of session files to website by AstroPlan FTP Uploader stalled at 03:09.

Analysis.    Extracts from AstroPlan log file from 2021-03-28 are shown below:

2021-03-29 10:14:08.60 | FTP Overseer >> FTP Queue Loop stalled at 2021-03-29 10:13:07
2021-03-29 10:14:08.60 | FTP Overseer >> Stall point is inside UploadFileFTP2
2021-03-29 10:14:09.67 | Exception in 'UploadFileFTP' whilst building/writing byte array for Session.ObsManagerTab.png
2021-03-29 10:14:09.67 | Error: Unable to Upload File : C:\Data\CCD Imaging\Live\Session.ObsManagerTab.png
2021-03-29 10:14:09.67 | Error: The underlying connection was closed: An unexpected error occurred on a receive.
2021-03-29 10:14:12.62 | FTP Overseer >> FTP Queue Loop resumed at 2021-03-29 10:14:12

2021-03-29 17:52:47.32 | FTP Overseer >> FTP Queue Loop stalled at 2021-03-29 17:51:45
2021-03-29 17:52:47.32 | FTP Overseer >> Stall point is inside UploadFileFTP2
2021-03-29 17:52:47.74 | Exception in 'UploadFileFTP' whilst building/writing byte array for Session.ObsManagerTab.png
2021-03-29 17:52:47.74 | Error: Unable to Upload File : C:\Data\CCD Imaging\Live\Session.ObsManagerTab.png
2021-03-29 17:52:47.74 | Error: The underlying connection was closed: An unexpected error occurred on a receive.
2021-03-29 17:52:53.36 | FTP Overseer >> FTP Queue Loop resumed at 2021-03-29 17:52:52

2021-03-29 21:09:31.73 | FTP Overseer >> FTP Queue Loop stalled at 2021-03-29 21:08:30
2021-03-29 21:09:31.73 | FTP Overseer >> Stall point is inside UploadFileFTP2
2021-03-29 21:11:59.43 | Exception in 'UploadFileFTP' whilst building/writing byte array for Session.TargetFrame09.jpg
2021-03-29 21:11:59.43 | Error: Unable to Upload File : C:\Data\CCD Imaging\Live\Session.TargetFrame09.jpg
2021-03-29 21:11:59.43 | Error: The underlying connection was closed: The server committed a protocol violation.
2021-03-29 21:14:49.67 | FTP Overseer >> FTP Queue Loop resumed at 2021-03-29 21:14:49

2021-03-29 21:15:50.00 | FTP Overseer >> FTP Queue Loop stalled at 2021-03-29 21:14:49
2021-03-29 21:15:50.00 | FTP Overseer >> Stall point is inside UploadFileFTP2
2021-03-29 21:15:56.04 | FTP Overseer >> FTP Queue Loop resumed at 2021-03-29 21:15:55

2021-03-29 21:58:34.99 | FTP Overseer >> FTP Queue Loop stalled at 2021-03-29 21:57:33
2021-03-29 21:58:34.99 | FTP Overseer >> Stall point is inside UploadFileFTP2
2021-03-29 21:58:36.00 | Exception in 'UploadFileFTP' whilst building/writing byte array for Session.Cam2TempChart.png
2021-03-29 21:58:36.00 | Error: Unable to Upload File : C:\Data\CCD Imaging\Live\Session.Cam2TempChart.png
2021-03-29 21:58:36.00 | Error: The underlying connection was closed: An unexpected error occurred on a receive.
2021-03-29 21:59:07.16 | FTP Overseer >> FTP Queue Loop resumed at 2021-03-29 21:59:06

2021-03-29 22:49:14.65 | FTP Overseer >> FTP Queue Loop stalled at 2021-03-29 22:48:13
2021-03-29 22:49:14.65 | FTP Overseer >> Stall point is inside UploadFileFTP2
2021-03-29 22:49:18.68 | FTP Overseer >> FTP Queue Loop resumed at 2021-03-29 22:49:17

2021-03-30 00:11:59.22 | Exception in 'UploadFileFTP' whilst getting RequestStream for Session.Header.js
2021-03-30 00:11:59.22 | Error: The underlying connection was closed: The server committed a protocol violation.

2021-03-30 00:19:07.20 | Exception in 'UploadFileFTP' whilst getting RequestStream for Session.Cam2TempChart.png
2021-03-30 00:19:07.20 | Error: Unable to connect to the remote server

2021-03-30 00:19:20.87 | FTP Overseer >> FTP Queue Loop stalled at 2021-03-30 00:18:20
2021-03-30 00:19:20.87 | FTP Overseer >> Stall point is inside UploadFileFTP2
2021-03-30 00:19:24.90 | FTP Overseer >> FTP Queue Loop resumed at 2021-03-30 00:19:24

2021-03-30 02:41:51.86 | Exception in UploadFileFTP (outer catch) for Session.LatestReport.htm
2021-03-30 02:41:51.86 | Error: Unable to Upload File : C:\Data\CCD Imaging\Live\Session.LatestReport.htm
2021-03-30 02:41:51.86 | Error: The process cannot access the file 'C:\Data\CCD Imaging\Live\Session.LatestReport.htm'
                         because it is being used by another process.
2021-03-30 02:42:50.92 | FTP Overseer >> FTP Queue Loop stalled at 2021-03-30 02:41:50
2021-03-30 02:42:50.92 | FTP Overseer >> Stall point is inside UploadFileFTP2
2021-03-30 02:42:51.88 | Exception in 'UploadFileFTP' whilst getting RequestStream for Session.LatestLog.log
2021-03-30 02:42:51.88 | Error: The operation has timed out.
2021-03-30 02:43:51.90 | Exception in 'UploadFileFTP' whilst getting RequestStream for Session.ObservatoryReportFlag.dat
2021-03-30 02:43:51.90 | Error: The operation has timed out.
2021-03-30 02:44:51.91 | Exception in 'UploadFileFTP' whilst getting RequestStream for Session.ObsManagerTab.png
2021-03-30 02:44:51.91 | Error: The operation has timed out.
2021-03-30 02:45:51.89 | Exception in 'UploadFileFTP' whilst getting RequestStream for Session.ServicesTab.png
2021-03-30 02:45:51.89 | Error: The operation has timed out.
2021-03-30 02:46:51.91 | Exception in 'UploadFileFTP' whilst getting RequestStream for Session.SkyConditionsTab01.png
2021-03-30 02:46:51.91 | Error: The operation has timed out.
2021-03-30 02:46:52.38 | FTP Overseer >> FTP Queue Loop resumed at 2021-03-30 02:46:51
2021-03-30 02:47:51.92 | Exception in 'UploadFileFTP' whilst getting RequestStream for Session.Header.js
2021-03-30 02:47:51.92 | Error: The operation has timed out.
2021-03-30 02:47:52.75 | FTP Overseer >> FTP Queue Loop stalled at 2021-03-30 02:46:51
2021-03-30 02:47:52.75 | FTP Overseer >> Stall point is inside UploadFileFTP2
2021-03-30 02:48:51.93 | Exception in 'UploadFileFTP' whilst getting RequestStream for Session.ObsPic.gif
2021-03-30 02:48:51.93 | Error: The operation has timed out.
2021-03-30 02:49:51.95 | Exception in 'UploadFileFTP' whilst getting RequestStream for event.dat
2021-03-30 02:49:51.95 | Error: The operation has timed out.

..... Multiple timeout exceptions...  (not shown here)

2021-03-30 03:09:52.17 | Error: The operation has timed out.
2021-03-30 03:09:52.84 | FTP Overseer >> FTP Queue Loop resumed at 2021-03-30 03:09:52
2021-03-30 03:10:52.18 | Exception in 'UploadFileFTP' whilst getting RequestStream for Session.Header.js
2021-03-30 03:10:52.18 | Error: The operation has timed out.
2021-03-30 03:10:53.21 | FTP Overseer >> FTP Queue Loop stalled at 2021-03-30 03:09:52
2021-03-30 03:10:53.21 | FTP Overseer >> Stall point is inside UploadFileFTP2
2021-03-30 03:11:52.20 | Exception in 'UploadFileFTP' whilst getting RequestStream for Session.ObsPic.gif
2021-03-30 03:11:52.20 | Error: The operation has timed out.
 
... Multiple timeout exceptions...  (not shown here)

2021-03-30 03:29:52.35 | Exception in 'UploadFileFTP' whilst getting RequestStream for Session.CcdTempChart.png
2021-03-30 03:29:52.35 | Error: The operation has timed out.
2021-03-30 03:30:21.07 | Closing Databases...
2021-03-30 03:30:21.10 | Closing Log Files...
2021-03-30 03:30:21.10 | Closing Log File

As well as  the terminal stall at 03:09 (21m+, program was closed before the queue resumed),  there were a number of shorter stalls that occurred at 10:14 (1m 5s duration),  17:52 (1m 7s duration),    21:14 (1m 6s duration),  21:58 (1m 33s duration), 22 48 (1m 4s duration) &  00:19 (1m 4s duration), plus a number of somewhat long stalls that occurred at 21:09 (6m 19s duration), 02:41 (5m 1s) &  02:46 (23m 1s).

Reporting of stalls is consistently made from FTP Overseer and nowhere else.   The messages consistently report that it is the 'FTP Queue Loop' that is stalled and that the stall point is 'inside UploadFileFTP2'.

A large proportion of 'stalls' are in range between 1m 4s &  1m 7s in duration. This suggests something about the frequency at which stall checks are made and the natural range of ftp upload timings.

The longer stall at 21:09 (6m 19s duration) might be connected to the creation of the night's observing plan around this time.  The log file shows an unexplained delay between 21:08:29 (logging of Sun Data) and 21:10:50 (logging of Moon Data)  

The stall at 21:14 (1m 6s duration)  follows directly on from that 21:09 (6m 19s duration) - no files are uploaded in the 0s interval between the first resuming and the second one starting.
Similarly the stall at  02:46 (23m 1s) follows directly on from stall at 02:41 (5m 1s).   Similarly the stall at 03:09 02:46 (21m+) follows directly on from stall at 02:46 (23m 1s)

The exception at 00:19:07 (exception whilst getting RequestStream for Session.Cam2TempChart.png) may or may not share a relation with an exception in AstroMain shortly beforehand at 00:18:37

00:18:37.64 | UGC 5760 DrawLegend Cam2Temp Fail | Exception in Cam2TempChart.DrawLegend (Mode: 1)
00:18:37.64 | UGC 5760 DrawLegend Cam2Temp Fail | Object is currently in use elsewhere.

Of the 6 exceptions  "Exception in 'UploadFileFTP'"  prior to the terminal stall ( should really be in 'UploadFileFTP2'") they were split as follows
    whilst building/writing byte array for file ....   (x4)
    whilst getting RequestStream for file ....  (x2)

The terminal stall at 03:09 is followed by series of exceptions  'Exception in UploadFileFTP' whilst getting RequestStream for file xxx .  The operation has timed out'
Since this exception type began to be logged from 02:42:51, just after the Stall at 02:41:50  (but not before then), it is probably appropriate to say the terminal stall began from 02:41:50.

The stall at 02:41:50 (logged at 02:42:50) appears to be immediately preceeded by an Exception in UploadFileFTP (outer catch) at 02:41:51.86:
     'Unable to Upload File Session.LatestReport.htm because it is being used by another process'.  

It is unclear whether this triggered the terminal stall or not.  Timing uncertainties are such that it could have been immediately succeeded by the exception.   Other shorter stalls seemed to associated with 'Unable to Upload File' exceptions , but they didn't lead to a terminal stall.  However the errors given for these other cases was different: 
     'The underlying connection was closed: An unexpected error occurred on a receive'. or 
     'The underlying connection was closed: The server committed a protocol violation'.
and were posted after the stall was logged rather than directly beforehand.

Later Cases
After restarting AstroPlan there were further reported short stalls in the FTP Queue

2021-03-30 03:32:11.92 | Starting 'FtpQueueThread'... (i.e. RunFtpQueue)
2021-03-30 03:32:11.94 | FTP Overseer >> FTP Queue Loop stalled at 0001-01-01 00:00:00
2021-03-30 03:32:11.94 | FTP Overseer >> Stall point is outside UploadFileFTP2
2021-03-30 03:32:11.94 | Executing RunFtpQueue...
2021-03-30 03:32:14.03 | FTP Overseer >> FTP Queue Loop resumed at 2021-03-30 03:32:13
2021-03-30 03:32:16.15 | RunFtpQueue has finishing uploading a batch of 1 files

2021-03-30 03:33:24.47 | FTP Overseer >> FTP Queue Loop stalled at 2021-03-30 03:32:24
2021-03-30 03:33:24.47 | FTP Overseer >> Stall point is inside UploadFileFTP2
2021-03-30 03:39:10.38 | FTP Overseer >> FTP Queue Loop resumed at 2021-03-30 03:39:10

2021-03-30 03:40:10.70 | FTP Overseer >> FTP Queue Loop stalled at 2021-03-30 03:39:10
2021-03-30 03:40:10.70 | FTP Overseer >> Stall point is inside UploadFileFTP2
2021-03-30 03:40:40.88 | FTP Overseer >> FTP Queue Loop resumed at 2021-03-30 03:40:39

The first stall at 03:32 is a bug relating to checking SecondsSince against a NullDate which has been reset by the first passage through queue.  2nd stall had duration 6m 46s, 3rd stall had duration 1m 29s.

In later session

2021-03-30 17:57:20.85 | Starting 'FtpQueueThread'... (i.e. RunFtpQueue)
2021-03-30 17:57:20.87 | Executing RunFtpQueue...
2021-03-30 17:57:20.87 | FTP Overseer >> File Upload Loop stalled at 0001-01-01 00:00:00
2021-03-30 17:57:22.90 | FTP Overseer >> File Upload Loop resumed at 2021-03-30 17:57:20
2021-03-30 17:58:23.27 | FTP Overseer >> FTP Queue Loop stalled at 2021-03-30 17:57:22
2021-03-30 17:58:23.27 | FTP Overseer >> Stall point is inside UploadFileFTP2
2021-03-30 18:04:41.57 | FTP Overseer >> FTP Queue Loop resumed at 2021-03-30 18:04:41
2021-03-30 18:04:49.01 | RunFtpQueue has finishing uploading a batch of 124 files
 
2021-03-30 18:12:00.84 | Exception in 'UploadFileFTP2' whilst getting RequestStream for Session.ObsManagerTab.png
2021-03-30 18:12:00.84 | Error: The remote server returned an error: 227 Entering Passive Mode (173,254,28,204,175,117).

Earlier Stalls
Checking back at logs from Session S876 (2021-03-26) when there was no major stall in FTP Upload, shows 16 occurances of Short Stalls

Errors were:
 'The underlying connection was closed: An unexpected error occurred on a receive.' (x8)
 'Unable to connect to the remote server' (x3)
 'System error.' (x3)
 'The operation has timed out (x1)

Further Analysis
FTP upload request has a request.TimeOut set at 60,000ms  (60s) and FtpOverseer has a stall trigger point set to be 60s.  If one file upload attempt failed and held up execution for 60s and the next upload attempt was successful this would nevertheless be reported as a stall.    Proposal is to reduce request.timeout to 30,000 ms (30s)

Still unclear why FTP Queue Upload stops working ,and requests continuously timeout.  (Issue with server connection is understandable but is unclear why restarting the program resolves the issue.

FtpOverseer updated to recognise and report when more than 5 timeouts have occurred in a row, and take action to stop FTP Queue and then restart it again.

Actions

• Establish why there are a large number for reported stalls which are all just over 1m in duration (are these just a reporting bug and not real stalls) ?
• Reduce request.Timeout to 30000ms (30s) in order to prevent the reporting of Short Stall (64-67s duration (fixed AstroPlan 1.25.5)
• Fix bug where stall is reported directly upon starting queue due to vcNullDate  (fix atttempted in AstroPlan 1.25.5 but still occuring
•  Four "Exception in 'UploadFileFTP' " messages should be title "Exception in 'UploadFileFTP2' "
•  Fix bug that restricts name of reported files name written to Report File (increase from 25 to 33 chars) (fixed AstroPlan 1.25.5)
• Modify AstroPlan so that log file is appended to when program is restarted rather than overwritten.  (fixed AstroPlan 1.25.5)
• Fix issue that causes FTP Queue to stall. 
• Mitgate FTP Queue Stall by attempting to restart Queue (fix attempted in AstroPlan 1.25.5)

Update