git clone, print progress BOTH to terminal and to a file, without buffering, and annotate progress with timestamps (on MacOS)

git-clone-print-progress-to-terminal-and-to-file.md

Note: this is MacOS specific

ORG=...
REPO=...
DEST_FOLDER=...
# just clone main branch, without tags, and don't fetch blobs over 1MB
FETCH_OPTIONS='--no-tags --single-branch --filter=blob:limit=1m'

caffeinate -d unbuffer \
   git clone --progress $FETCH_OPTIONS \
     git@github.com:$ORG/$REPO.git $DEST_FOLDER 2>&1 | \
   stdbuf -oL tr '\r' '\n' | ts "%H:%M:%S" | tee clone.log

Explanations:

  caffeinate -d      prevents Macbook from sleeping (the cloned repo is big)
  --progress         forces progress to be printed, even if we're piping
  2>&1               redirect stderr to stdout, so that we can pipe it to tee
  stdbuf -oL         prevent buffering of output (i.e. make output "live" in terminal & logs)
  tr '\r' '\n'       replace \r to \n in the stream so that 'ts' can properly annotate each line
  ts "%H:%M:%S"      add HH:MM:SS in front of each line
  | tee clone.log    write output to clone.log, but also print everything to terminal live

Deps

• caffeinate is macOS built-in
• tee is a standard unixy tool, and a macOS built-in
• stdbuf comes from brew install coreutils
• ts comes from brew install moreutils
• unbuffer comes from brew install expect

zzz_clone.log

18:49:05 Cloning into 'DEST_FOLDER'...
18:49:37 remote: Enumerating objects: 12028058
18:49:38 remote: Enumerating objects: 12657390
18:49:39 remote: Enumerating objects: 13305725
18:49:40 remote: Enumerating objects: 13897662
18:49:41 remote: Enumerating objects: 14021348, done.
18:49:41 remote: Counting objects:   0% (1/1993290)
18:49:41 remote: Counting objects:   1% (19933/1993290)
18:49:41 remote: Counting objects:   2% (39866/1993290)
18:49:41 remote: Counting objects:   3% (59799/1993290)
18:49:41 remote: Counting objects:   4% (79732/1993290)
18:49:41 remote: Counting objects:   5% (99665/1993290)
18:49:41 remote: Counting objects:   6% (119598/1993290)
18:49:41 remote: Counting objects:   7% (139531/1993290)
18:49:41 remote: Counting objects:   8% (159464/1993290)
18:49:41 remote: Counting objects:   9% (179397/1993290)
18:49:41 remote: Counting objects:  10% (199329/1993290)
18:49:41 remote: Counting objects:  11% (219262/1993290)
18:49:41 remote: Counting objects:  12% (239195/1993290)
18:49:41 remote: Counting objects:  13% (259128/1993290)
18:49:41 remote: Counting objects:  14% (279061/1993290)
18:49:41 remote: Counting objects:  15% (298994/1993290)
...
18:49:44 remote: Counting objects: 100% (1993290/1993290)
18:49:44 remote: Counting objects: 100% (1993290/1993290), done.
18:49:44 remote: Compressing objects:   0% (1/218023)
18:49:44 remote: Compressing objects:   1% (2181/218023)
18:49:44 remote: Compressing objects:   2% (4361/218023)
18:49:44 remote: Compressing objects:   3% (6541/218023)
18:49:45 remote: Compressing objects:   4% (8721/218023)
18:49:45 remote: Compressing objects:   4% (10652/218023)
18:49:46 remote: Compressing objects:   5% (10902/218023)
18:49:46 remote: Compressing objects:   5% (12705/218023)
18:50:21 remote: Compressing objects:  97% (212845/218023)
18:50:21 remote: Compressing objects:  98% (213663/218023)
18:50:21 remote: Compressing objects:  99% (215843/218023)
18:50:21 remote: Compressing objects: 100% (218023/218023)
18:50:21 remote: Compressing objects: 100% (218023/218023), done.
18:50:22 Receiving objects:   0% (1/14021348)
18:50:23 Receiving objects:   0% (35525/14021348), 17.81 MiB | 17.41 MiB/s
18:50:24 Receiving objects:   0% (67365/14021348), 26.29 MiB | 17.26 MiB/s
18:50:25 Receiving objects:   0% (99987/14021348), 43.57 MiB | 17.18 MiB/s
18:50:26 Receiving objects:   0% (133248/14021348), 61.12 MiB | 17.28 MiB/s
18:50:26 Receiving objects:   1% (140214/14021348), 69.53 MiB | 17.19 MiB/s
18:50:27 Receiving objects:   1% (166598/14021348), 78.25 MiB | 17.21 MiB/s
18:50:28 Receiving objects:   1% (201844/14021348), 95.49 MiB | 17.17 MiB/s
18:50:29 Receiving objects:   1% (238949/14021348), 112.76 MiB | 17.22 MiB/s
...
18:56:10 Receiving objects:  99% (13976722/14021348), 5.62 GiB | 15.95 MiB/s
18:56:10 remote: Total 14021348 (delta 1933934), reused 1782718 (delta 1775267), pack-reused 12028058 (from 3)
18:56:10 Receiving objects: 100% (14021348/14021348), 5.63 GiB | 16.11 MiB/s
18:56:10 Receiving objects: 100% (14021348/14021348), 5.63 GiB | 16.56 MiB/s, done.
18:56:11 Resolving deltas:   0% (0/10401646)
18:56:12 Resolving deltas:   1% (104018/10401646)
18:56:12 Resolving deltas:   1% (119874/10401646)
18:56:13 Resolving deltas:   1% (186962/10401646)
18:56:13 Resolving deltas:   2% (208033/10401646)
18:56:14 Resolving deltas:   2% (287621/10401646)
18:57:23 Resolving deltas:  98% (10291536/10401646)
18:57:24 Resolving deltas:  99% (10297630/10401646)
18:57:24 Resolving deltas:  99% (10320227/10401646)
18:57:25 Resolving deltas:  99% (10389702/10401646)
18:57:26 Resolving deltas: 100% (10401646/10401646)
18:57:26 Resolving deltas: 100% (10401646/10401646), done.
18:57:54 remote: Enumerating objects: 589, done.
18:57:54 remote: Counting objects:   1% (1/51)
18:57:54 remote: Counting objects:   3% (2/51)
18:57:54 remote: Counting objects:   5% (3/51)
18:57:54 remote: Counting objects:   7% (4/51)
18:57:54 remote: Counting objects:   9% (5/51)
18:57:54 remote: Counting objects:  11% (6/51)
18:57:57 remote: Compressing objects:  93% (30/32)
18:57:57 remote: Compressing objects:  96% (31/32)
18:57:57 remote: Compressing objects: 100% (32/32)
18:57:57 remote: Compressing objects: 100% (32/32), done.
18:57:57 Receiving objects:   0% (1/589)
18:57:57 Receiving objects:   1% (6/589), 8.82 MiB | 17.64 MiB/s
18:57:58 Receiving objects:   1% (7/589), 16.36 MiB | 16.35 MiB/s
18:57:59 Receiving objects:   1% (8/589), 27.68 MiB | 13.77 MiB/s
18:57:59 Receiving objects:   2% (12/589), 27.68 MiB | 13.77 MiB/s
9:00:25 Receiving objects:  95% (560/589), 2.44 GiB | 13.88 MiB/s
19:00:26 Receiving objects:  96% (566/589), 2.44 GiB | 13.88 MiB/s
19:00:26 Receiving objects:  97% (572/589), 2.45 GiB | 12.46 MiB/s
19:00:26 Receiving objects:  98% (578/589), 2.45 GiB | 12.46 MiB/s
19:00:26 Receiving objects:  99% (584/589), 2.45 GiB | 12.46 MiB/s
19:00:26 remote: Total 589 (delta 36), reused 19 (delta 19), pack-reused 538 (from 1)
19:00:26 Receiving objects: 100% (589/589), 2.45 GiB | 12.46 MiB/s
19:00:26 Receiving objects: 100% (589/589), 2.45 GiB | 16.83 MiB/s, done.
19:00:26 Resolving deltas:   0% (0/42)
19:00:26 Resolving deltas:   2% (1/42)
19:00:26 Resolving deltas:   4% (2/42)
19:00:26 Resolving deltas:   7% (3/42)
19:00:26 Resolving deltas:  14% (6/42)
19:00:26 Resolving deltas:  16% (7/42)
19:00:26 Resolving deltas:  19% (8/42)
19:00:26 Resolving deltas:  21% (9/42)
19:00:26 Resolving deltas:  23% (10/42)
...
19:00:26 Resolving deltas:  97% (41/42)
19:00:26 Resolving deltas: 100% (42/42)
19:00:26 Resolving deltas: 100% (42/42), done.
19:00:26 Updating files:   0% (1/181858)
19:00:26 Updating files:   0% (236/181858)
19:00:27 Updating files:   0% (806/181858)
19:00:28 Updating files:   1% (1819/181858)
19:00:28 Updating files:   1% (1821/181858)
19:00:29 Updating files:   1% (3237/181858)

19:01:10 Updating files:  95% (173837/181858)
19:01:11 Updating files:  96% (174584/181858)
19:01:11 Updating files:  97% (176403/181858)
19:01:11 Updating files:  98% (178221/181858)
19:01:11 Updating files:  98% (179149/181858)
19:01:12 Updating files:  99% (180040/181858)
19:01:12 Updating files: 100% (181858/181858)
19:01:12 Updating files: 100% (181858/181858), done.
[19:01:13] $