#85 quick-fedora-mirror generates huge master-transferlist.sorted (causing rsync to hang) on already up to date mirror
Opened by dotsrc. Modified

In our (dotsrc.org) setup, quick-fedora-mirror generates huge master-transferlist.sorted list for modules that are already mostly up to date. This in turn causes rsync to hang, as rsync is not geared to handle such a big file as --files-from argument.

When doing a full rsync, we have no problems:

$ rsync --recursive --force --links --safe-links --hard-links --times --perms --sparse --stats --delete --verbose --timeout=3600 --exclude=archive/ rsync://dl-tier1.fedoraproject.org/fedora-buffet0/ /srv/mirrors/fedora-buffet
[...]
Number of files: 4,606,455 (reg: 4,531,939, dir: 74,470, link: 46)
Number of created files: 12,570 (reg: 12,528, dir: 42)
Number of deleted files: 8,301 (reg: 8,094, dir: 207)
Number of regular files transferred: 12,728
Total file size: 12,363,384,791,366 bytes
Total transferred file size: 52,724,589,231 bytes
Literal data: 51,714,404,384 bytes
Matched data: 1,010,184,847 bytes
File list size: 193,118,509
File list generation time: 0.004 seconds
File list transfer time: 0.000 seconds
Total bytes sent: 1,400,113
Total bytes received: 51,953,671,064
sent 1,400,113 bytes  received 51,953,671,064 bytes  9,721,222.04 bytes/sec
total size is 12,363,384,791,366  speedup is 237.96
Exit status: 0

If we then run quick-fedora-mirror, it generates a huge master-transferlist.sorted list:

mirror@kvaser:/tmp/quick-mirror.ca9QhlRjf2$ wc -l master-transferlist.sorted 
1736572 master-transferlist.sorted

We're using quick-fedora-mirror on latest commit (09050ced) and

$ zsh --version
zsh 5.8 (x86_64-ubuntu-linux-gnu)
$ rsync --version
rsync  version 3.1.3  protocol version 31
$ awk --version
GNU Awk 5.0.1, API: 2.0 (GNU MPFR 4.0.2, GNU MP 6.2.0)
$ find --version
find (GNU findutils) 4.7.0

Our config:

$ sed -s '/^#/d' quick-fedora-mirror-dotsrc.conf | tr -s '\n'
DESTD=/srv/mirrors/fedora-buffet/
TIMEFILE=/home/mirror/quick-fedora-mirror/timefile
REMOTE=rsync://dl-tier1.fedoraproject.org
MASTERMODULE=fedora-buffet0
PREBITFLIP=1
MODULES=(fedora-enchilada fedora-epel fedora-secondary fedora-alt)
CURL=/usr/bin/curl
RSYNCTIMEOUT=600
NORSYNCRECOVERY=1
VERBOSE=7

Output

$ quick-fedora-mirror/quick-fedora-mirror --dry-run --config quick-fedora-mirror/quick-fedora-mirror-dotsrc.conf
Mirror starting: Sat Oct 21 14:40:16 CEST 2023
>> Log: Run start: cfg quick-fedora-mirror/quick-fedora-mirror-dotsrc.conf, tmp /tmp/quick-mirror.ca9QhlRjf2
Times:
LASTTIME=0
starttime=1697892011
TIMEFILE=/home/mirror/quick-fedora-mirror/timefile
Dirs:
tempd=/tmp/quick-mirror.ca9QhlRjf2
DESTD=/srv/mirrors/fedora-buffet/
Rsync:
REMOTE=rsync://dl-tier1.fedoraproject.org
MASTERMODULE=fedora-buffet0
RSYNC=/usr/bin/rsync
RSYNCOPTS=-aSH -f R .~tmp~ --stats --delay-updates --out-format=@ %i %10l  %n%L
Modules:
MODULES=fedora-enchilada fedora-epel fedora-secondary fedora-alt
MODULEMAPPING=fedora alt epel archive fedora-secondary
Misc:
VERBOSE=7
============================================================
>> Log: Remote file list download start
Downloading file lists
>> Calling /usr/bin/rsync --timeout=600 -aSH -f R .~tmp~ --stats --delay-updates --out-format=@ %i %10l  %n%L --progress -v -v --files-from=filelist-transferlist --no-dirs --relative --compress rsync://dl-tier1.fedoraproject.org/fedora-buffet0/ .
>> Log: calling /usr/bin/rsync --timeout=600 -aSH -f R .~tmp~ --stats --delay-updates --out-format=@ %i %10l  %n%L --progress -v -v --files-from=filelist-transferlist --no-dirs --relative --compress rsync://dl-tier1.fedoraproject.org/fedora-buffet0/ .
opening tcp connection to dl-tier1.fedoraproject.org port 873
sending daemon args: --server --sender -vvlHogDtpRSze.LsfxC --timeout=600 --files-from=- --from0 . fedora-buffet0/  (8 args)
----------------------------
Fedora Master Mirror Servers
----------------------------
NOTE: This server is for authorized Fedora tier1 mirrors only!
If you are using bare rsync to sync content, please stop and 
take a look at https://pagure.io/quick-fedora-mirror.
See http://fedoraproject.org/wiki/Infrastructure/Mirroring for
further instructions.
----------------------------
You have connected to dl-iad01.fedoraproject.org
delta-transmission enabled
@ .d..tp.....       4096  alt/
@ >f.st......  167475609  alt/fullfiletimelist-alt
    167,475,609 100%  156.89MB/s    0:00:01 (xfr#1, to-chk=6/8)
@ .d..tp.....       4096  epel/
@ >f.st......   25226609  epel/fullfiletimelist-epel
     25,226,609 100%  151.31MB/s    0:00:00 (xfr#2, to-chk=4/8)
@ .d..t......       4096  fedora-secondary/
@ .f           147031722  fedora-secondary/fullfiletimelist-fedora-secondary
@ .d..tp.....       4096  fedora/
@ .f           196192792  fedora/fullfiletimelist-fedora
rsync[544042] (receiver) heap statistics:
  arena:         434176   (bytes from sbrk)
  ordblks:            3   (chunks not in use)
  smblks:             0
  hblks:              2   (chunks from mmap)
  hblkhd:        532480   (bytes from mmap)
  allmem:        966656   (bytes from sbrk + mmap)
  usmblks:            0
  fsmblks:            0
  uordblks:      288160   (bytes used)
  fordblks:      146016   (bytes free)
  keepcost:      134208   (bytes in releasable chunk)
rsync[543934] (generator) heap statistics:
  arena:         581632   (bytes from sbrk)
  ordblks:            2   (chunks not in use)
  smblks:             0
  hblks:              2   (chunks from mmap)
  hblkhd:        532480   (bytes from mmap)
  allmem:       1114112   (bytes from sbrk + mmap)
  usmblks:            0
  fsmblks:            0
  uordblks:      182512   (bytes used)
  fordblks:      399120   (bytes free)
  keepcost:      397488   (bytes in releasable chunk)
Number of files: 8 (reg: 4, dir: 4)
Number of created files: 0
Number of deleted files: 0
Number of regular files transferred: 2
Total file size: 535,926,732 bytes
Total transferred file size: 192,702,218 bytes
Literal data: 1,702,137 bytes
Matched data: 191,000,081 bytes
File list size: 309
File list generation time: 0.159 seconds
File list transfer time: 0.000 seconds
Total bytes sent: 120,944
Total bytes received: 187,410
sent 120,944 bytes  received 187,410 bytes  47,439.08 bytes/sec
total size is 535,926,732  speedup is 1,738.02
>> Log: rsync call completed succesfully with return 0
>> Log: File list download: 183.02KB received, 46.33KB/s
>> Log: Remote file list download: end
>> Log: Processing start
>> Log: No change in file list for fedora-enchilada
No change in file list checksum. Skipping fedora-enchilada.
============================================================
>> Log: Processing start: fedora-epel
Processing fedora-epel
>> Extracting file and directory lists for fedora-epel.
>>>> Directories (pre-bitflip included)
>>>> New dirs (pre-bitflip included)
>>>> Files (pre-bitflip included)
>>>> New files (pre-bitflip included)
Total on server:        266495 files, 2151 dirs.
New on server:          266495 files, 2151 dirs.
>> Finding file list changes since last run
>> Log: Generating database diff start: fedora-epel
>> Log: Generating database diff end: fedora-epel
>> Generating local file/dir list
>> Log: Generating local file list start: fedora-epel
>> Log: Generating local file list end: fedora-epel
Total on client:        266498 files, 2149 dirs.
Not present on server:      67 files,    3 dirs.
Missing on client:          67 files,    5 dirs.
Size Changed:                2 files.
Timestamps to restore:      39 files.
Checksum Failed:             5 files.
Filelist changes:         1136 paths.
Total to transfer:      268649 paths.
>> Log: Counts for fedora-epel: Svr:266495/2151 Loc:266498/2149 Diff:1136 New:266495/2151 Xtra:67/3 Miss:67/5 Size:2 Csum:5 Dtim:39
>> Log: Processing end: fedora-epel
Finished processing fedora-epel.
Changes in fedora-epel: 268649 files/dirs
>> Log: No change in file list for fedora-secondary
No change in file list checksum. Skipping fedora-secondary.
============================================================
>> Log: Processing start: fedora-alt
Processing fedora-alt
>> Extracting file and directory lists for fedora-alt.
>>>> Directories (pre-bitflip included)
>>>> New dirs (pre-bitflip included)
>>>> Files (pre-bitflip included)
>>>> New files (pre-bitflip included)
Total on server:       1403483 files, 64437 dirs.
New on server:         1403483 files, 64437 dirs.
>> Finding file list changes since last run
>> Log: Generating database diff start: fedora-alt
>> Log: Generating database diff end: fedora-alt
>> Generating local file/dir list
>> Log: Generating local file list start: fedora-alt
>> Log: Generating local file list end: fedora-alt
Total on client:       1402231 files, 64243 dirs.
Not present on server:       0 files,    0 dirs.
Missing on client:        1255 files,  194 dirs.
Size Changed:                0 files.
Timestamps to restore:       0 files.
Checksum Failed:             0 files.
Filelist changes:         1618 paths.
Total to transfer:     1467923 paths.
>> Log: Counts for fedora-alt: Svr:1403483/64437 Loc:1402231/64243 Diff:1618 New:1403483/64437 Xtra:0/0 Miss:1255/194 Size:0 Csum:0 Dtim:0
>> Log: Processing end: fedora-alt
Finished processing fedora-alt.
Changes in fedora-alt: 1467923 files/dirs
============================================================
============================================================
Transferring 1736572 files.
>> Calling /usr/bin/rsync --timeout=600 -aSH -f R .~tmp~ --stats --delay-updates --out-format=@ %i %10l  %n%L --progress -v -v --files-from=master-transferlist.sorted -n rsync://dl-tier1.fedoraproject.org/fedora-buffet0/ /srv/mirrors/fedora-buffet/
>> Log: calling /usr/bin/rsync --timeout=600 -aSH -f R .~tmp~ --stats --delay-updates --out-format=@ %i %10l  %n%L --progress -v -v --files-from=master-transferlist.sorted -n rsync://dl-tier1.fedoraproject.org/fedora-buffet0/ /srv/mirrors/fedora-buffet/
opening tcp connection to dl-tier1.fedoraproject.org port 873
sending daemon args: --server --sender -vvnlHogDtpRSe.LsfxC --timeout=600 --files-from=- --from0 . fedora-buffet0/  (8 args)
----------------------------
Fedora Master Mirror Servers
----------------------------
NOTE: This server is for authorized Fedora tier1 mirrors only!
If you are using bare rsync to sync content, please stop and 
take a look at https://pagure.io/quick-fedora-mirror.
See http://fedoraproject.org/wiki/Infrastructure/Mirroring for
further instructions.
----------------------------
You have connected to dl-iad01.fedoraproject.org
receiving file list ... 
 32700 files...
[Receiver] expand file_list pointer array to 524288 bytes, did move
 65500 files...
[Receiver] expand file_list pointer array to 1048576 bytes, did move
 131000 files...
[Receiver] expand file_list pointer array to 2097152 bytes, did move
 262100 files...
[Receiver] expand file_list pointer array to 4194304 bytes, did move
 524200 files...
[Receiver] expand file_list pointer array to 8388608 bytes, did move
rsync error: received SIGINT, SIGTERM, or SIGHUP (code 20) at rsync.c(644) [Receiver=3.1.3]
rsync: [Receiver] write error: Broken pipe (32)
rsync error: received SIGINT, SIGTERM, or SIGHUP (code 20) at io.c(1651) [sender=3.2.3]
>> Log: ERR: rsync returned 20, which was not expected.
rsync returned 20, which was not expected.
rsync error: received SIGINT, SIGTERM, or SIGHUP (code 20) at rsync.c(644) [Receiver=3.1.3]
rsync: [Receiver] write error: Broken pipe (32)
rsync error: received SIGINT, SIGTERM, or SIGHUP (code 20) at io.c(1651) [sender=3.2.3]
rsync failed; aborting run.
Will not check in or delete anything.
>> Log:
=========================
Mirror finished: Sat Oct 21 21:15:15 CEST 2023 (1)
>> Log: Run end; exiting 1.

(killed rsync as it had been running for many hours)


Metadata