Reduce logging output when a zip download fails

[kevinphippsstfc]

I thought that I had already created an issue for this but it appears not so I'll record what I can remember now.

Shortly after ids.r2dfoo went into production (on 22/06/22 I think) Chris noticed that there were more error messages than normal in the IDS log file. After investigation I found that this was due to some new logging that had been added to ids.r2dfoo that wasn't in ids.server.

Basically what we think happens is that when a download fails, probably due to the user's connection dropping during the download of a zip file, each file that has not yet been added to the zip file records an error message in the log file. What we noticed was that the last one of these error messages would have the message "Failed to stream ....".

Chris looked at the number of failed downloads prior to the upgrade and since the upgrade and concluded that the failure rate was the same so we were not concerned that users were experiencing more failed downloads than before. He confirmed this in an email to me, Sabah and Brian on 29/06/22.

However, it would be better if we could reduce the number of error messages in the log when this happens. Zip files can contain thousands of files and we don't need them all logged.

Looking at the ids.log file for yesterday, I can see that most failures follow the pattern:

2022-11-15 00:31:06,777 DEBUG [http-thread-pool::http-listener-2(1)] IdsStreamingOutput - Adding /dls/i04/data/2021/mx21426-124/Kuni/gluA4-Nb/GluA4ATD_Nb80_E12_1/GluA4ATD_Nb80_E12_1_2_000001.h5 to zip
2022-11-15 00:31:06,778 WARN [http-thread-pool::http-listener-2(1)] IdsStreamingOutput - Caught IOException IOException Connection is closed
2022-11-15 00:31:06,778 WARN [http-thread-pool::http-listener-2(1)] IdsStreamingOutput - Skipping missing file in zip: dls/i04/data/2021/mx21426-124/Kuni/gluA4-Nb/GluA4ATD_Nb80_E12_1/GluA4ATD_Nb80_E12_1_2_000001
.h5
2022-11-15 00:31:06,778 DEBUG [http-thread-pool::http-listener-2(1)] IdsStreamingOutput - Adding /dls/i04/data/2021/mx21426-124/Kuni/gluA4-Nb/GluA4ATD_Nb80_E12_1/GluA4ATD_Nb80_E12_1_3_header.cbf to zip
2022-11-15 00:31:06,778 WARN [http-thread-pool::http-listener-2(1)] IdsStreamingOutput - Caught IOException IOException Connection is closed
2022-11-15 00:31:06,779 WARN [http-thread-pool::http-listener-2(1)] IdsStreamingOutput - Skipping missing file in zip: dls/i04/data/2021/mx21426-124/Kuni/gluA4-Nb/GluA4ATD_Nb80_E12_1/GluA4ATD_Nb80_E12_1_3_header
.cbf
2022-11-15 00:31:06,779 DEBUG [http-thread-pool::http-listener-2(1)] IdsStreamingOutput - Adding /dls/i04/data/2021/mx21426-124/Kuni/gluA4-Nb/GluA4ATD_Nb80_E12_1/GluA4ATD_Nb80_E12_1_2_000003.h5 to zip
2022-11-15 00:31:06,779 WARN [http-thread-pool::http-listener-2(1)] IdsStreamingOutput - Caught IOException IOException Connection is closed
2022-11-15 00:31:06,779 WARN [http-thread-pool::http-listener-2(1)] IdsStreamingOutput - Skipping missing file in zip: dls/i04/data/2021/mx21426-124/Kuni/gluA4-Nb/GluA4ATD_Nb80_E12_1/GluA4ATD_Nb80_E12_1_2_000003
.h5
2022-11-15 00:31:06,779 DEBUG [http-thread-pool::http-listener-2(1)] IdsStreamingOutput - Adding missing files listing MISSING_FILES.txt to zip
2022-11-15 00:31:06,782 ERROR [http-thread-pool::http-listener-2(1)] IdsStreamingOutput - Failed to stream /dls/i04/data/2021/mx21426-124/Kuni/gluA4-Nb/GluA4ATD_Nb80_E12_1/GluA4ATD_Nb80_E12_1_2_000003.h5 due to Connection is closed

where the IOException for each file is "Connection is closed"

However, some follow the pattern:

2022-11-15 16:16:13,073 DEBUG [http-thread-pool::http-listener-2(5)] IdsStreamingOutput - Adding /dls/i03/data/2022/mx24447-93/auto/Manoj/MtFEN/xGC10_D148K_MP299_D9B/xGC10_D148K_MP299_D9B_1.nxs to zip
2022-11-15 16:16:43,075 WARN [http-thread-pool::http-listener-2(5)] IdsStreamingOutput - Caught IOException IOException Write timeout exceeded when trying to flush the data
2022-11-15 16:16:43,075 WARN [http-thread-pool::http-listener-2(5)] IdsStreamingOutput - Skipping missing file in zip: dls/i03/data/2022/mx24447-93/auto/Manoj/MtFEN/xGC10_D148K_MP299_D9B/xGC10_D148K_MP299_D9B_1.
nxs
2022-11-15 16:16:43,076 DEBUG [http-thread-pool::http-listener-2(5)] IdsStreamingOutput - Adding /dls/i03/data/2022/mx24447-93/xraycentring/auto/Manoj/MtFEN/xGC10_D148K_MP299_D9B/xGC10_D148K_MP299_D9B_2.gridscan
to zip
2022-11-15 16:16:43,076 DEBUG [http-thread-pool::http-listener-2(5)] IdsStreamingOutput - Adding /dls/i03/data/2022/mx24447-93/auto/Manoj/MtFEN/xGC10_D148K_MP299_D9B/xGC10_D148K_MP299_D9B_2.nxs to zip
2022-11-15 16:17:13,096 WARN [http-thread-pool::http-listener-2(5)] IdsStreamingOutput - Caught IOException IOException Write timeout exceeded when trying to flush the data
2022-11-15 16:17:13,097 WARN [http-thread-pool::http-listener-2(5)] IdsStreamingOutput - Skipping missing file in zip: dls/i03/data/2022/mx24447-93/auto/Manoj/MtFEN/xGC10_D148K_MP299_D9B/xGC10_D148K_MP299_D9B_2.
nxs
2022-11-15 16:17:13,097 DEBUG [http-thread-pool::http-listener-2(5)] IdsStreamingOutput - Adding /dls/i03/data/2022/mx24447-93/xraycentring/auto/Manoj/MtFEN/xGC10_D148K_MP299_D9B/xGC10_D148K_MP299_D9B_1.gridscan
to zip
2022-11-15 16:17:19,789 INFO [Timer-2] MainSDStorage - Size of /exportstage/data/datafiles (90826989619986) is less than highArchivingLevel (92160000000000): no action.
2022-11-15 16:17:43,100 WARN [http-thread-pool::http-listener-2(5)] IdsStreamingOutput - Caught IOException IOException Write timeout exceeded when trying to flush the data
2022-11-15 16:17:43,100 WARN [http-thread-pool::http-listener-2(5)] IdsStreamingOutput - Skipping missing file in zip: dls/i03/data/2022/mx24447-93/xraycentring/auto/Manoj/MtFEN/xGC10_D148K_MP299_D9B/xGC10_D148K
_MP299_D9B_1.gridscan
2022-11-15 16:17:43,101 DEBUG [http-thread-pool::http-listener-2(5)] IdsStreamingOutput - Adding missing files listing MISSING_FILES.txt to zip
2022-11-15 16:18:02,589 INFO [http-thread-pool::http-listener-2(137)] IdsBean - New webservice request: isPrepared preparedId = 9c53d894-a972-40e3-8d44-ba3ff1679003
2022-11-15 16:18:13,104 ERROR [http-thread-pool::http-listener-2(5)] IdsStreamingOutput - Failed to stream /dls/i03/data/2022/mx24447-93/xraycentring/auto/Manoj/MtFEN/xGC10_D148K_MP299_D9B/xGC10_D148K_MP299_D9B_1.gridscan due to Write timeout exceeded when trying to flush the data

where the IOException on each file is "Write timeout exceeded when trying to flush the data"

So this may need to be taken into account when fixing this.