SOAR mirror hangs on one of last downloads

[ErikPGJ]

SOAR mirror sometimes hangs on one of the last downloads during nominal use (cron+manual launch).

Current commit which should be valid for at least
79e9e8d Erik P G Johansson (2025-04-29 16:57:47 +0200) (HEAD -> master) Add some logging and codetiming calls for ~profiling

• NOTE: Only hangs when the download is big (but not always when the download is big).
• NOTE Always hangs on one of the very last downloads.
• TODO-NI: After a failure, does a subsequent sync+redownload succeed?
• THEORY: Something with parallelization of downloads, with waiting for the last download to finish.
  • PROPOSAL: Timeout for download jobs.
• THEORY: Something with big downloads, running out of resources somehow.
  • CON: Should not necessarily be triggered for the last downloads.

Cases

All cases found among the most recent 100 logs (2024-05-23 to 2025-12-11, anna+brain):

> tail -n 10 *
==> so_soar_irfu_mirror_sync.brain.2025-06-06T18.24.03.log.crashed_interrupted.log <==
2025-06-06 20:40:36,112 INFO         Completed        Remaining      Total (est.)     Unit
2025-06-06 20:40:36,113 INFO     -------------------------------------------------------------------------
2025-06-06 20:40:36,113 INFO                 1643                2             1645 [datasets]
2025-06-06 20:40:36,113 INFO            358459.00          5847.84        364306.85 [MiB]
2025-06-06 20:40:36,113 INFO               6678.8            109.0           6787.8 [s]
2025-06-06 20:40:36,113 INFO              1:51:19          0:01:49          1:53:08 [(days,) hour:min:sec]
2025-06-06 20:40:36,113 INFO     -------------------------------------------------------------------------
2025-06-06 20:40:36,113 INFO     Effective average download speed so far: 53.67 [MiB/s]
2025-06-06 20:40:36,114 INFO     Estimated time of completion:            2025-06-06T20.42.25
2025-06-06 20:40:36,114 INFO     -------------------------------------------------------------------------

==> so_soar_irfu_mirror_sync.brain.2025-06-13T18.11.03.log.crashed_interrupted.log <==
2025-06-13 20:33:18,690 INFO         Completed        Remaining      Total (est.)     Unit
2025-06-13 20:33:18,690 INFO     -------------------------------------------------------------------------
2025-06-13 20:33:18,690 INFO                 2712                3             2715 [datasets]
2025-06-13 20:33:18,690 INFO            360393.26          8067.18        368460.44 [MiB]
2025-06-13 20:33:18,690 INFO               7127.9            159.6           7287.4 [s]
2025-06-13 20:33:18,690 INFO              1:58:48          0:02:40          2:01:27 [(days,) hour:min:sec]
2025-06-13 20:33:18,690 INFO     -------------------------------------------------------------------------
2025-06-13 20:33:18,690 INFO     Effective average download speed so far: 50.56 [MiB/s]
2025-06-13 20:33:18,690 INFO     Estimated time of completion:            2025-06-13T20.35.58
2025-06-13 20:33:18,691 INFO     -------------------------------------------------------------------------

==> so_soar_irfu_mirror_sync.brain.2025-06-27T18.11.03.log.hung_interrupted.log <==
2025-06-27 21:04:41,226 INFO         Completed        Remaining      Total (est.)     Unit
2025-06-27 21:04:41,226 INFO     -------------------------------------------------------------------------
2025-06-27 21:04:41,226 INFO                 1792                7             1799 [datasets]
2025-06-27 21:04:41,226 INFO            369684.69         19982.33        389667.02 [MiB]
2025-06-27 21:04:41,227 INFO               8162.8            441.2           8604.0 [s]
2025-06-27 21:04:41,227 INFO              2:16:03          0:07:21          2:23:24 [(days,) hour:min:sec]
2025-06-27 21:04:41,227 INFO     -------------------------------------------------------------------------
2025-06-27 21:04:41,227 INFO     Effective average download speed so far: 45.29 [MiB/s]
2025-06-27 21:04:41,227 INFO     Estimated time of completion:            2025-06-27T21.12.02
2025-06-27 21:04:41,227 INFO     -------------------------------------------------------------------------

==> so_soar_irfu_mirror_sync.brain.2025-07-11T18.11.02.log.hung_intterupted.log <==
2025-07-11 20:07:46,609 INFO         Completed        Remaining      Total (est.)     Unit
2025-07-11 20:07:46,609 INFO     -------------------------------------------------------------------------
2025-07-11 20:07:46,609 INFO                  801                5              806 [datasets]
2025-07-11 20:07:46,609 INFO            226221.76         14637.54        240859.30 [MiB]
2025-07-11 20:07:46,609 INFO               4834.4            312.8           5147.2 [s]
2025-07-11 20:07:46,609 INFO              1:20:34          0:05:13          1:25:47 [(days,) hour:min:sec]
2025-07-11 20:07:46,609 INFO     -------------------------------------------------------------------------
2025-07-11 20:07:46,609 INFO     Effective average download speed so far: 46.79 [MiB/s]
2025-07-11 20:07:46,610 INFO     Estimated time of completion:            2025-07-11T20.12.59
2025-07-11 20:07:46,610 INFO     -------------------------------------------------------------------------

==> so_soar_irfu_mirror_sync.brain.2025-07-25T18.11.02.log <==
2025-07-25 19:04:11,106 INFO         Completed        Remaining      Total (est.)     Unit
2025-07-25 19:04:11,106 INFO     -------------------------------------------------------------------------
2025-07-25 19:04:11,106 INFO                   20                1               21 [datasets]
2025-07-25 19:04:11,106 INFO             11758.06          2934.05         14692.11 [MiB]
2025-07-25 19:04:11,106 INFO               1424.4            355.4           1779.9 [s]
2025-07-25 19:04:11,106 INFO              0:23:44          0:05:55          0:29:40 [(days,) hour:min:sec]
2025-07-25 19:04:11,106 INFO     -------------------------------------------------------------------------
2025-07-25 19:04:11,106 INFO     Effective average download speed so far: 8.25 [MiB/s]
2025-07-25 19:04:11,106 INFO     Estimated time of completion:            2025-07-25T19.10.06
2025-07-25 19:04:11,106 INFO     -------------------------------------------------------------------------

==> so_soar_irfu_mirror_sync.brain.2025-12-10T16.06.01.log <==
2025-12-10 17:36:31,595 INFO         Completed        Remaining      Total (est.)     Unit
2025-12-10 17:36:31,595 INFO     -------------------------------------------------------------------------
2025-12-10 17:36:31,595 INFO                12536                1            12537 [datasets]
2025-12-10 17:36:31,595 INFO            192044.63          2924.03        194968.66 [MiB]
2025-12-10 17:36:31,595 INFO               3524.6             53.7           3578.2 [s]
2025-12-10 17:36:31,596 INFO              0:58:45          0:00:54          0:59:38 [(days,) hour:min:sec]
2025-12-10 17:36:31,596 INFO     -------------------------------------------------------------------------
2025-12-10 17:36:31,596 INFO     Effective average download speed so far: 54.49 [MiB/s]
2025-12-10 17:36:31,596 INFO     Estimated time of completion:            2025-12-10T17.37.25

so_soar_irfu_mirror_sync.brain.2025-06-06T18.24.03.log.crashed_interrupted.log
so_soar_irfu_mirror_sync.brain.2025-06-13T18.11.03.log.crashed_interrupted.log
so_soar_irfu_mirror_sync.brain.2025-06-27T18.11.03.log.hung_interrupted.log
so_soar_irfu_mirror_sync.brain.2025-07-11T18.11.02.log.hung_intterupted.log
so_soar_irfu_mirror_sync.brain.2025-07-25T18.11.02.log
so_soar_irfu_mirror_sync.brain.2025-12-10T16.06.01.log

[ErikPGJ]

Re-running the sync after hanging (last log above) appears to behave well and consistently:

• Code tries to download the same datasets (not checked if exactly the same set of datasets)
• Downloaded datasets can not be downloaded because the destination path is already occupied by a file (from the previous run)
• All downloaded datasets in the downloads directory (from previous run) are moved to the final destination, despite not being downloaded in this run.
• Datasets that should be removed are still removed.

so_soar_irfu_mirror_sync.brain.2025-12-11T09.19.12.log

CONCLUSION: The obvious mitigation is to just kill the process and re-run.