search

kubernetes / git-sync

A sidecar app which clones a git repo and keeps it in sync with the upstream.
Apache License 2.0
2.22k stars 411 forks source link

Temporarily missing files when using $GITSYNC_LINK #856

Closed alex-souslik-hs closed 8 months ago

alex-souslik-hs commented 8 months ago

When setting the $GIT_LINK environment variable we get some odd behavior during the sync itself. We run git-sync as a sidecar and after each time a sync is triggered, for about 5-10 seconds we get errors in the main container that various files are not found. This does not happen when the link is not set explicitly. This is an example log from the container:

{"logger":"","ts":"2024-01-14 11:04:19.661405","caller":{"file":"main.go","line":1184},"msg":"can't list worktree directory","error":"readdirent /git/git/<repo>/.worktrees/382226e20f7aa8b3fe377ea965c1d3293cad50b8: not a directory","path":"/git/git/<repo>/.worktrees/382226e20f7aa8b3fe377ea965c1d3293cad50b8"}
{"logger":"","ts":"2024-01-14 11:04:19.661507","caller":{"file":"main.go","line":1624},"level":0,"msg":"worktree failed checks or was empty","path":"/git/git/<repo>/.worktrees/382226e20f7aa8b3fe377ea965c1d3293cad50b8"}
{"logger":"","ts":"2024-01-14 11:04:19.661538","caller":{"file":"main.go","line":1306},"level":1,"msg":"removing worktree","path":"/git/git/<repo>/.worktrees/382226e20f7aa8b3fe377ea965c1d3293cad50b8"}
{"logger":"","ts":"2024-01-14 11:04:19.662765","caller":{"file":"main.go","line":1639},"level":0,"msg":"update required","ref":"HEAD","local":"","remote":"382226e20f7aa8b3fe377ea965c1d3293cad50b8","syncCount":788}
{"logger":"","ts":"2024-01-14 11:04:19.662790","caller":{"file":"main.go","line":1712},"level":1,"msg":"fetching","ref":"382226e20f7aa8b3fe377ea965c1d3293cad50b8","repo":"git@github.com:<org>/<repo>"}
{"logger":"","ts":"2024-01-14 11:04:22.918427","caller":{"file":"main.go","line":1306},"level":1,"msg":"removing worktree","path":"/git/<repo>/.worktrees/382226e20f7aa8b3fe377ea965c1d3293cad50b8"}
{"logger":"","ts":"2024-01-14 11:04:25.216789","caller":{"file":"main.go","line":1330},"level":1,"msg":"adding worktree","path":"/git/<repo>/.worktrees/382226e20f7aa8b3fe377ea965c1d3293cad50b8","hash":"382226e20f7aa8b3fe377ea965c1d3293cad50b8"}
{"logger":"","ts":"2024-01-14 11:04:25.220670","caller":{"file":"main.go","line":1402},"level":1,"msg":"setting worktree HEAD","hash":"382226e20f7aa8b3fe377ea965c1d3293cad50b8"}
{"logger":"","ts":"2024-01-14 11:04:30.223172","caller":{"file":"main.go","line":1410},"level":1,"msg":"updating submodules"}
{"logger":"","ts":"2024-01-14 11:04:30.513654","caller":{"file":"main.go","line":1283},"level":2,"msg":"creating tmp symlink","dir":"/opt","link":"tmp-link","target":"../git/<repo>/.worktrees/382226e20f7aa8b3fe377ea965c1d3293cad50b8"}
{"logger":"","ts":"2024-01-14 11:04:30.513810","caller":{"file":"main.go","line":1288},"level":2,"msg":"renaming symlink","root":"/opt","oldName":"tmp-link","newName":"<repo>"}
{"logger":"","ts":"2024-01-14 11:04:30.514086","caller":{"file":"main.go","line":1690},"level":0,"msg":"updated successfully","ref":"HEAD","remote":"382226e20f7aa8b3fe377ea965c1d3293cad50b8","syncCount":789}

This is an example of the errors we get:

FileNotFoundError: [Errno 2] No such file or directory: '/opt/<repo>/<folder>/<file>.yaml'
thockin commented 8 months ago

See the logs:

What version of git-sync are you using? It's possible this is a real bug - help me to repro it with a more verbose log? Run with -v 6 and send the whole thing, so I can see exactly how flags are set, etc?

alex-souslik-hs commented 8 months ago

We are using v4.1.0, here is a log with an initial and a subsequent run with -v 6:


INFO: detected pid 1, running init handler
{"logger":"","ts":"2024-01-16 09:16:58.642449","caller":{"file":"main.go","line":523},"level":0,"msg":"starting up","pid":12,"uid":65533,"gid":65533,"home":"/tmp","flags":["--add-user=false","--change-permissions=0","--cookie-file=false","--credential=[]","--depth=1","--exechook-backoff=3s","--exechook-timeout=30s","--git=git","--git-gc=always","--group-write=false","--help=false","--http-metrics=false","--http-pprof=false","--link=/opt/<repo>","--man=false","--max-failures=-1","--max-sync-failures=0","--one-time=false","--period=1m0s","--ref=HEAD","--repo=git@github.com:<org>/<repo>","--root=/git/<repo>","--ssh=false","--ssh-key-file=[/etc/git-ssh/id_rsa]","--ssh-known-hosts=true","--ssh-known-hosts-file=/etc/git-ssh/known_hosts","--stale-worktree-timeout=0s","--submodules=recursive","--sync-timeout=2m0s","--timeout=0","--v=-1","--verbose=6","--version=false","--wait=0","--webhook-backoff=3s","--webhook-method=POST","--webhook-success-status=200","--webhook-timeout=1s"]}
{"logger":"","ts":"2024-01-16 09:16:58.647156","caller":{"file":"main.go","line":593},"level":2,"msg":"created private gitconfig file","path":"/tmp/git-sync.gitconfig.3170679603"}
{"logger":"","ts":"2024-01-16 09:16:58.647238","caller":{"file":"main.go","line":1907},"level":5,"msg":"running command","cwd":"","cmd":"git config --global gc.autoDetach false"}
{"logger":"","ts":"2024-01-16 09:16:58.655627","caller":{"file":"main.go","line":1907},"level":6,"msg":"command result","stdout":"","stderr":"","time":"8.307641ms"}
{"logger":"","ts":"2024-01-16 09:16:58.655721","caller":{"file":"main.go","line":1907},"level":5,"msg":"running command","cwd":"","cmd":"git config --global gc.pruneExpire now"}
{"logger":"","ts":"2024-01-16 09:16:58.664146","caller":{"file":"main.go","line":1907},"level":6,"msg":"command result","stdout":"","stderr":"","time":"8.303161ms"}
{"logger":"","ts":"2024-01-16 09:16:58.664264","caller":{"file":"main.go","line":1907},"level":5,"msg":"running command","cwd":"","cmd":"git config --global credential.helper \"cache --timeout 3600\""}
{"logger":"","ts":"2024-01-16 09:16:58.764052","caller":{"file":"main.go","line":1907},"level":6,"msg":"command result","stdout":"","stderr":"","time":"99.685222ms"}
{"logger":"","ts":"2024-01-16 09:16:58.764127","caller":{"file":"main.go","line":1907},"level":5,"msg":"running command","cwd":"","cmd":"git config --global core.askPass true"}
{"logger":"","ts":"2024-01-16 09:16:58.766956","caller":{"file":"main.go","line":1907},"level":6,"msg":"command result","stdout":"","stderr":"","time":"2.75113ms"}
{"logger":"","ts":"2024-01-16 09:16:58.767034","caller":{"file":"main.go","line":1907},"level":5,"msg":"running command","cwd":"","cmd":"git config --global safe.directory *"}
{"logger":"","ts":"2024-01-16 09:16:58.840959","caller":{"file":"main.go","line":1907},"level":6,"msg":"command result","stdout":"","stderr":"","time":"73.83984ms"}
{"logger":"","ts":"2024-01-16 09:16:58.841039","caller":{"file":"main.go","line":1776},"level":1,"msg":"setting up git SSH credentials"}
{"logger":"","ts":"2024-01-16 09:16:58.841081","caller":{"file":"main.go","line":1578},"level":3,"msg":"syncing","repo":"git@github.com:<org>/<repo>"}
{"logger":"","ts":"2024-01-16 09:16:58.841187","caller":{"file":"main.go","line":1071},"level":3,"msg":"repo directory exists","path":"/git/<repo>"}
{"logger":"","ts":"2024-01-16 09:16:58.841327","caller":{"file":"main.go","line":1143},"level":3,"msg":"sanity-checking git repo","repo":"/git/<repo>"}
{"logger":"","ts":"2024-01-16 09:16:58.841466","caller":{"file":"main.go","line":1149},"level":3,"msg":"repo directory is empty","path":"/git/<repo>"}
{"logger":"","ts":"2024-01-16 09:16:58.841526","caller":{"file":"main.go","line":1079},"level":0,"msg":"repo directory was empty or failed checks","path":"/git/<repo>"}
{"logger":"","ts":"2024-01-16 09:16:58.841573","caller":{"file":"main.go","line":1089},"level":0,"msg":"initializing repo directory","path":"/git/<repo>"}
{"logger":"","ts":"2024-01-16 09:16:58.841665","caller":{"file":"main.go","line":1090},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git init -b git-sync"}
{"logger":"","ts":"2024-01-16 09:16:58.863848","caller":{"file":"main.go","line":1090},"level":6,"msg":"command result","stdout":"Initialized empty Git repository in /git/<repo>/.git/","stderr":"","time":"21.87421ms"}
{"logger":"","ts":"2024-01-16 09:16:58.863941","caller":{"file":"main.go","line":1143},"level":3,"msg":"sanity-checking git repo","repo":"/git/<repo>"}
{"logger":"","ts":"2024-01-16 09:16:58.864042","caller":{"file":"main.go","line":1154},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git rev-parse --show-toplevel"}
{"logger":"","ts":"2024-01-16 09:16:58.946822","caller":{"file":"main.go","line":1154},"level":6,"msg":"command result","stdout":"/git/<repo>","stderr":"","time":"82.705656ms"}
{"logger":"","ts":"2024-01-16 09:16:58.947134","caller":{"file":"main.go","line":1167},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git fsck --no-progress --connectivity-only"}
{"logger":"","ts":"2024-01-16 09:16:59.046795","caller":{"file":"main.go","line":1167},"level":6,"msg":"command result","stdout":"","stderr":"notice: HEAD points to an unborn branch (git-sync)\nnotice: No default references","time":"99.42238ms"}
{"logger":"","ts":"2024-01-16 09:16:59.046897","caller":{"file":"main.go","line":1100},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git remote get-url origin"}
{"logger":"","ts":"2024-01-16 09:16:59.049455","caller":{"file":"main.go","line":1105},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git remote add origin git@github.com:<org>/<repo>"}
{"logger":"","ts":"2024-01-16 09:16:59.052816","caller":{"file":"main.go","line":1105},"level":6,"msg":"command result","stdout":"","stderr":"","time":"3.049664ms"}
{"logger":"","ts":"2024-01-16 09:16:59.052886","caller":{"file":"main.go","line":1496},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git ls-remote -q git@github.com:<org>/<repo> HEAD HEAD^{}"}
{"logger":"","ts":"2024-01-16 09:17:02.843683","caller":{"file":"main.go","line":1496},"level":6,"msg":"command result","stdout":"e816bc92b4a8448685db3afd4136e10ec9cd0907\tHEAD","stderr":"","time":"3.790731591s"}
{"logger":"","ts":"2024-01-16 09:17:02.843794","caller":{"file":"main.go","line":1617},"level":3,"msg":"current hash","hash":""}
{"logger":"","ts":"2024-01-16 09:17:02.843824","caller":{"file":"main.go","line":1639},"level":0,"msg":"update required","ref":"HEAD","local":"","remote":"e816bc92b4a8448685db3afd4136e10ec9cd0907","syncCount":0}
{"logger":"","ts":"2024-01-16 09:17:02.843848","caller":{"file":"main.go","line":1712},"level":1,"msg":"fetching","ref":"e816bc92b4a8448685db3afd4136e10ec9cd0907","repo":"git@github.com:<org>/<repo>"}
{"logger":"","ts":"2024-01-16 09:17:02.843875","caller":{"file":"main.go","line":1730},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git fetch git@github.com:<org>/<repo> e816bc92b4a8448685db3afd4136e10ec9cd0907 --verbose --no-progress --prune --no-auto-gc --depth 1"}
{"logger":"","ts":"2024-01-16 09:17:30.245368","caller":{"file":"main.go","line":1730},"level":6,"msg":"command result","stdout":"","stderr":"From github.com:<org>/<repo>\n * branch            e816bc92b4a8448685db3afd4136e10ec9cd0907 -> FETCH_HEAD","time":"27.401387259s"}
{"logger":"","ts":"2024-01-16 09:17:30.245508","caller":{"file":"main.go","line":1650},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git reset --soft FETCH_HEAD"}
{"logger":"","ts":"2024-01-16 09:17:30.248741","caller":{"file":"main.go","line":1650},"level":6,"msg":"command result","stdout":"","stderr":"","time":"3.154505ms"}
{"logger":"","ts":"2024-01-16 09:17:30.248839","caller":{"file":"main.go","line":1330},"level":1,"msg":"adding worktree","path":"/git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907","hash":"e816bc92b4a8448685db3afd4136e10ec9cd0907"}
{"logger":"","ts":"2024-01-16 09:17:30.248882","caller":{"file":"main.go","line":1331},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git worktree add --force --detach /git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907 e816bc92b4a8448685db3afd4136e10ec9cd0907 --no-checkout"}
{"logger":"","ts":"2024-01-16 09:17:30.345773","caller":{"file":"main.go","line":1331},"level":6,"msg":"command result","stdout":"","stderr":"Preparing worktree (detached HEAD e816bc9)","time":"96.831158ms"}
{"logger":"","ts":"2024-01-16 09:17:30.347356","caller":{"file":"main.go","line":1402},"level":1,"msg":"setting worktree HEAD","hash":"e816bc92b4a8448685db3afd4136e10ec9cd0907"}
{"logger":"","ts":"2024-01-16 09:17:30.347430","caller":{"file":"main.go","line":1403},"level":5,"msg":"running command","cwd":"/git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907","cmd":"git reset --hard e816bc92b4a8448685db3afd4136e10ec9cd0907 --"}
{"logger":"","ts":"2024-01-16 09:17:40.341160","caller":{"file":"main.go","line":1403},"level":6,"msg":"command result","stdout":"HEAD is now at e816bc9 <commit-message>","stderr":"Updating files:  18% (1178/6410)\rUpdating files:  19% (1218/6410)\rUpdating files:  20% (1282/6410)\rUpdating files:  21% (1347/6410)\rUpdating files:  22% (1411/6410)\rUpdating files:  23% (1475/6410)\rUpdating files:  24% (1539/6410)\rUpdating files:  25% (1603/6410)\rUpdating files:  26% (1667/6410)\rUpdating files:  27% (1731/6410)\rUpdating files:  28% (1795/6410)\rUpdating files:  29% (1859/6410)\rUpdating files:  30% (1923/6410)\rUpdating files:  31% (1988/6410)\rUpdating files:  32% (2052/6410)\rUpdating files:  33% (2116/6410)\rUpdating files:  34% (2180/6410)\rUpdating files:  35% (2244/6410)\rUpdating files:  36% (2308/6410)\rUpdating files:  36% (2366/6410)\rUpdating files:  37% (2372/6410)\rUpdating files:  38% (2436/6410)\rUpdating files:  39% (2500/6410)\rUpdating files:  40% (2564/6410)\rUpdating files:  41% (2629/6410)\rUpdating files:  42% (2693/6410)\rUpdating files:  43% (2757/6410)\rUpdating files:  44% (2821/6410)\rUpdating files:  45% (2885/6410)\rUpdating files:  46% (2949/6410)\rUpdating files:  47% (3013/6410)\rUpdating files:  48% (3077/6410)\rUpdating files:  49% (3141/6410)\rUpdating files:  50% (3205/6410)\rUpdating files:  51% (3270/6410)\rUpdating files:  52% (3334/6410)\rUpdating files:  52% (3367/6410)\rUpdating files:  53% (3398/6410)\rUpdating files:  54% (3462/6410)\rUpdating files:  55% (3526/6410)\rUpdating files:  56% (3590/6410)\rUpdating files:  57% (3654/6410)\rUpdating files:  58% (3718/6410)\rUpdating files:  59% (3782/6410)\rUpdating files:  60% (3846/6410)\rUpdating files:  61% (3911/6410)\rUpdating files:  62% (3975/6410)\rUpdating files:  63% (4039/6410)\rUpdating files:  64% (4103/6410)\rUpdating files:  65% (4167/6410)\rUpdating files:  66% (4231/6410)\rUpdating files:  66% (4286/6410)\rUpdating files:  67% (4295/6410)\rUpdating files:  68% (4359/6410)\rUpdating files:  69% (4423/6410)\rUpdating files:  69% (4425/6410)\rUpdating files:  70% (4487/6410)\rUpdating files:  70% (4539/6410)\rUpdating files:  71% (4552/6410)\rUpdating files:  72% (4616/6410)\rUpdating files:  73% (4680/6410)\rUpdating files:  74% (4744/6410)\rUpdating files:  74% (4772/6410)\rUpdating files:  75% (4808/6410)\rUpdating files:  76% (4872/6410)\rUpdating files:  77% (4936/6410)\rUpdating files:  78% (5000/6410)\rUpdating files:  78% (5017/6410)\rUpdating files:  79% (5064/6410)\rUpdating files:  80% (5128/6410)\rUpdating files:  81% (5193/6410)\rUpdating files:  82% (5257/6410)\rUpdating files:  83% (5321/6410)\rUpdating files:  84% (5385/6410)\rUpdating files:  85% (5449/6410)\rUpdating files:  86% (5513/6410)\rUpdating files:  87% (5577/6410)\rUpdating files:  88% (5641/6410)\rUpdating files:  89% (5705/6410)\rUpdating files:  90% (5769/6410)\rUpdating files:  91% (5834/6410)\rUpdating files:  91% (5884/6410)\rUpdating files:  92% (5898/6410)\rUpdating files:  93% (5962/6410)\rUpdating files:  94% (6026/6410)\rUpdating files:  95% (6090/6410)\rUpdating files:  96% (6154/6410)\rUpdating files:  97% (6218/6410)\rUpdating files:  98% (6282/6410)\rUpdating files:  99% (6346/6410)\rUpdating files: 100% (6410/6410)\rUpdating files: 100% (6410/6410), done.","time":"9.993622284s"}
{"logger":"","ts":"2024-01-16 09:17:40.341336","caller":{"file":"main.go","line":1410},"level":1,"msg":"updating submodules"}
{"logger":"","ts":"2024-01-16 09:17:40.341369","caller":{"file":"main.go","line":1418},"level":5,"msg":"running command","cwd":"/git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907","cmd":"git submodule update --init --recursive --depth 1"}
{"logger":"","ts":"2024-01-16 09:17:40.842703","caller":{"file":"main.go","line":1418},"level":6,"msg":"command result","stdout":"","stderr":"","time":"501.241089ms"}
{"logger":"","ts":"2024-01-16 09:17:40.842802","caller":{"file":"main.go","line":1283},"level":2,"msg":"creating tmp symlink","dir":"/opt","link":"tmp-link","target":"../git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907"}
{"logger":"","ts":"2024-01-16 09:17:40.842908","caller":{"file":"main.go","line":1288},"level":2,"msg":"renaming symlink","root":"/opt","oldName":"tmp-link","newName":"<repo>"}
{"logger":"","ts":"2024-01-16 09:17:40.842960","caller":{"file":"main.go","line":1690},"level":0,"msg":"updated successfully","ref":"HEAD","remote":"e816bc92b4a8448685db3afd4136e10ec9cd0907","syncCount":1}
{"logger":"","ts":"2024-01-16 09:17:40.843015","caller":{"file":"main.go","line":1124},"level":3,"msg":"cleaning up stale worktrees","currentHash":"e816bc92b4a8448685db3afd4136e10ec9cd0907"}
{"logger":"","ts":"2024-01-16 09:17:40.843299","caller":{"file":"main.go","line":1247},"level":4,"msg":"skipping path","path":"/git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907"}
{"logger":"","ts":"2024-01-16 09:17:40.843375","caller":{"file":"main.go","line":1523},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git rev-parse HEAD^{commit}"}
{"logger":"","ts":"2024-01-16 09:17:40.846363","caller":{"file":"main.go","line":1523},"level":6,"msg":"command result","stdout":"e816bc92b4a8448685db3afd4136e10ec9cd0907","stderr":"","time":"2.907842ms"}
{"logger":"","ts":"2024-01-16 09:17:40.846448","caller":{"file":"main.go","line":855},"level":3,"msg":"next sync","waitTime":"1m0s","syncCount":1}
{"logger":"","ts":"2024-01-16 09:18:40.905393","caller":{"file":"main.go","line":1578},"level":3,"msg":"syncing","repo":"git@github.com:<org>/<repo>"}
{"logger":"","ts":"2024-01-16 09:18:40.905507","caller":{"file":"main.go","line":1071},"level":3,"msg":"repo directory exists","path":"/git/<repo>"}
{"logger":"","ts":"2024-01-16 09:18:40.905535","caller":{"file":"main.go","line":1143},"level":3,"msg":"sanity-checking git repo","repo":"/git/<repo>"}
{"logger":"","ts":"2024-01-16 09:18:40.905611","caller":{"file":"main.go","line":1154},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git rev-parse --show-toplevel"}
{"logger":"","ts":"2024-01-16 09:18:40.909156","caller":{"file":"main.go","line":1154},"level":6,"msg":"command result","stdout":"/git/<repo>","stderr":"","time":"3.472066ms"}
{"logger":"","ts":"2024-01-16 09:18:40.909388","caller":{"file":"main.go","line":1167},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git fsck --no-progress --connectivity-only"}
{"logger":"","ts":"2024-01-16 09:18:41.047240","caller":{"file":"main.go","line":1167},"level":6,"msg":"command result","stdout":"","stderr":"","time":"137.73858ms"}
{"logger":"","ts":"2024-01-16 09:18:41.047327","caller":{"file":"main.go","line":1073},"level":4,"msg":"repo directory is valid","path":"/git/<repo>"}
{"logger":"","ts":"2024-01-16 09:18:41.047356","caller":{"file":"main.go","line":1100},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git remote get-url origin"}
{"logger":"","ts":"2024-01-16 09:18:41.050264","caller":{"file":"main.go","line":1100},"level":6,"msg":"command result","stdout":"git@github.com:<org>/<repo>","stderr":"","time":"2.827379ms"}
{"logger":"","ts":"2024-01-16 09:18:41.050376","caller":{"file":"main.go","line":1496},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git ls-remote -q git@github.com:<org>/<repo> HEAD HEAD^{}"}
{"logger":"","ts":"2024-01-16 09:18:44.698025","caller":{"file":"main.go","line":1496},"level":6,"msg":"command result","stdout":"e816bc92b4a8448685db3afd4136e10ec9cd0907\tHEAD","stderr":"","time":"3.64745279s"}
{"logger":"","ts":"2024-01-16 09:18:44.698121","caller":{"file":"main.go","line":1617},"level":3,"msg":"current hash","hash":"e816bc92b4a8448685db3afd4136e10ec9cd0907"}
{"logger":"","ts":"2024-01-16 09:18:44.698146","caller":{"file":"main.go","line":1621},"level":3,"msg":"current hash is same as remote","hash":"e816bc92b4a8448685db3afd4136e10ec9cd0907"}
{"logger":"","ts":"2024-01-16 09:18:44.698185","caller":{"file":"main.go","line":1180},"level":3,"msg":"sanity-checking worktree","repo":"/git/<repo>","worktree":"/git/git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907"}
{"logger":"","ts":"2024-01-16 09:18:44.698237","caller":{"file":"main.go","line":1184},"msg":"can't list worktree directory","error":"open /git/git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907: no such file or directory","path":"/git/git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907"}
{"logger":"","ts":"2024-01-16 09:18:44.698286","caller":{"file":"main.go","line":1624},"level":0,"msg":"worktree failed checks or was empty","path":"/git/git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907"}
{"logger":"","ts":"2024-01-16 09:18:44.698317","caller":{"file":"main.go","line":1639},"level":0,"msg":"update required","ref":"HEAD","local":"","remote":"e816bc92b4a8448685db3afd4136e10ec9cd0907","syncCount":1}
{"logger":"","ts":"2024-01-16 09:18:44.698359","caller":{"file":"main.go","line":1712},"level":1,"msg":"fetching","ref":"e816bc92b4a8448685db3afd4136e10ec9cd0907","repo":"git@github.com:<org>/<repo>"}
{"logger":"","ts":"2024-01-16 09:18:44.698400","caller":{"file":"main.go","line":1730},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git fetch git@github.com:<org>/<repo> e816bc92b4a8448685db3afd4136e10ec9cd0907 --verbose --no-progress --prune --no-auto-gc --depth 1"}
{"logger":"","ts":"2024-01-16 09:18:50.947688","caller":{"file":"main.go","line":1730},"level":6,"msg":"command result","stdout":"","stderr":"From github.com:<org>/<repo>\n * branch            e816bc92b4a8448685db3afd4136e10ec9cd0907 -> FETCH_HEAD","time":"6.206703551s"}
{"logger":"","ts":"2024-01-16 09:18:50.947862","caller":{"file":"main.go","line":1650},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git reset --soft FETCH_HEAD"}
{"logger":"","ts":"2024-01-16 09:18:50.951560","caller":{"file":"main.go","line":1650},"level":6,"msg":"command result","stdout":"","stderr":"","time":"3.585999ms"}
{"logger":"","ts":"2024-01-16 09:18:50.951722","caller":{"file":"main.go","line":1306},"level":1,"msg":"removing worktree","path":"/git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907"}
{"logger":"","ts":"2024-01-16 09:18:56.442469","caller":{"file":"main.go","line":1310},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git worktree prune --verbose"}
{"logger":"","ts":"2024-01-16 09:18:56.445269","caller":{"file":"main.go","line":1310},"level":6,"msg":"command result","stdout":"","stderr":"Removing worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907: gitdir file points to non-existent location","time":"2.525673ms"}
{"logger":"","ts":"2024-01-16 09:18:56.445325","caller":{"file":"main.go","line":1330},"level":1,"msg":"adding worktree","path":"/git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907","hash":"e816bc92b4a8448685db3afd4136e10ec9cd0907"}
{"logger":"","ts":"2024-01-16 09:18:56.445368","caller":{"file":"main.go","line":1331},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git worktree add --force --detach /git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907 e816bc92b4a8448685db3afd4136e10ec9cd0907 --no-checkout"}
{"logger":"","ts":"2024-01-16 09:18:56.541761","caller":{"file":"main.go","line":1331},"level":6,"msg":"command result","stdout":"","stderr":"Preparing worktree (detached HEAD e816bc9)","time":"96.323012ms"}
{"logger":"","ts":"2024-01-16 09:18:56.542688","caller":{"file":"main.go","line":1402},"level":1,"msg":"setting worktree HEAD","hash":"e816bc92b4a8448685db3afd4136e10ec9cd0907"}
{"logger":"","ts":"2024-01-16 09:18:56.543213","caller":{"file":"main.go","line":1403},"level":5,"msg":"running command","cwd":"/git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907","cmd":"git reset --hard e816bc92b4a8448685db3afd4136e10ec9cd0907 --"}
{"logger":"","ts":"2024-01-16 09:19:06.646106","caller":{"file":"main.go","line":1403},"level":6,"msg":"command result","stdout":"HEAD is now at e816bc9 <commit-message>","stderr":"Updating files:  18% (1180/6410)\rUpdating files:  19% (1218/6410)\rUpdating files:  20% (1282/6410)\rUpdating files:  21% (1347/6410)\rUpdating files:  22% (1411/6410)\rUpdating files:  23% (1475/6410)\rUpdating files:  24% (1539/6410)\rUpdating files:  25% (1603/6410)\rUpdating files:  26% (1667/6410)\rUpdating files:  27% (1731/6410)\rUpdating files:  28% (1795/6410)\rUpdating files:  29% (1859/6410)\rUpdating files:  30% (1923/6410)\rUpdating files:  31% (1988/6410)\rUpdating files:  32% (2052/6410)\rUpdating files:  33% (2116/6410)\rUpdating files:  34% (2180/6410)\rUpdating files:  35% (2244/6410)\rUpdating files:  36% (2308/6410)\rUpdating files:  37% (2372/6410)\rUpdating files:  37% (2411/6410)\rUpdating files:  38% (2436/6410)\rUpdating files:  39% (2500/6410)\rUpdating files:  40% (2564/6410)\rUpdating files:  41% (2629/6410)\rUpdating files:  42% (2693/6410)\rUpdating files:  43% (2757/6410)\rUpdating files:  44% (2821/6410)\rUpdating files:  45% (2885/6410)\rUpdating files:  46% (2949/6410)\rUpdating files:  47% (3013/6410)\rUpdating files:  48% (3077/6410)\rUpdating files:  49% (3141/6410)\rUpdating files:  50% (3205/6410)\rUpdating files:  50% (3248/6410)\rUpdating files:  51% (3270/6410)\rUpdating files:  52% (3334/6410)\rUpdating files:  53% (3398/6410)\rUpdating files:  54% (3462/6410)\rUpdating files:  55% (3526/6410)\rUpdating files:  56% (3590/6410)\rUpdating files:  57% (3654/6410)\rUpdating files:  58% (3718/6410)\rUpdating files:  59% (3782/6410)\rUpdating files:  60% (3846/6410)\rUpdating files:  61% (3911/6410)\rUpdating files:  62% (3975/6410)\rUpdating files:  63% (4039/6410)\rUpdating files:  64% (4103/6410)\rUpdating files:  65% (4167/6410)\rUpdating files:  66% (4231/6410)\rUpdating files:  66% (4284/6410)\rUpdating files:  67% (4295/6410)\rUpdating files:  68% (4359/6410)\rUpdating files:  68% (4406/6410)\rUpdating files:  69% (4423/6410)\rUpdating files:  70% (4487/6410)\rUpdating files:  70% (4524/6410)\rUpdating files:  71% (4552/6410)\rUpdating files:  72% (4616/6410)\rUpdating files:  73% (4680/6410)\rUpdating files:  74% (4744/6410)\rUpdating files:  75% (4808/6410)\rUpdating files:  76% (4872/6410)\rUpdating files:  76% (4889/6410)\rUpdating files:  77% (4936/6410)\rUpdating files:  78% (5000/6410)\rUpdating files:  79% (5064/6410)\rUpdating files:  80% (5128/6410)\rUpdating files:  81% (5193/6410)\rUpdating files:  82% (5257/6410)\rUpdating files:  83% (5321/6410)\rUpdating files:  84% (5385/6410)\rUpdating files:  85% (5449/6410)\rUpdating files:  86% (5513/6410)\rUpdating files:  87% (5577/6410)\rUpdating files:  88% (5641/6410)\rUpdating files:  89% (5705/6410)\rUpdating files:  89% (5762/6410)\rUpdating files:  90% (5769/6410)\rUpdating files:  91% (5834/6410)\rUpdating files:  92% (5898/6410)\rUpdating files:  93% (5962/6410)\rUpdating files:  94% (6026/6410)\rUpdating files:  95% (6090/6410)\rUpdating files:  96% (6154/6410)\rUpdating files:  97% (6218/6410)\rUpdating files:  98% (6282/6410)\rUpdating files:  99% (6346/6410)\rUpdating files: 100% (6410/6410)\rUpdating files: 100% (6410/6410), done.","time":"10.102765416s"}
{"logger":"","ts":"2024-01-16 09:19:06.646324","caller":{"file":"main.go","line":1410},"level":1,"msg":"updating submodules"}
{"logger":"","ts":"2024-01-16 09:19:06.646362","caller":{"file":"main.go","line":1418},"level":5,"msg":"running command","cwd":"/git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907","cmd":"git submodule update --init --recursive --depth 1"}
{"logger":"","ts":"2024-01-16 09:19:07.141287","caller":{"file":"main.go","line":1418},"level":6,"msg":"command result","stdout":"","stderr":"","time":"494.848927ms"}
{"logger":"","ts":"2024-01-16 09:19:07.141378","caller":{"file":"main.go","line":1283},"level":2,"msg":"creating tmp symlink","dir":"/opt","link":"tmp-link","target":"../git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907"}
{"logger":"","ts":"2024-01-16 09:19:07.141505","caller":{"file":"main.go","line":1288},"level":2,"msg":"renaming symlink","root":"/opt","oldName":"tmp-link","newName":"<repo>"}
{"logger":"","ts":"2024-01-16 09:19:07.141858","caller":{"file":"main.go","line":1690},"level":0,"msg":"updated successfully","ref":"HEAD","remote":"e816bc92b4a8448685db3afd4136e10ec9cd0907","syncCount":2}
{"logger":"","ts":"2024-01-16 09:19:07.141939","caller":{"file":"main.go","line":1124},"level":3,"msg":"cleaning up stale worktrees","currentHash":"e816bc92b4a8448685db3afd4136e10ec9cd0907"}
{"logger":"","ts":"2024-01-16 09:19:07.142008","caller":{"file":"main.go","line":1247},"level":4,"msg":"skipping path","path":"/git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907"}
{"logger":"","ts":"2024-01-16 09:19:07.142051","caller":{"file":"main.go","line":1523},"level":5,"msg":"running command","cwd":"/git/<repo>","cmd":"git rev-parse HEAD^{commit}"}
{"logger":"","ts":"2024-01-16 09:19:07.145216","caller":{"file":"main.go","line":1523},"level":6,"msg":"command result","stdout":"e816bc92b4a8448685db3afd4136e10ec9cd0907","stderr":"","time":"3.092997ms"}
{"logger":"","ts":"2024-01-16 09:19:07.145298","caller":{"file":"main.go","line":855},"level":3,"msg":"next sync","waitTime":"1m0s","syncCount":2}
{"logger":"","ts":"2024-01-16 09:20:07.202734","caller":{"file":"main.go","line":1578},"level":3,"msg":"syncing","repo":"git@github.com:<org>/<repo>"}
{"logger":"","ts":"2024-01-16 09:20:07.202854","caller":{"file":"main.go","line":1071},"level":3,"msg":"repo directory exists","path":"/git/<repo>"}```
thockin commented 8 months ago

Well, there's clearly a problem. First we see:

"msg":"adding worktree","path":"/git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907","hash":"e816bc92b4a8448685db3afd4136e10ec9cd0907"}

Then a few lines later:

"msg":"sanity-checking worktree","repo":"/git/<repo>","worktree":"/git/git/<repo>/.worktrees/e816bc92b4a8448685db3afd4136e10ec9cd0907"}

Note the "/git/git". The problem is that I cannot repro it, even at 4.1.0. The good news is that I already have a fix in for it, but had not cut a release! https://github.com/kubernetes/git-sync/commit/9a806c09cbe5a9a851e8cab3e00dd8da5b28ac1d

I'll cut a 4.2.0 today, if possible.

thockin commented 8 months ago

https://github.com/kubernetes/git-sync/releases/tag/v4.2.0