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.

runtime/doc/channel.txt

@@ -633,8 +633,8 @@ ch_logfile({fname} [, {mode}])					*ch_logfile()*
 		is going on in real time.
 
 		To enable the log very early, to see what is received from a
-		terminal during startup, use |--cmd|: >
+		terminal during startup, use |--log|: >
-			vim --cmd "call ch_logfile('logfile', 'w')"
+			vim --log logfile
 <
 		This function is not available in the |sandbox|.
 		NOTE: the channel communication is stored in the file, be

runtime/doc/starting.txt

@@ -344,6 +344,12 @@ a slash.  Thus "-R" means recovery and "-/R" readonly.
 		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 "-/R" readonly.
 		{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.

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

src/main.c

@@ -138,15 +138,23 @@ main
     atexit(vim_mem_profile_dump);
 #endif
 
-#ifdef STARTUPTIME
+#if defined(STARTUPTIME) || defined(FEAT_JOB_CHANNEL)
-    // Need to find "--startuptime" before actually parsing arguments.
+    // 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 <file>" already handled
+		    // "--log <file>" 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 <file>\tWrite startup timing messages to <file>"));
 #endif
+#ifdef FEAT_JOB_CHANNEL
+    main_msg(_("--log <file>\tStart logging to <file> early"));
+#endif
 #ifdef FEAT_VIMINFO
     main_msg(_("-i <viminfo>\t\tUse <viminfo> instead of .viminfo"));
 #endif

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);

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)
     {

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

src/version.c

@@ -746,6 +746,8 @@ static char *(features[]) =
 
 static int included_patches[] =
 {   /* Add new patch number below this line */
+/**/
+    4742,
 /**/
     4741,
 /**/