# HG changeset patch # User Bram Moolenaar # Date 1649772903 -7200 # Node ID 0533e7466ef0c15c16d675d33936170eb7cfff8e # Parent dfef2e002d5b179f783797723a2c3feb18c4e37a patch 8.2.4742: there is no way to start logging very early in startup Commit: https://github.com/vim/vim/commit/c9a9a0ac1ec3b985d38c01ddf9f0ba2f15386f34 Author: Bram Moolenaar Date: Tue Apr 12 15:09:23 2022 +0100 patch 8.2.4742: there is no way to start logging very early in startup Problem: There is no way to start logging very early in startup. Solution: Add the --log argument. Include the date in the start message in the log file. Avoid a duplicate message when forking. Log an executed shell command. diff --git a/runtime/doc/channel.txt b/runtime/doc/channel.txt --- a/runtime/doc/channel.txt +++ b/runtime/doc/channel.txt @@ -633,8 +633,8 @@ ch_logfile({fname} [, {mode}]) *ch_l is going on in real time. To enable the log very early, to see what is received from a - terminal during startup, use |--cmd|: > - vim --cmd "call ch_logfile('logfile', 'w')" + terminal during startup, use |--log|: > + vim --log logfile < This function is not available in the |sandbox|. NOTE: the channel communication is stored in the file, be diff --git a/runtime/doc/starting.txt b/runtime/doc/starting.txt --- a/runtime/doc/starting.txt +++ b/runtime/doc/starting.txt @@ -344,6 +344,12 @@ a slash. Thus "-R" means recovery and " Example: > vim -V20vimlog foobar < +--log {filename} *--log* + Start logging and write entries to {filename}. + This works like calling `ch_logfile({filename}, 'a')` very + early during startup. + {only available with the +channel feature} + *-D* -D Debugging. Go to debugging mode when executing the first command from a script. |debug-mode| @@ -564,6 +570,7 @@ a slash. Thus "-R" means recovery and " {scriptout} cannot start with a digit. If you want to record what is typed in a human readable for you can use |ch_logfile()|, It adds "raw key input" lines. + Also see |--log|. *-W* -W {scriptout} Like -w, but do not append, overwrite an existing file. diff --git a/src/channel.c b/src/channel.c --- a/src/channel.c +++ b/src/channel.c @@ -178,7 +178,10 @@ ch_logfile(char_u *fname, char_u *opt) if (log_fd != NULL) { - fprintf(log_fd, "==== start log session ====\n"); + fprintf(log_fd, "==== start log session %s ====\n", + get_ctime(time(NULL), FALSE)); + // flush now, if fork/exec follows it could be written twice + fflush(log_fd); #ifdef FEAT_RELTIME profile_start(&log_start); #endif diff --git a/src/main.c b/src/main.c --- a/src/main.c +++ b/src/main.c @@ -138,15 +138,23 @@ main atexit(vim_mem_profile_dump); #endif -#ifdef STARTUPTIME - // Need to find "--startuptime" before actually parsing arguments. +#if defined(STARTUPTIME) || defined(FEAT_JOB_CHANNEL) + // Need to find "--startuptime" and "--log" before actually parsing + // arguments. for (i = 1; i < argc - 1; ++i) - if (STRICMP(argv[i], "--startuptime") == 0) + { +# ifdef STARTUPTIME + if (STRICMP(argv[i], "--startuptime") == 0 && time_fd == NULL) { time_fd = mch_fopen(argv[i + 1], "a"); TIME_MSG("--- VIM STARTING ---"); - break; } +# endif +# ifdef FEAT_JOB_CHANNEL + if (STRICMP(argv[i], "--log") == 0) + ch_logfile((char_u *)(argv[i + 1]), (char_u *)"a"); +# endif + } #endif starttime = time(NULL); @@ -1997,6 +2005,8 @@ command_line_scan(mparm_T *parmp) // "--version" give version message // "--clean" clean context // "--literal" take files literally + // "--startuptime fname" write timing info + // "--log fname" start logging early // "--nofork" don't fork // "--not-a-term" don't warn for not a term // "--ttyfail" exit if not a term @@ -2053,6 +2063,11 @@ command_line_scan(mparm_T *parmp) want_argument = TRUE; argv_idx += 11; } + else if (STRNICMP(argv[0] + argv_idx, "log", 3) == 0) + { + want_argument = TRUE; + argv_idx += 3; + } #ifdef FEAT_CLIENTSERVER else if (STRNICMP(argv[0] + argv_idx, "serverlist", 10) == 0) ; // already processed -- no arg @@ -2435,6 +2450,7 @@ command_line_scan(mparm_T *parmp) (char_u *)argv[0]; } // "--startuptime " already handled + // "--log " already handled break; // case 'd': -d {device} is handled in mch_check_win() for the @@ -3539,6 +3555,9 @@ usage(void) #ifdef STARTUPTIME main_msg(_("--startuptime \tWrite startup timing messages to ")); #endif +#ifdef FEAT_JOB_CHANNEL + main_msg(_("--log \tStart logging to early")); +#endif #ifdef FEAT_VIMINFO main_msg(_("-i \t\tUse instead of .viminfo")); #endif diff --git a/src/os_unix.c b/src/os_unix.c --- a/src/os_unix.c +++ b/src/os_unix.c @@ -5480,6 +5480,9 @@ mch_call_shell( char_u *cmd, int options) // SHELL_*, see vim.h { +#ifdef FEAT_JOB_CHANNEL + ch_log(NULL, "executing shell command: %s", cmd); +#endif #if defined(FEAT_GUI) && defined(FEAT_TERMINAL) if (gui.in_use && vim_strchr(p_go, GO_TERMINAL) != NULL) return mch_call_shell_terminal(cmd, options); diff --git a/src/os_win32.c b/src/os_win32.c --- a/src/os_win32.c +++ b/src/os_win32.c @@ -4767,6 +4767,9 @@ mch_call_shell( int tmode = cur_tmode; WCHAR szShellTitle[512]; +#ifdef FEAT_JOB_CHANNEL + ch_log(NULL, "executing shell command: %s", cmd); +#endif // Change the title to reflect that we are in a subshell. if (GetConsoleTitleW(szShellTitle, ARRAY_LENGTH(szShellTitle) - 4) > 0) { diff --git a/src/testdir/test_startup.vim b/src/testdir/test_startup.vim --- a/src/testdir/test_startup.vim +++ b/src/testdir/test_startup.vim @@ -726,6 +726,25 @@ func Test_startuptime() call delete('Xtestout') endfunc +func Test_log() + CheckFeature channel + + call assert_false(filereadable('Xlogfile')) + let after = ['qall'] + if RunVim([], after, '--log Xlogfile') + call assert_equal(1, readfile('Xlogfile') + \ ->filter({i, l -> l =~ '==== start log session'}) + \ ->len()) + " second time appends to the log + if RunVim([], after, '--log Xlogfile') + call assert_equal(2, readfile('Xlogfile') + \ ->filter({i, l -> l =~ '==== start log session'}) + \ ->len()) + endif + endif + call delete('Xlogfile') +endfunc + func Test_read_stdin() let after =<< trim [CODE] write Xtestout diff --git a/src/version.c b/src/version.c --- a/src/version.c +++ b/src/version.c @@ -747,6 +747,8 @@ static char *(features[]) = static int included_patches[] = { /* Add new patch number below this line */ /**/ + 4742, +/**/ 4741, /**/ 4740,