search

sindrets / diffview.nvim

Single tabpage interface for easily cycling through diffs for all modified files for any git rev.
Other
3.74k stars 105 forks source link

[Bug] race condition in the parsing of git log? #371

Closed emmanueltouzery closed 1 year ago

emmanueltouzery commented 1 year ago

Description

while testing my (I believe unrelated) PR, I stumbled on a frequent (not 100%) reproduction of what I believe might be an unrelated race condition in the parsing of git-log output. I also see "Inbalance in data" in the diffview log.

Expected behavior

No response

Actual behavior

I have modified the diffview source to print out more info...

function GitAdapter:parse_fh_data(data, commit, state)
  local files = {}

+ print(vim.inspect(data.namestat))
  for i = 1, #data.numstat do

+   print(vim.inspect(data.namestat[i]))
    local status = data.namestat[i]:sub(1, 1):gsub("%s", " ")

It's clear that the data.namestat is malformed. It seems truncated, part of it is missing. I wonder whether it might be some sort of race condition, because I cannot reproduce the issue 100% of the time, only "often".

I didn't want to put actual filenames from the proprietary repo so I just indicate the filenames were 100% legit and prefixed with M\t, except for the final row that blows up, where there is no M\t and only the end of the filename.

Output+stacktrace 
"M\tcomplete_and_valid_filename.extension"
"M\tcomplete_and_valid_filename.extension"
"M\tcomplete_and_valid_filename.extension"
"M\tcomplete_and_valid_filename.extension"
"M\tcomplete_and_valid_filename.extension"
"M\tcomplete_and_valid_filename.extension"
"M\tcomplete_and_valid_filename.extension"
"M\tcomplete_and_valid_filename.extension"
"M\tcomplete_and_valid_filename.extension"
"M\tcomplete_and_valid_filename.extension"
"M\tcomplete_and_valid_filename.extension"
"only_end_of_filename.extension"
Error executing luv callback:
...e/pack/packer/start/diffview.nvim/lua/diffview/async.lua:179: The coroutine failed with this message: 
    context: cur_thread=main co_thread= co_func=...art/diffview.nvim/lua/diffview/vcs/adapters/git/init.lua:837
...art/diffview.nvim/lua/diffview/vcs/adapters/git/init.lua:1024: attempt to index local 'name' (a nil value)
stack traceback:
    ...art/diffview.nvim/lua/diffview/vcs/adapters/git/init.lua:1024: in function 'parse_fh_data'
    ...art/diffview.nvim/lua/diffview/vcs/adapters/git/init.lua:996: in function <...art/diffview.nvim/lua/diffview/vcs/adapters/git/init.lua:837>
    [C]: in function 'xpcall'
    ...e/pack/packer/start/diffview.nvim/lua/diffview/async.lua:354: in function <...e/pack/packer/start/diffview.nvim/lua/diffview/async.lua:351>
stack traceback:
    [C]: in function 'error'
    ...e/pack/packer/start/diffview.nvim/lua/diffview/async.lua:362: in function <...e/pack/packer/start/diffview.nvim/lua/diffview/async.lua:351>
stack traceback:
    [C]: in function 'error'
    ...e/pack/packer/start/diffview.nvim/lua/diffview/async.lua:179: in function 'raise'
    ...e/pack/packer/start/diffview.nvim/lua/diffview/async.lua:207: in function 'step'
    ...e/pack/packer/start/diffview.nvim/lua/diffview/async.lua:239: in function 'notify_all'
    ...e/pack/packer/start/diffview.nvim/lua/diffview/async.lua:214: in function 'step'
    ...e/pack/packer/start/diffview.nvim/lua/diffview/async.lua:392: in function 'temp'
    ...art/diffview.nvim/lua/diffview/vcs/adapters/git/init.lua:877: in function 'callback'
    ...art/diffview.nvim/lua/diffview/vcs/adapters/git/init.lua:462: in function 'listener'
    ...ite/pack/packer/start/diffview.nvim/lua/diffview/job.lua:192: in function <...ite/pack/packer/start/diffview.nvim/lua/diffview/job.lua:170>
    [C]: in function 'nvim_exec2'
    vim/_editor.lua: in function 'cmd'
    ...packer/start/diffview.nvim/lua/diffview/scene/layout.lua:298: in function <...packer/start/diffview.nvim/lua/diffview/scene/layout.lua:294>
    [C]: in function 'resume'
    ...e/pack/packer/start/diffview.nvim/lua/diffview/async.lua:185: in function 'step'
    ...e/pack/packer/start/diffview.nvim/lua/diffview/async.lua:239: in function 'notify_all'
    ...e/pack/packer/start/diffview.nvim/lua/diffview/async.lua:214: in function 'step'
    ...e/pack/packer/start/diffview.nvim/lua/diffview/async.lua:392: in function <...e/pack/packer/start/diffview.nvim/lua/diffview/async.lua:384>
Error detected while processing BufWinEnter Autocommands for "*":
E5108: Error executing lua ...start/todo-comments.nvim/lua/todo-comments/highlight.lua:175: Vim:E11: Invalid in command-line window;  executes, CTRL-C quits
stack traceback:
    [C]: in function 'nvim_set_current_win'
    ...start/todo-comments.nvim/lua/todo-comments/highlight.lua:175: in function 'highlight_win'
    ...start/todo-comments.nvim/lua/todo-comments/highlight.lua:263: in function 'attach'
    [string ":lua"]:1: in main chunk
Error executing Lua callback: vim/_editor.lua:0: nvim_exec2(): Vim(split):E11: Invalid in command-line window;  executes, CTRL-C quits: sp /home/emmanuel/.cache/nvim/diffview.log | norm! G
stack traceback:
    [C]: in function 'nvim_exec2'
    vim/_editor.lua: in function 'cmd'
    ...site/pack/packer/start/diffview.nvim/plugin/diffview.lua:54: in function <...site/pack/packer/start/diffview.nvim/plugin/diffview.lua:53>

Steps to reproduce

I run :DiffviewFileHistory --before=2023-03-05 (i believe the before is irrelevant) in a proprietary repo that I cannot share, and sometimes i'll get the error, but not 100% of the time.

Health check

Output of :checkhealth diffview ``` ============================================================================== diffview: require("diffview.health").check() Checking plugin dependencies ~ - OK nvim-web-devicons installed. Checking VCS tools ~ - The plugin requires at least one of the supported VCS tools to be valid. - OK Git found. - OK Git is up-to-date. (2.40.1) - WARNING Configured `hg_cmd` is not executable: 'hg' ```

Log info

Relevant info from :DiffviewLog ``` [INFO 2023-06-06 21:17:30.810 +0200] ...ite/pack/packer/start/diffview.nvim/lua/diffview/lib.lua:74: [command call] :DiffviewFileHistory --before=2023-03-05 [ERROR 2023-06-06 21:17:31.648 +0200] ...ck/packer/start/diffview.nvim/lua/diffview/multi_job.lua:142: Inbalance in file history data! [ERROR 2023-06-06 21:17:31.648 +0200] ...ck/packer/start/diffview.nvim/lua/diffview/multi_job.lua:145: [job-info] Exit code: 0 [ERROR 2023-06-06 21:17:31.648 +0200] ...ck/packer/start/diffview.nvim/lua/diffview/multi_job.lua:145: [cmd] git '-P' '-c' 'gc.auto=0' 'log' '--pretty=format:%x00' '--date=raw' '--numstat' '-n256' '--diff-merges=first-parent' '--before=2023-03-05' '--' [ERROR 2023-06-06 21:17:31.648 +0200] ...ck/packer/start/diffview.nvim/lua/diffview/multi_job.lua:145: [cwd] /home/emmanuel/projects/flatman [ERROR 2023-06-06 21:17:31.648 +0200] ...ck/packer/start/diffview.nvim/lua/diffview/multi_job.lua:148: (1/2) Retrying failed jobs... [INFO 2023-06-06 21:17:32.415 +0200] ...ck/packer/start/diffview.nvim/lua/diffview/multi_job.lua:157: Retry was successful! [INFO 2023-06-06 21:18:04.754 +0200] ...ite/pack/packer/start/diffview.nvim/lua/diffview/lib.lua:24: [command call] :DiffviewOpen [INFO 2023-06-06 21:18:04.866 +0200] ...iffview.nvim/lua/diffview/scene/views/diff/diff_view.lua:483: [DiffView] Completed update for 1 files successfully (32.498 ms) ```

Neovim version

NVIM v0.9.0
Build type: Release
LuaJIT 2.1.0-beta3

Operating system and version

Linux 6.3.5-200.fc38.x86_64 x86_64 GNU/Linux

Minimal config

No response

sindrets commented 1 year ago

Yes, I've tried to deal with this for some time. I believe it's a race condition in Git, because I can get it to produce malformed data in a shell as well. Seems like it's possibly related to running multiple Git jobs on the same repository concurrently. It's very difficult to deal with. But I have a new branch that I'm working on that aims to address this instability issue: https://github.com/sindrets/diffview.nvim/tree/perf/single-job-history

From my testing this approach seems a lot more stable. If you have time to test that branch, I would love to hear if it makes a difference for you as well.

jasnross commented 1 year ago

If you have time to test that branch

I started running into this same problem today. There is one specific repository where I can repro it consistently when using main branch. When I use the perf/single-job-history branch the issue goes away.

sindrets commented 1 year ago

@jasnross Thanks for testing the branch and reporting back. I've been using that branch for the last weeks and it's been far more stable for me. I have a few more ideas related to data validation and recovery that I'd like to work on, and then I'll try to get it merged soon.