Skip to content

log_init: call log_path_init #11501

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Merged
merged 1 commit into from
Dec 2, 2019
Merged

log_init: call log_path_init #11501

merged 1 commit into from
Dec 2, 2019

Conversation

blueyed
Copy link
Contributor

@blueyed blueyed commented Dec 2, 2019

This has to be done after init_homedir for XDG default and set_init_1 for
lookup from env, which could be done earlier likely (to help with
#10937), but this keeps it in
sync with Vim.

Fixes #11499.

@blueyed
log_init: call log_path_init
1b8e124 
This has to be done after `init_homedir` for XDG default and `set_init_1` for
lookup from env, which could be done earlier likely (to help with
neovim#10937), but this keeps it in
sync with Vim.

Fixes neovim#11499.
@blueyed blueyed merged commit 22b52dd into neovim:master Dec 2, 2019
@blueyed blueyed deleted the log-always branch December 2, 2019 21:21
@justinmk justinmk mentioned this pull request Sep 26, 2021
Closed
justinmk added a commit to justinmk/neovim that referenced this pull request May 27, 2022
@justinmk
fix(startup): crash on early logging
e4de714 
Problem:
22b52dd (neovim#11501) regressed 6f27f5e (neovim#10172). We need at least
the mutex to be initalized before early_init so that things like
process_spawn can use logging without crashing Nvim.

Solution:
- Initialize logging in two stages. The first stage initalizes the mutex
  so that log_lock() doesn't crash.
- FUTURE: we can simplify this after "remote TUI", then we can remove
  log_lock().
@justinmk justinmk mentioned this pull request May 27, 2022
Merged
justinmk added a commit to justinmk/neovim that referenced this pull request May 27, 2022
@justinmk
fix(startup): crash on early logging
ac73f75 
Problem:
22b52dd (neovim#11501) regressed 6f27f5e (neovim#10172). We need at least
the mutex to be initalized before early_init so that things like
process_spawn can use logging without crashing Nvim.

Solution:
- Initialize logging in two stages. The first stage initalizes the mutex
  so that log_lock() doesn't crash.
- FUTURE: we can simplify this after "remote TUI", then we can remove
  log_lock().
justinmk added a commit to justinmk/neovim that referenced this pull request May 28, 2022
@justinmk
fix(startup): crash on early logging
074c1dc 
Problem:
22b52dd (neovim#11501) regressed 6f27f5e (neovim#10172), because
set_init_1..process_spawn tries to log (see backtrace below), but the
mutex isn't initalized yet. Even if the mutex were valid, we don't want
early logging to fallback to stderr because that can break embedders
when stdio is used as an RPC channel.

Solution:
- Skip logging if log_init wasn't called yet.
- FUTURE: when "remote TUI" is merged, can we remove log_lock()?

    frame #1: 0x00000001001d54f4 nvim`open_log_file at log.c:205:7
    frame #2: 0x00000001001d5390 nvim`logmsg(log_level=1, context="UI: ", func_name=0x0000000000000000, line_num=-1, eol=true, fmt="win_viewport") at log.c:150:20
    frame #3: 0x000000010039aea2 nvim`ui_call_win_viewport(grid=2, win=1000, topline=0, botline=1, curline=0, curcol=0, line_count=1) at ui_events_call.generated.h:321:3
    frame #4: 0x00000001003dfefc nvim`ui_ext_win_viewport(wp=0x0000000101816400) at window.c:939:5
    frame #5: 0x00000001003ec5b4 nvim`win_ui_flush at window.c:7303:7
    frame #6: 0x00000001003a04c0 nvim`ui_flush at ui.c:508:3
    frame neovim#7: 0x00000001002966ba nvim`do_os_system(argv=0x0000600000c0c000, input=0x0000000000000000, len=0, output=0x0000000000000000, nread=0x00007ff7bfefe830, silent=false, forward_output=false) at shell.c:894:3
    frame neovim#8: 0x0000000100295f68 nvim`os_call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_args=0x0000000000000000) at shell.c:663:18
    frame neovim#9: 0x0000000100295845 nvim`call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_shell_arg=0x0000000000000000) at shell.c:712:14
    frame neovim#10: 0x0000000100294c6f nvim`os_expand_wildcards(num_pat=1, pat=0x00007ff7bfefeb20, num_file=0x00007ff7bfefee58, file=0x00007ff7bfefee60, flags=43) at shell.c:328:7
    ...
    frame neovim#23: 0x000000010028ccef nvim`expand_env_esc(srcp=",~foo", dst="~foo", dstlen=4094, esc=false, one=false, prefix=0x0000000000000000) at env.c:673:17
    frame neovim#24: 0x000000010026fdd5 nvim`option_expand(opt_idx=29, val=",~foo") at option.c:1950:3
    frame neovim#25: 0x000000010026f129 nvim`set_init_1(clean_arg=false) at option.c:558:19
    frame neovim#26: 0x00000001001ea25e nvim`early_init(paramp=0x00007ff7bfeff5f0) at main.c:198:3
    frame neovim#27: 0x00000001001ea6bf nvim`main(argc=1, argv=0x00007ff7bfeff848) at main.c:255:3
justinmk added a commit to justinmk/neovim that referenced this pull request May 28, 2022
@justinmk
fix(startup): crash on early logging
86debd1 
Problem:
22b52dd (neovim#11501) regressed 6f27f5e (neovim#10172), because
set_init_1..process_spawn tries to log (see backtrace below), but the
mutex isn't initalized yet. Even if the mutex were valid, we don't want
early logging to fallback to stderr because that can break embedders
when stdio is used as an RPC channel.

Solution:
- Skip logging if log_init wasn't called yet.
- FUTURE: when "remote TUI" is merged, can we remove log_lock()?

    frame #1: 0x00000001001d54f4 nvim`open_log_file at log.c:205:7
    frame #2: 0x00000001001d5390 nvim`logmsg(log_level=1, context="UI: ", func_name=0x0000000000000000, line_num=-1, eol=true, fmt="win_viewport") at log.c:150:20
    frame #3: 0x000000010039aea2 nvim`ui_call_win_viewport(grid=2, win=1000, topline=0, botline=1, curline=0, curcol=0, line_count=1) at ui_events_call.generated.h:321:3
    frame #4: 0x00000001003dfefc nvim`ui_ext_win_viewport(wp=0x0000000101816400) at window.c:939:5
    frame #5: 0x00000001003ec5b4 nvim`win_ui_flush at window.c:7303:7
    frame #6: 0x00000001003a04c0 nvim`ui_flush at ui.c:508:3
    frame neovim#7: 0x00000001002966ba nvim`do_os_system(argv=0x0000600000c0c000, input=0x0000000000000000, len=0, output=0x0000000000000000, nread=0x00007ff7bfefe830, silent=false, forward_output=false) at shell.c:894:3
    frame neovim#8: 0x0000000100295f68 nvim`os_call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_args=0x0000000000000000) at shell.c:663:18
    frame neovim#9: 0x0000000100295845 nvim`call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_shell_arg=0x0000000000000000) at shell.c:712:14
    frame neovim#10: 0x0000000100294c6f nvim`os_expand_wildcards(num_pat=1, pat=0x00007ff7bfefeb20, num_file=0x00007ff7bfefee58, file=0x00007ff7bfefee60, flags=43) at shell.c:328:7
    ...
    frame neovim#23: 0x000000010028ccef nvim`expand_env_esc(srcp=",~foo", dst="~foo", dstlen=4094, esc=false, one=false, prefix=0x0000000000000000) at env.c:673:17
    frame neovim#24: 0x000000010026fdd5 nvim`option_expand(opt_idx=29, val=",~foo") at option.c:1950:3
    frame neovim#25: 0x000000010026f129 nvim`set_init_1(clean_arg=false) at option.c:558:19
    frame neovim#26: 0x00000001001ea25e nvim`early_init(paramp=0x00007ff7bfeff5f0) at main.c:198:3
    frame neovim#27: 0x00000001001ea6bf nvim`main(argc=1, argv=0x00007ff7bfeff848) at main.c:255:3
justinmk added a commit to justinmk/neovim that referenced this pull request May 28, 2022
@justinmk
fix(startup): crash on early logging
19dbc4f 
Problem:
22b52dd (neovim#11501) regressed 6f27f5e (neovim#10172), because
set_init_1..process_spawn tries to log (see backtrace below), but the
mutex isn't initalized yet. Even if the mutex were valid, we don't want
early logging to fallback to stderr because that can break embedders
when stdio is used as an RPC channel.

Solution:
- Skip logging if log_init wasn't called yet.
- FUTURE: when "remote TUI" is merged, can we remove log_lock()?

    frame #1: 0x00000001001d54f4 nvim`open_log_file at log.c:205:7
    frame #2: 0x00000001001d5390 nvim`logmsg(log_level=1, context="UI: ", func_name=0x0000000000000000, line_num=-1, eol=true, fmt="win_viewport") at log.c:150:20
    frame #3: 0x000000010039aea2 nvim`ui_call_win_viewport(grid=2, win=1000, topline=0, botline=1, curline=0, curcol=0, line_count=1) at ui_events_call.generated.h:321:3
    frame #4: 0x00000001003dfefc nvim`ui_ext_win_viewport(wp=0x0000000101816400) at window.c:939:5
    frame #5: 0x00000001003ec5b4 nvim`win_ui_flush at window.c:7303:7
    frame #6: 0x00000001003a04c0 nvim`ui_flush at ui.c:508:3
    frame neovim#7: 0x00000001002966ba nvim`do_os_system(argv=0x0000600000c0c000, input=0x0000000000000000, len=0, output=0x0000000000000000, nread=0x00007ff7bfefe830, silent=false, forward_output=false) at shell.c:894:3
    frame neovim#8: 0x0000000100295f68 nvim`os_call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_args=0x0000000000000000) at shell.c:663:18
    frame neovim#9: 0x0000000100295845 nvim`call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_shell_arg=0x0000000000000000) at shell.c:712:14
    frame neovim#10: 0x0000000100294c6f nvim`os_expand_wildcards(num_pat=1, pat=0x00007ff7bfefeb20, num_file=0x00007ff7bfefee58, file=0x00007ff7bfefee60, flags=43) at shell.c:328:7
    ...
    frame neovim#23: 0x000000010028ccef nvim`expand_env_esc(srcp=",~foo", dst="~foo", dstlen=4094, esc=false, one=false, prefix=0x0000000000000000) at env.c:673:17
    frame neovim#24: 0x000000010026fdd5 nvim`option_expand(opt_idx=29, val=",~foo") at option.c:1950:3
    frame neovim#25: 0x000000010026f129 nvim`set_init_1(clean_arg=false) at option.c:558:19
    frame neovim#26: 0x00000001001ea25e nvim`early_init(paramp=0x00007ff7bfeff5f0) at main.c:198:3
    frame neovim#27: 0x00000001001ea6bf nvim`main(argc=1, argv=0x00007ff7bfeff848) at main.c:255:3
justinmk added a commit to justinmk/neovim that referenced this pull request May 29, 2022
@justinmk
fix(logging): skip recursion, fix crash
5852047 
Problem:
1. The main log routine does not protect itself against recursion.
   log_lock() doesn't guard against recursion, it would deadlock...
2. 22b52dd (neovim#11501) regressed 6f27f5e (neovim#10172), because
   set_init_1..process_spawn tries to log (see backtrace below), but the
   mutex isn't initalized yet. Even if the mutex were valid, we don't
   want early logging to fallback to stderr because that can break
   embedders when stdio is used as an RPC channel.

    frame #1: 0x00000001001d54f4 nvim`open_log_file at log.c:205:7
    frame #2: 0x00000001001d5390 nvim`logmsg(log_level=1, context="UI: ", func_name=0x0000000000000000, line_num=-1, eol=true, fmt="win_viewport") at log.c:150:20
    frame #3: 0x000000010039aea2 nvim`ui_call_win_viewport(grid=2, win=1000, topline=0, botline=1, curline=0, curcol=0, line_count=1) at ui_events_call.generated.h:321:3
    frame #4: 0x00000001003dfefc nvim`ui_ext_win_viewport(wp=0x0000000101816400) at window.c:939:5
    frame #5: 0x00000001003ec5b4 nvim`win_ui_flush at window.c:7303:7
    frame #6: 0x00000001003a04c0 nvim`ui_flush at ui.c:508:3
    frame neovim#7: 0x00000001002966ba nvim`do_os_system(argv=0x0000600000c0c000, input=0x0000000000000000, len=0, output=0x0000000000000000, nread=0x00007ff7bfefe830, silent=false, forward_output=false) at shell.c:894:3
    frame neovim#8: 0x0000000100295f68 nvim`os_call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_args=0x0000000000000000) at shell.c:663:18
    frame neovim#9: 0x0000000100295845 nvim`call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_shell_arg=0x0000000000000000) at shell.c:712:14
    frame neovim#10: 0x0000000100294c6f nvim`os_expand_wildcards(num_pat=1, pat=0x00007ff7bfefeb20, num_file=0x00007ff7bfefee58, file=0x00007ff7bfefee60, flags=43) at shell.c:328:7
    ...
    frame neovim#23: 0x000000010028ccef nvim`expand_env_esc(srcp=",~foo", dst="~foo", dstlen=4094, esc=false, one=false, prefix=0x0000000000000000) at env.c:673:17
    frame neovim#24: 0x000000010026fdd5 nvim`option_expand(opt_idx=29, val=",~foo") at option.c:1950:3
    frame neovim#25: 0x000000010026f129 nvim`set_init_1(clean_arg=false) at option.c:558:19
    frame neovim#26: 0x00000001001ea25e nvim`early_init(paramp=0x00007ff7bfeff5f0) at main.c:198:3
    frame neovim#27: 0x00000001001ea6bf nvim`main(argc=1, argv=0x00007ff7bfeff848) at main.c:255:3

Solution:
1. Check for recursion and log to stderr.
    - FUTURE: when "remote TUI" is merged, can we remove log_lock()?
2. Skip logging if log_init wasn't called yet.
justinmk added a commit to justinmk/neovim that referenced this pull request May 29, 2022
@justinmk
fix(logging): skip recursion, fix crash
ff0a17b 
Problem:
1. The main log routine does not protect itself against recursion.
   log_lock() doesn't guard against recursion, it would deadlock...
2. 22b52dd (neovim#11501) regressed 6f27f5e (neovim#10172), because
   set_init_1..process_spawn tries to log (see backtrace below), but the
   mutex isn't initalized yet. Even if the mutex were valid, we don't
   want early logging to fallback to stderr because that can break
   embedders when stdio is used as an RPC channel.

    frame 1: 0x00000001001d54f4 nvim`open_log_file at log.c:205:7
    frame 2: 0x00000001001d5390 nvim`logmsg(log_level=1, context="UI: ", func_name=0x0000000000000000, line_num=-1, eol=true, fmt="win_viewport") at log.c:150:20
    frame : 0x000000010039aea2 nvim`ui_call_win_viewport(grid=2, win=1000, topline=0, botline=1, curline=0, curcol=0, line_count=1) at ui_events_call.generated.h:321:3
    frame 4: 0x00000001003dfefc nvim`ui_ext_win_viewport(wp=0x0000000101816400) at window.c:939:5
    frame 5: 0x00000001003ec5b4 nvim`win_ui_flush at window.c:7303:7
    frame 6: 0x00000001003a04c0 nvim`ui_flush at ui.c:508:3
    frame 7: 0x00000001002966ba nvim`do_os_system(argv=0x0000600000c0c000, input=0x0000000000000000, len=0, output=0x0000000000000000, nread=0x00007ff7bfefe830, silent=false, forward_output=false) at shell.c:894:3
    frame 8: 0x0000000100295f68 nvim`os_call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_args=0x0000000000000000) at shell.c:663:18
    frame 9: 0x0000000100295845 nvim`call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_shell_arg=0x0000000000000000) at shell.c:712:14
    frame 10: 0x0000000100294c6f nvim`os_expand_wildcards(num_pat=1, pat=0x00007ff7bfefeb20, num_file=0x00007ff7bfefee58, file=0x00007ff7bfefee60, flags=43) at shell.c:328:7
    ...
    frame 23: 0x000000010028ccef nvim`expand_env_esc(srcp=",~foo", dst="~foo", dstlen=4094, esc=false, one=false, prefix=0x0000000000000000) at env.c:673:17
    frame 24: 0x000000010026fdd5 nvim`option_expand(opt_idx=29, val=",~foo") at option.c:1950:3
    frame 25: 0x000000010026f129 nvim`set_init_1(clean_arg=false) at option.c:558:19
    frame 26: 0x00000001001ea25e nvim`early_init(paramp=0x00007ff7bfeff5f0) at main.c:198:3
    frame 27: 0x00000001001ea6bf nvim`main(argc=1, argv=0x00007ff7bfeff848) at main.c:255:3

Solution:
1. Check for recursion and log to stderr.
    - FUTURE: when "remote TUI" is merged, can we remove log_lock()?
2. Skip logging if log_init wasn't called yet.
justinmk added a commit to justinmk/neovim that referenced this pull request May 30, 2022
@justinmk
fix(logging): skip recursion, fix crash
c6a8915 
Problem:
1. The main log routine does not protect itself against recursion.
   log_lock() doesn't guard against recursion, it would deadlock...
2. 22b52dd (neovim#11501) regressed 6f27f5e (neovim#10172), because
   set_init_1..process_spawn tries to log (see backtrace below), but the
   mutex isn't initalized yet. Even if the mutex were valid, we don't
   want early logging to fallback to stderr because that can break
   embedders when stdio is used as an RPC channel.

    frame 1: 0x00000001001d54f4 nvim`open_log_file at log.c:205:7
    frame 2: 0x00000001001d5390 nvim`logmsg(log_level=1, context="UI: ", func_name=0x0000000000000000, line_num=-1, eol=true, fmt="win_viewport") at log.c:150:20
    frame : 0x000000010039aea2 nvim`ui_call_win_viewport(grid=2, win=1000, topline=0, botline=1, curline=0, curcol=0, line_count=1) at ui_events_call.generated.h:321:3
    frame 4: 0x00000001003dfefc nvim`ui_ext_win_viewport(wp=0x0000000101816400) at window.c:939:5
    frame 5: 0x00000001003ec5b4 nvim`win_ui_flush at window.c:7303:7
    frame 6: 0x00000001003a04c0 nvim`ui_flush at ui.c:508:3
    frame 7: 0x00000001002966ba nvim`do_os_system(argv=0x0000600000c0c000, input=0x0000000000000000, len=0, output=0x0000000000000000, nread=0x00007ff7bfefe830, silent=false, forward_output=false) at shell.c:894:3
    frame 8: 0x0000000100295f68 nvim`os_call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_args=0x0000000000000000) at shell.c:663:18
    frame 9: 0x0000000100295845 nvim`call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_shell_arg=0x0000000000000000) at shell.c:712:14
    frame 10: 0x0000000100294c6f nvim`os_expand_wildcards(num_pat=1, pat=0x00007ff7bfefeb20, num_file=0x00007ff7bfefee58, file=0x00007ff7bfefee60, flags=43) at shell.c:328:7
    ...
    frame 23: 0x000000010028ccef nvim`expand_env_esc(srcp=",~foo", dst="~foo", dstlen=4094, esc=false, one=false, prefix=0x0000000000000000) at env.c:673:17
    frame 24: 0x000000010026fdd5 nvim`option_expand(opt_idx=29, val=",~foo") at option.c:1950:3
    frame 25: 0x000000010026f129 nvim`set_init_1(clean_arg=false) at option.c:558:19
    frame 26: 0x00000001001ea25e nvim`early_init(paramp=0x00007ff7bfeff5f0) at main.c:198:3
    frame 27: 0x00000001001ea6bf nvim`main(argc=1, argv=0x00007ff7bfeff848) at main.c:255:3

Solution:
1. Check for recursion and log to stderr.
    - FUTURE: when "remote TUI" is merged, can we remove log_lock()?
2. Skip logging if log_init wasn't called yet.
justinmk added a commit to justinmk/neovim that referenced this pull request May 30, 2022
@justinmk
fix(logging): skip recursion, fix crash
29a5f0a 
Problem:
1. The main log routine does not protect itself against recursion.
   log_lock() doesn't guard against recursion, it would deadlock...
2. 22b52dd (neovim#11501) regressed 6f27f5e (neovim#10172), because
   set_init_1..process_spawn tries to log (see backtrace below), but the
   mutex isn't initalized yet. Even if the mutex were valid, we don't
   want early logging to fallback to stderr because that can break
   embedders when stdio is used as an RPC channel.

    frame 1: 0x00000001001d54f4 nvim`open_log_file at log.c:205:7
    frame 2: 0x00000001001d5390 nvim`logmsg(log_level=1, context="UI: ", func_name=0x0000000000000000, line_num=-1, eol=true, fmt="win_viewport") at log.c:150:20
    frame : 0x000000010039aea2 nvim`ui_call_win_viewport(grid=2, win=1000, topline=0, botline=1, curline=0, curcol=0, line_count=1) at ui_events_call.generated.h:321:3
    frame 4: 0x00000001003dfefc nvim`ui_ext_win_viewport(wp=0x0000000101816400) at window.c:939:5
    frame 5: 0x00000001003ec5b4 nvim`win_ui_flush at window.c:7303:7
    frame 6: 0x00000001003a04c0 nvim`ui_flush at ui.c:508:3
    frame 7: 0x00000001002966ba nvim`do_os_system(argv=0x0000600000c0c000, input=0x0000000000000000, len=0, output=0x0000000000000000, nread=0x00007ff7bfefe830, silent=false, forward_output=false) at shell.c:894:3
    frame 8: 0x0000000100295f68 nvim`os_call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_args=0x0000000000000000) at shell.c:663:18
    frame 9: 0x0000000100295845 nvim`call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_shell_arg=0x0000000000000000) at shell.c:712:14
    frame 10: 0x0000000100294c6f nvim`os_expand_wildcards(num_pat=1, pat=0x00007ff7bfefeb20, num_file=0x00007ff7bfefee58, file=0x00007ff7bfefee60, flags=43) at shell.c:328:7
    ...
    frame 23: 0x000000010028ccef nvim`expand_env_esc(srcp=",~foo", dst="~foo", dstlen=4094, esc=false, one=false, prefix=0x0000000000000000) at env.c:673:17
    frame 24: 0x000000010026fdd5 nvim`option_expand(opt_idx=29, val=",~foo") at option.c:1950:3
    frame 25: 0x000000010026f129 nvim`set_init_1(clean_arg=false) at option.c:558:19
    frame 26: 0x00000001001ea25e nvim`early_init(paramp=0x00007ff7bfeff5f0) at main.c:198:3
    frame 27: 0x00000001001ea6bf nvim`main(argc=1, argv=0x00007ff7bfeff848) at main.c:255:3

Solution:
1. Check for recursion and log to stderr.
    - FUTURE: when "remote TUI" is merged, can we remove log_lock()?
2. Skip logging if log_init wasn't called yet.
justinmk added a commit to justinmk/neovim that referenced this pull request May 30, 2022
@justinmk
fix(logging): skip recursion, fix crash
2356095 
Problem:
1. The main log routine does not protect itself against recursion.
   log_lock() doesn't guard against recursion, it would deadlock...
2. 22b52dd (neovim#11501) regressed 6f27f5e (neovim#10172), because
   set_init_1..process_spawn tries to log (see backtrace below), but the
   mutex isn't initalized yet. Even if the mutex were valid, we don't
   want early logging to fallback to stderr because that can break
   embedders when stdio is used as an RPC channel.

    frame 1: 0x00000001001d54f4 nvim`open_log_file at log.c:205:7
    frame 2: 0x00000001001d5390 nvim`logmsg(log_level=1, context="UI: ", func_name=0x0000000000000000, line_num=-1, eol=true, fmt="win_viewport") at log.c:150:20
    frame : 0x000000010039aea2 nvim`ui_call_win_viewport(grid=2, win=1000, topline=0, botline=1, curline=0, curcol=0, line_count=1) at ui_events_call.generated.h:321:3
    frame 4: 0x00000001003dfefc nvim`ui_ext_win_viewport(wp=0x0000000101816400) at window.c:939:5
    frame 5: 0x00000001003ec5b4 nvim`win_ui_flush at window.c:7303:7
    frame 6: 0x00000001003a04c0 nvim`ui_flush at ui.c:508:3
    frame 7: 0x00000001002966ba nvim`do_os_system(argv=0x0000600000c0c000, input=0x0000000000000000, len=0, output=0x0000000000000000, nread=0x00007ff7bfefe830, silent=false, forward_output=false) at shell.c:894:3
    frame 8: 0x0000000100295f68 nvim`os_call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_args=0x0000000000000000) at shell.c:663:18
    frame 9: 0x0000000100295845 nvim`call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_shell_arg=0x0000000000000000) at shell.c:712:14
    frame 10: 0x0000000100294c6f nvim`os_expand_wildcards(num_pat=1, pat=0x00007ff7bfefeb20, num_file=0x00007ff7bfefee58, file=0x00007ff7bfefee60, flags=43) at shell.c:328:7
    ...
    frame 23: 0x000000010028ccef nvim`expand_env_esc(srcp=",~foo", dst="~foo", dstlen=4094, esc=false, one=false, prefix=0x0000000000000000) at env.c:673:17
    frame 24: 0x000000010026fdd5 nvim`option_expand(opt_idx=29, val=",~foo") at option.c:1950:3
    frame 25: 0x000000010026f129 nvim`set_init_1(clean_arg=false) at option.c:558:19
    frame 26: 0x00000001001ea25e nvim`early_init(paramp=0x00007ff7bfeff5f0) at main.c:198:3
    frame 27: 0x00000001001ea6bf nvim`main(argc=1, argv=0x00007ff7bfeff848) at main.c:255:3

Solution:
1. Check for recursion and log to stderr.
    - FUTURE: when "remote TUI" is merged, can we remove log_lock()?
2. Skip logging if log_init wasn't called yet.
justinmk added a commit that referenced this pull request May 30, 2022
@justinmk
fix(logging): skip recursion, fix crash #18764
f6e19e7 
Problem:
1. The main log routine does not protect itself against recursion.
   log_lock() doesn't guard against recursion, it would deadlock...
2. 22b52dd (#11501) regressed 6f27f5e (#10172), because
   set_init_1..process_spawn tries to log (see backtrace below), but the
   mutex isn't initialized yet. Even if the mutex were valid, we don't
   want early logging to fallback to stderr because that can break
   embedders when stdio is used for RPC.

    frame 1: 0x00000001001d54f4 nvim`open_log_file at log.c:205:7
    frame 2: 0x00000001001d5390 nvim`logmsg(log_level=1, context="UI: ", func_name=0x0000000000000000, line_num=-1, eol=true, fmt="win_viewport") at log.c:150:20
    frame : 0x000000010039aea2 nvim`ui_call_win_viewport(grid=2, win=1000, topline=0, botline=1, curline=0, curcol=0, line_count=1) at ui_events_call.generated.h:321:3
    frame 4: 0x00000001003dfefc nvim`ui_ext_win_viewport(wp=0x0000000101816400) at window.c:939:5
    frame 5: 0x00000001003ec5b4 nvim`win_ui_flush at window.c:7303:7
    frame 6: 0x00000001003a04c0 nvim`ui_flush at ui.c:508:3
    frame 7: 0x00000001002966ba nvim`do_os_system(argv=0x0000600000c0c000, input=0x0000000000000000, len=0, output=0x0000000000000000, nread=0x00007ff7bfefe830, silent=false, forward_output=false) at shell.c:894:3
    frame 8: 0x0000000100295f68 nvim`os_call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_args=0x0000000000000000) at shell.c:663:18
    frame 9: 0x0000000100295845 nvim`call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_shell_arg=0x0000000000000000) at shell.c:712:14
    frame 10: 0x0000000100294c6f nvim`os_expand_wildcards(num_pat=1, pat=0x00007ff7bfefeb20, num_file=0x00007ff7bfefee58, file=0x00007ff7bfefee60, flags=43) at shell.c:328:7
    ...
    frame 23: 0x000000010028ccef nvim`expand_env_esc(srcp=",~foo", dst="~foo", dstlen=4094, esc=false, one=false, prefix=0x0000000000000000) at env.c:673:17
    frame 24: 0x000000010026fdd5 nvim`option_expand(opt_idx=29, val=",~foo") at option.c:1950:3
    frame 25: 0x000000010026f129 nvim`set_init_1(clean_arg=false) at option.c:558:19
    frame 26: 0x00000001001ea25e nvim`early_init(paramp=0x00007ff7bfeff5f0) at main.c:198:3
    frame 27: 0x00000001001ea6bf nvim`main(argc=1, argv=0x00007ff7bfeff848) at main.c:255:3

Solution:
1. Check for recursion, show "internal error" message.
    - FUTURE: when "remote TUI" is merged, can we remove log_lock()?
2. Skip logging if log_init wasn't called yet.
kraftwerk28 pushed a commit to kraftwerk28/neovim that referenced this pull request Jun 1, 2022
@justinmk @kraftwerk28
fix(logging): skip recursion, fix crash neovim#18764
1b129fc 
Problem:
1. The main log routine does not protect itself against recursion.
   log_lock() doesn't guard against recursion, it would deadlock...
2. 22b52dd (neovim#11501) regressed 6f27f5e (neovim#10172), because
   set_init_1..process_spawn tries to log (see backtrace below), but the
   mutex isn't initialized yet. Even if the mutex were valid, we don't
   want early logging to fallback to stderr because that can break
   embedders when stdio is used for RPC.

    frame 1: 0x00000001001d54f4 nvim`open_log_file at log.c:205:7
    frame 2: 0x00000001001d5390 nvim`logmsg(log_level=1, context="UI: ", func_name=0x0000000000000000, line_num=-1, eol=true, fmt="win_viewport") at log.c:150:20
    frame : 0x000000010039aea2 nvim`ui_call_win_viewport(grid=2, win=1000, topline=0, botline=1, curline=0, curcol=0, line_count=1) at ui_events_call.generated.h:321:3
    frame 4: 0x00000001003dfefc nvim`ui_ext_win_viewport(wp=0x0000000101816400) at window.c:939:5
    frame 5: 0x00000001003ec5b4 nvim`win_ui_flush at window.c:7303:7
    frame 6: 0x00000001003a04c0 nvim`ui_flush at ui.c:508:3
    frame 7: 0x00000001002966ba nvim`do_os_system(argv=0x0000600000c0c000, input=0x0000000000000000, len=0, output=0x0000000000000000, nread=0x00007ff7bfefe830, silent=false, forward_output=false) at shell.c:894:3
    frame 8: 0x0000000100295f68 nvim`os_call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_args=0x0000000000000000) at shell.c:663:18
    frame 9: 0x0000000100295845 nvim`call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_shell_arg=0x0000000000000000) at shell.c:712:14
    frame 10: 0x0000000100294c6f nvim`os_expand_wildcards(num_pat=1, pat=0x00007ff7bfefeb20, num_file=0x00007ff7bfefee58, file=0x00007ff7bfefee60, flags=43) at shell.c:328:7
    ...
    frame 23: 0x000000010028ccef nvim`expand_env_esc(srcp=",~foo", dst="~foo", dstlen=4094, esc=false, one=false, prefix=0x0000000000000000) at env.c:673:17
    frame 24: 0x000000010026fdd5 nvim`option_expand(opt_idx=29, val=",~foo") at option.c:1950:3
    frame 25: 0x000000010026f129 nvim`set_init_1(clean_arg=false) at option.c:558:19
    frame 26: 0x00000001001ea25e nvim`early_init(paramp=0x00007ff7bfeff5f0) at main.c:198:3
    frame 27: 0x00000001001ea6bf nvim`main(argc=1, argv=0x00007ff7bfeff848) at main.c:255:3

Solution:
1. Check for recursion, show "internal error" message.
    - FUTURE: when "remote TUI" is merged, can we remove log_lock()?
2. Skip logging if log_init wasn't called yet.
justinmk added a commit to justinmk/neovim that referenced this pull request Jun 8, 2022
@justinmk
refactor(log): simplify log_path_init
df1b7c4 
Problem:
Since 22b52dd neovim#11501, log_path_init is called in log_init, which
means it is now called at a deterministic time. So the "just in time"
complexity of log_path_init is no longer needed.

Solution:
Remove logic intended to try to "heal" partial initialization.
@justinmk justinmk mentioned this pull request Jun 8, 2022
Merged
justinmk added a commit to justinmk/neovim that referenced this pull request Jun 8, 2022
@justinmk
refactor(log): simplify log_path_init
a20fbc6 
Problem:
Since 22b52dd neovim#11501, log_path_init is called in log_init, so it is
now called at a deterministic time. So the "just in time" complexity of
log_path_init is no longer needed.

Solution:
Remove logic intended to try to "heal" partial initialization.
justinmk added a commit to justinmk/neovim that referenced this pull request Jun 8, 2022
@justinmk
refactor(log): simplify log_path_init
d0f976a 
Problem:
Since 22b52dd neovim#11501, log_path_init is called in log_init, so it is
now called at a deterministic time. So the "just in time" complexity of
log_path_init is no longer needed.

Solution:
Remove logic intended to try to "heal" partial initialization.
justinmk added a commit that referenced this pull request Jun 8, 2022
@justinmk
refactor(log): simplify log_path_init #18898
4d9e224 
Problem:
Since 22b52dd #11501, log_path_init is called in log_init, so it is
now called at a deterministic time. So the "just in time" complexity of
log_path_init is no longer needed.

Solution:
Remove logic intended to try to "heal" partial initialization.
kraftwerk28 pushed a commit to kraftwerk28/neovim that referenced this pull request Jul 6, 2022
@justinmk @kraftwerk28
refactor(log): simplify log_path_init neovim#18898
4e29b7b 
Problem:
Since 22b52dd neovim#11501, log_path_init is called in log_init, so it is
now called at a deterministic time. So the "just in time" complexity of
log_path_init is no longer needed.

Solution:
Remove logic intended to try to "heal" partial initialization.
smjonas pushed a commit to smjonas/neovim that referenced this pull request Dec 31, 2022
@justinmk @smjonas
refactor(log): simplify log_path_init neovim#18898
d4c4eac 
Problem:
Since 22b52dd neovim#11501, log_path_init is called in log_init, so it is
now called at a deterministic time. So the "just in time" complexity of
log_path_init is no longer needed.

Solution:
Remove logic intended to try to "heal" partial initialization.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@justinmk justinmk justinmk approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

Make $NVIM_LOG_FILE available earlier/always
2 participants
@blueyed @justinmk