{"thread":{"id":"54509","subject":"Tracking a merge bug","startedAt":"2020-10-26T15:08:23Z","lastAt":"2021-03-05T11:08:47Z","messageCount":3,"participants":["Ephrim Khong","Elijah Newren"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"408398","messageId":"120922f1-67a9-9ae2-2e9c-56e20935e0f9@gmail.com","threadId":"54509","inReplyTo":null,"subject":"Tracking a merge bug","fromName":"Ephrim Khong","fromEmail":"dr.khong@gmail.com","sentAt":"2020-10-26T15:08:13Z","receivedAt":"2020-10-26T15:08:23Z","isPatch":false,"sender":{"key":"dr.khong@gmail.com","avatar":"https://avatars.githubusercontent.com/u/2847265?v=4"},"body":"Dear All,\n\nI am trying to find the root cause for what I believe might be a strange\nbug in git merge.  I have a feature branch A which branched off master\nnot too long ago, and want to bring it up to date with master:\n\n    git checkout A\n    git merge master\n\nwhich yields\n\n    Removing somefile\n    Removing anotherfile\n    error: add_cacheinfo failed to refresh for path 'c/d/e.sh'; merge\naborting.\n\nthe offending file, c/d/e.sh, does not exist in my feature branch but\nwas added to master since branching off. After aborting, the working\ndirectory is in an inconsistent state and c/d/e.sh exists with the\ncorrect content.\n\nBelow is a stacktrace - the merger handles the file as a rename\n(apparently there is a similar / identical file 'c/f/g.sh' that is\nrenamed to 'c/d/e.sh'), but that fails because the file has MODE_CHANGED\nset. (Which appears strange - at the time where the merge is aborting,\nthe file apparently was already written to the working directory. Is it\nrenaming two different files to the same target file?).\n\nAny hint is appreciated, especially where to look: Is the root cause\nmore likely to be at the filesystem level (the stat returns something\noff), or in the merge logic? What else could be wrong here?\n\n\nThe stacktrace looks roughly as follows:\n\n-> read-cache.c, ie_modified(): ie_match_stat returned 63, which is\n\t\tMTIME_CHANGED\t| CTIME_CHANGED | OWNER_CHANGED |\n\t\tMODE_CHANGED | INODE_CHANGED | DATA_CHANGED\n\tand is_modified() returns 63 because MODE_CHANGED is set.\n\n-> read-cache.c, refresh_cache_ent(): at the call to ie_modified\n\n-> read-cache.c, refresh_cache_entry()\n\n-> merge-recursive.c, add_cacheinfo(), is in the refresh-path (i.e.\nmake_cache_entry() worked, but refresh_cache_entry() will fail)\n\n-> merge-recursive.c, update_file_flags(), after the update_index: label\n\n-> merge-recursive.c, update_file()\n\n-> merge-recursive.c, handle_content_merge() is in the very last\nupdate_file() call, close to the end of the function\n\n-> merge-recursive.c, handle_rename_normal()\n\n-> merge-recursive.c, process_entry()\n\tis in the RENAME_NORMAL / RENAME_ONE_FILE_TO_ONE block\n\n-> [...]\n\nThanks\n- Eph\n"},{"id":"408399","messageId":"CABPp-BFju3vJYMRH8fXBcHu1sDkthWsdO9rJzSNKB7E3pfGiHQ@mail.gmail.com","threadId":"54509","inReplyTo":"120922f1-67a9-9ae2-2e9c-56e20935e0f9@gmail.com","subject":"Re: Tracking a merge bug","fromName":"Elijah Newren","fromEmail":"newren@gmail.com","sentAt":"2020-10-26T15:50:19Z","receivedAt":"2020-10-26T15:50:33Z","isPatch":false,"sender":{"key":"newren@gmail.com","avatar":"https://avatars.githubusercontent.com/u/5455730?v=4"},"body":"On Mon, Oct 26, 2020 at 8:11 AM Ephrim Khong <dr.khong@gmail.com> wrote:\n>\n> Dear All,\n>\n> I am trying to find the root cause for what I believe might be a strange\n> bug in git merge.  I have a feature branch A which branched off master\n> not too long ago, and want to bring it up to date with master:\n>\n>     git checkout A\n>     git merge master\n>\n> which yields\n>\n>     Removing somefile\n>     Removing anotherfile\n>     error: add_cacheinfo failed to refresh for path 'c/d/e.sh'; merge\n> aborting.\n\n\"add_cacheinfo failed to refresh\"?  Wow, that's a new one.  Some years\nback we had a \"add_cacheinfo failed for path\" corresponding to the\nother error site within that function, but we fixed that one up long\nago.  I've never seen anything hit the refresh failure.\n\nThe fact that you're seeing this error message means you're using git\n>= 2.18.0.  Could you verify the exact version?\n\nAlso, I suspect \"somefile\" and \"anotherfile\" are placeholders.  Any\nchance we could see the real names?\n\n> the offending file, c/d/e.sh, does not exist in my feature branch but\n> was added to master since branching off. After aborting, the working\n> directory is in an inconsistent state and c/d/e.sh exists with the\n> correct content.\n\nIs c/d a file or submodule or anything in the feature branch?  Do you\nhave any untracked files at the beginning of the merge named c/d or\nc/d/e.sh?  I'm trying to guess at what might be weird about the paths\nhere.\n\n> Below is a stacktrace - the merger handles the file as a rename\n> (apparently there is a similar / identical file 'c/f/g.sh' that is\n> renamed to 'c/d/e.sh'), but that fails because the file has MODE_CHANGED\n> set. (Which appears strange - at the time where the merge is aborting,\n> the file apparently was already written to the working directory. Is it\n> renaming two different files to the same target file?).\n\nWhat's the output of\n  git ls-tree -r master | grep c/d/e.sh\n  git ls-tree -r feature | grep c/d/f.sh\n  git ls-tree -r $(git merge-base master feature) | grep c/d/f.sh\n?\n\nAnd, before the merge, what is the output of\n  ls -l c/d/e.sh c/d/f.sh\n?\n\n> Any hint is appreciated, especially where to look: Is the root cause\n> more likely to be at the filesystem level (the stat returns something\n> off), or in the merge logic? What else could be wrong here?\n\nNot sure; I've never hit this before.  I'm curious if you've got a\nweird mode recorded for one of the files in your tree or something.\nWe might have to get someone who understands the index data structure\nand read-cache.c to take a look.\n\n> The stacktrace looks roughly as follows:\n>\n> -> read-cache.c, ie_modified(): ie_match_stat returned 63, which is\n>                 MTIME_CHANGED   | CTIME_CHANGED | OWNER_CHANGED |\n>                 MODE_CHANGED | INODE_CHANGED | DATA_CHANGED\n>         and is_modified() returns 63 because MODE_CHANGED is set.\n>\n> -> read-cache.c, refresh_cache_ent(): at the call to ie_modified\n>\n> -> read-cache.c, refresh_cache_entry()\n>\n> -> merge-recursive.c, add_cacheinfo(), is in the refresh-path (i.e.\n> make_cache_entry() worked, but refresh_cache_entry() will fail)\n>\n> -> merge-recursive.c, update_file_flags(), after the update_index: label\n>\n> -> merge-recursive.c, update_file()\n>\n> -> merge-recursive.c, handle_content_merge() is in the very last\n> update_file() call, close to the end of the function\n>\n> -> merge-recursive.c, handle_rename_normal()\n>\n> -> merge-recursive.c, process_entry()\n>         is in the RENAME_NORMAL / RENAME_ONE_FILE_TO_ONE block\n\nRENAME_NORMAL / RENAME_ONE_FILE_TO_ONE means this is NOT a case of\nrenaming two files to one.  From just this information, it could be\nthat both sides renamed c/d/f.sh -> c/d/e.sh -- but you ruled that out\nwhen you said c/d/e.sh didn't exist in your branch.  So, that\nbasically leaves us with a normal rename; i.e. c/d/f.sh existed in the\nmerge base and in your feature branch, but it was renamed to c/d/e.sh\nin master.\n\n\nAny chance this repository is available for others to access to try to\nreproduce the problem?  If the repository has sensitive contents, are\nthe files c/d/f.sh and c/d/e.sh sensitive?  If the repository overall\nis sensitive but those two files aren't, we might be able to get a\nreproduction by cloning the repository and running\n   git filter-repo --path c/d/e.sh --path c/d/f.sh\nto filter the repository down to just these two files (after first\ninstalling git-filter-repo; see\nhttps://github.com/newren/git-filter-repo).\n"},{"id":"418309","messageId":"7b960460-dd3a-abaf-b97b-9b29cbc52990@gmail.com","threadId":"54509","inReplyTo":"CABPp-BFju3vJYMRH8fXBcHu1sDkthWsdO9rJzSNKB7E3pfGiHQ@mail.gmail.com","subject":"Re: Tracking a merge bug","fromName":"Ephrim Khong","fromEmail":"dr.khong@gmail.com","sentAt":"2021-03-05T11:07:46Z","receivedAt":"2021-03-05T11:08:47Z","isPatch":false,"sender":{"key":"dr.khong@gmail.com","avatar":"https://avatars.githubusercontent.com/u/2847265?v=4"},"body":"On 26.10.2020 16:50, Elijah Newren wrote:\n> On Mon, Oct 26, 2020 at 8:11 AM Ephrim Khong <dr.khong@gmail.com> wrote:\n>>\n>> I am trying to find the root cause for what I believe might be a strange\n>> bug in git merge.  I have a feature branch A which branched off master\n>> not too long ago, and want to bring it up to date with master:\n>>\n>>     git checkout A\n>>     git merge master\n>>\n>> which yields\n>>\n>>     error: add_cacheinfo failed to refresh for path 'c/d/e.sh'; merge\n>> aborting.\n> \n> \"add_cacheinfo failed to refresh\"?  Wow, that's a new one.  Some years\n> back we had a \"add_cacheinfo failed for path\" corresponding to the\n> other error site within that function, but we fixed that one up long\n> ago.  I've never seen anything hit the refresh failure.\n\nThank you for looking into this and sorry for the delay. I ran into this\nagain and did some more testing.\n\nThe merge works if I copy the complete repository to a different\nfilesystem (in this case a local SSD) with cp -a. It was originally on a\nnetwork share.\n\nAn strace on the affected file seems to show that git creates and writes\nthe file, attempting to set the executable bit. But the subsequent lstat\nreports that no executable bit is set (and that is correct, when looking\nat the file after the merge errors out):\n\n\t\n> lstat(\"tools/ci/nightly/run_benchmarks.sh\", 0x7ffc2f148c20) = -1 ENOENT (No such file or directory)\n> openat(AT_FDCWD, \"tools/ci/nightly/run_benchmarks.sh\", O_WRONLY|O_CREAT|O_EXCL, 0777) = 4\n> write(4, \"#!/bin/bash\\n#\\n# Build and run hb\"..., 1973) = 1973\n> fstat(4, {st_mode=S_IFREG|0755, st_size=1973, ...}) = 0\n> close(4)                                = 0\n> \t\n> lstat(\"tools/ci/nightly/run_benchmarks.sh\", {st_mode=S_IFREG|0755, st_size=1973, ...}) = 0   #<-- first lstat, mode is OK\n> unlink(\"tools/ci/nightly/run_benchmarks.sh\") = 0\n> openat(AT_FDCWD, \"tools/ci/nightly/run_benchmarks.sh\", O_WRONLY|O_CREAT|O_TRUNC, 0777) = 4\n> write(4, \"#!/bin/bash\\n#\\n# Build and run hb\"..., 1973) = 1973\n> close(4)                                = 0\n> lstat(\"tools/ci/nightly/run_benchmarks.sh\", {st_mode=S_IFREG|0640, st_size=1973, ...}) = 0   #<-- second lstat, mode is wrong\n> \t\n> write(2, \"error: add_cacheinfo failed to r\"..., 120error: add_cacheinfo failed to refresh for path 'tools/ci/nightly/run_benchmarks.sh' (2); merge aborting.\n\nnote how the last lstat() reports 0640, even though openat() wanted\n0777. The same thing when merging on the SSD shows\n\n> lstat(\"tools/ci/nightly/run_benchmarks.sh\", 0x7ffd491745c0) = -1 ENOENT (No such file or directory)\n> openat(AT_FDCWD, \"tools/ci/nightly/run_benchmarks.sh\", O_WRONLY|O_CREAT|O_EXCL, 0777) = 4\n> write(4, \"#!/bin/bash\\n#\\n# Build and run hb\"..., 1973) = 1973\n> fstat(4, {st_mode=S_IFREG|0755, st_size=1973, ...}) = 0\n> close(4)                                = 0\n> \t\t\n> lstat(\"tools/ci/nightly/run_benchmarks.sh\", {st_mode=S_IFREG|0755, st_size=1973, ...}) = 0\n> unlink(\"tools/ci/nightly/run_benchmarks.sh\") = 0\n> openat(AT_FDCWD, \"tools/ci/nightly/run_benchmarks.sh\", O_WRONLY|O_CREAT|O_TRUNC, 0777) = 4\n> write(4, \"#!/bin/bash\\n#\\n# Build and run hb\"..., 1973) = 1973\n> close(4)                                = 0\n> lstat(\"tools/ci/nightly/run_benchmarks.sh\", {st_mode=S_IFREG|0755, st_size=1973, ...}) = 0\n> \t\t\n> openat(AT_FDCWD, \"tools/ci/nightly/run_benchmarks.sh\", O_RDONLY|O_CLOEXEC) = 4\n> read(4, \"#!/bin/bash\\n#\\n# Build and run hb\"..., 1973) = 1973\n> close(4)                                = 0\n\nhere, lstat() reports 0755 and the merge continues.\n\nThis could very well be an issue with the storage system backing my\nnetwork share, but maybe I overlooked something in that strace that git\nis doing wrong or could do better. It does, for example, write the file\ntwice with identical content for some reason.\n\nI have patched my git for now, and in read-cache.c, refresh_cache_ent()\ncall chmod() and re-run lstat() if the mode is incorrect. That fixes the\nproblem for now. It's not perfect, since chmod() ignores the umask, but\nat least allows to merge.\n\n> Any chance this repository is available for others to access to try to\n> reproduce the problem?\n\nUnfortunately it's not public. I have tried to cut out the offending\npart, but was unable to reproduce it with a smaller test case yet.\n\nThanks\n- Eph\n"}]}