Updatexlrator testing - everything is working great! (I compiled core 118, installed it on my spare ipfire replacement box, and swapped it in yesterday morning.) Here are some key excerpts from the debug log.


The Microsoft files are generally defined as "URL" based because it is not necessarily the name that is unique, but the url itself.


2018-01-11 08:26:58 [5878] [updxlrator] Running command /var/ipfire/updatexlrator/bin/download microsoft http://officecdn.microsoft.com/pr/39168D7E-077B-48E7-872C-B232C3E72675/Office/Data/v32.cab 0 &

2018-01-11 08:27:04 [5878] [updxlrator] Running command /var/ipfire/updatexlrator/bin/download microsoft http://officecdn.microsoft.com/pr/492350f6-3a01-4f97-b9c0-c7c6ddf67d60/Office/Data/v32.cab 0 &


But if the filename contains the 40-digit SHA1 value, then we know that the filename is unique, and so we can treat it like Linux files, where it can be considered as a mirror-able file and only saved once. The following logs highlight A.) Multiple requests for the same 2GB file. (20 in two seconds!!) B.) The redirect from URL to FILE based caching. C.) two download requests before the lock file could be created. (Imagine how many more would have started when the lock delayed until wget wrote the first data.)


2018-01-11 17:35:23 [5878] [updxlrator] Processing ...kb4056891-x64_5... (first time this URL was seen. 22 attempts in the following 6 seconds).

2018-01-11 17:35:23 [6040] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:24 [6040] [updxlrator] SHA1: microsoft 033ed1d0-1709-957f-9fd1-34e24770fed4 not cached. Reprocessing as mirror http://7.au.download.windowsupdate.com/c/msdownload/update/software/secu/2018/01/windows10.0-kb4056891-x64_5_0a5255f85efca77e0abaa9c74f1581b5d3994c47.psf

2018-01-11 17:35:24 [5878] [updxlrator] SHA1: microsoft 033ed1d0-1709-957f-9fd1-34e24770fed4 not cached. Reprocessing as mirror http://7.au.download.windowsupdate.com/c/msdownload/update/software/secu/2018/01/windows10.0-kb4056891-x64_5_0a5255f85efca77e0abaa9c74f1581b5d3994c47.psf

2018-01-11 17:35:24 [6040] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:24 [5878] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:25 [6040] [updxlrator] Running command /var/ipfire/updatexlrator/bin/download microsoft ...kb4056891-x64_5... 1 &

2018-01-11 17:35:25 [5878] [updxlrator] Running command /var/ipfire/updatexlrator/bin/download microsoft ...kb4056891-x64_5... 1 &

2018-01-11 17:35:28 [6025] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:28 [6040] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:28 [6123] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:28 [6131] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:28 [6065] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:28 [6112] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:28 [2384] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:28 [2397] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:28 [2471] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:28 [2481] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:29 [2519] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:29 [2520] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:29 [2491] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:29 [2533] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:29 [16847] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:29 [2643] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:29 [16923] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:29 [16854] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:29 [16952] [updxlrator] Processing ...kb4056891-x64_5...

2018-01-11 17:35:29 [16990] [updxlrator] Processing ...kb4056891-x64_5...



These logs show 3 different URLs that a single client (55.55.55.40/DESKTOP-5NNUJJJ.local) requested this 2GB file from.


2018-01-12 02:21:12 [6115] [updxlrator] SHA1: microsoft 033ed1d0-1709-957f-9fd1-34e24770fed4 not cached. Reprocessing as mirror http://7.au.download.windowsupdate.com/c/msdownload/update/software/secu/2018/01/windows10.0-kb4056891-x64_5_0a5255f85efca77e0abaa9c74f1581b5d3994c47.psf

2018-01-12 04:13:44 [5878] [updxlrator] SHA1: microsoft b6e85197-9fcb-ffd1-0388-fd8adad6a4b1 not cached. Reprocessing as mirror http://000498-1.l.windowsupdate.com/llnhost_4.au.download.windowsupdate.com/c/msdownload/update/software/secu/2018/01/windows10.0-kb4056891-x64_5_0a5255f85efca77e0abaa9c74f1581b5d3994c47.psf

2018-01-12 04:14:11 [5878] [updxlrator] SHA1: microsoft e28b880b-1350-d70a-fd16-be58c4ce1e45 not cached. Reprocessing as mirror http://4.au.download.windowsupdate.com/c/msdownload/update/software/secu/2018/01/windows10.0-kb4056891-x64_5_0a5255f85efca77e0abaa9c74f1581b5d3994c47.psf


Oh, and some logs just to show the cache working in action - downloaded from one mirror, and fulfilled in a request from another mirror

...

2018-01-11 16:43:58 [6025] [updxlrator] Running command /var/ipfire/updatexlrator/bin/download microsoft http://7.au.download.windowsupdate.com/c/msdownload/update/software/secu/2018/01/windows10.0-kb4056891-x64_1_0a04efc071ff44c3262927fd2df414474e6a4c56.psf 1 &

...

2018-01-12 03:22:03 [6025] [updxlrator] Processing URL http://000f31-1.l.windowsupdate.com/llnhost_4.au.download.windowsupdate.com/c/msdownload/update/software/secu/2018/01/windows10.0-kb4056891-x64_1_0a04efc071ff44c3262927fd2df414474e6a4c56.psf

2018-01-12 03:22:03 [6025] [updxlrator] UUID is da895428-94cf-268c-6545-56d4c1c1aca2

2018-01-12 03:22:04 [6025] [updxlrator] SHA1: microsoft da895428-94cf-268c-6545-56d4c1c1aca2 not cached. Reprocessing as mirror http://000f31-1.l.windowsupdate.com/llnhost_4.au.download.windowsupdate.com/c/msdownload/update/software/secu/2018/01/windows10.0-kb4056891-x64_1_0a04efc071ff44c3262927fd2df414474e6a4c56.psf

2018-01-12 03:22:04 [6025] [updxlrator] UUID is b52663ab-8332-5292-0157-b95d50a5c96f

2018-01-12 03:22:04 [6040] [updxlrator] File exists in cache and is up to date

2018-01-12 03:22:04 [6040] [updxlrator] Retrieving file from cache (UPDCACHE) for 55.55.55.40/DESKTOP-5NNUJJJ.local



So, this single log from yesterday nicely highlights the importance of these patches

-it was super easy (especially on slow connections) to have MANY download attempts for the same file. The download command now has improved logic to prevent simultaneous wget's. I confirmed that only one wget was running for each downloading file.

-clients can request these huge updates from anywhere. Even though you might have had the file cached from a previous request, if another client starts requesting from a different mirror, you would have downloaded that too. The bandwidth (and disk) savings from this change in logic is going to be huge.