patch 9.0.0977: it is not easy to see what client-server commands are doing

Problem:    It is not easy to see what client-server commands are doing.
Solution:   Add channel log messages if ch_log() is available.  Move the
            channel logging and make it available with the +eval feature.

Filelist

@@ -88,10 +88,11 @@ SRC_ALL =	\
 		src/job.c \
 		src/json.c \
 		src/json_test.c \
+		src/keymap.h \
 		src/kword_test.c \
 		src/list.c \
 		src/locale.c \
-		src/keymap.h \
+		src/logfile.c \
 		src/macros.h \
 		src/main.c \
 		src/map.c \

runtime/doc/starting.txt

@@ -348,7 +348,7 @@ a slash.  Thus "-R" means recovery and "-/R" readonly.
 		Start logging and write entries to {filename}.
 		This works like calling `ch_logfile({filename}, 'ao')` very
 		early during startup.
-		{only available with the |+channel| feature}
+		{only available with the |+eval| feature}
 
 							*-D*
 -D		Debugging.  Go to debugging mode when executing the first

src/Make_ami.mak

@@ -124,6 +124,7 @@ SRC += \
 	json.c \
 	list.c \
 	locale.c \
+	logfile.c \
 	main.c \
 	mark.c \
 	map.c \

src/Make_cyg_ming.mak

@@ -800,6 +800,7 @@ OBJ = \
 	$(OUTDIR)/json.o \
 	$(OUTDIR)/list.o \
 	$(OUTDIR)/locale.o \
+	$(OUTDIR)/logfile.o \
 	$(OUTDIR)/main.o \
 	$(OUTDIR)/map.o \
 	$(OUTDIR)/mark.o \

src/Make_mvc.mak

@@ -685,6 +685,7 @@ OBJ = \
 	$(OUTDIR)\json.obj \
 	$(OUTDIR)\list.obj \
 	$(OUTDIR)\locale.obj \
+	$(OUTDIR)\logfile.obj \
 	$(OUTDIR)\main.obj \
 	$(OUTDIR)\map.obj \
 	$(OUTDIR)\mark.obj \
@@ -1586,6 +1587,8 @@ $(OUTDIR)/list.obj:	$(OUTDIR) list.c  $(INCL)
 
 $(OUTDIR)/locale.obj:	$(OUTDIR) locale.c  $(INCL)
 
+$(OUTDIR)/logfile.obj:	$(OUTDIR) logfile.c  $(INCL)
+
 $(OUTDIR)/main.obj:	$(OUTDIR) main.c  $(INCL) $(CUI_INCL)
 
 $(OUTDIR)/map.obj:	$(OUTDIR) map.c  $(INCL)
@@ -1862,6 +1865,7 @@ proto.h: \
 	proto/json.pro \
 	proto/list.pro \
 	proto/locale.pro \
+	proto/logfile.pro \
 	proto/main.pro \
 	proto/map.pro \
 	proto/mark.pro \

src/Make_vms.mms

@@ -357,6 +357,7 @@ SRC = \
 	json.c \
 	list.c \
 	locale.c \
+	logfile.c \
 	main.c \
 	map.c \
 	mark.c \
@@ -481,6 +482,7 @@ OBJ = \
 	json.obj \
 	list.obj \
 	locale.obj \
+	logfile.obj \
 	main.obj \
 	map.obj \
 	mark.obj \
@@ -928,6 +930,10 @@ locale.obj : locale.c vim.h [.auto]config.h feature.h os_unix.h \
  ascii.h keymap.h termdefs.h macros.h option.h structs.h regexp.h gui.h \
  beval.h [.proto]gui_beval.pro alloc.h ex_cmds.h spell.h proto.h \
  errors.h globals.h
+logfile.obj : logfile.c vim.h [.auto]config.h feature.h os_unix.h \
+ ascii.h keymap.h termdefs.h macros.h option.h structs.h regexp.h gui.h \
+ beval.h [.proto]gui_beval.pro alloc.h ex_cmds.h spell.h proto.h \
+ errors.h globals.h
 main.obj : main.c vim.h [.auto]config.h feature.h os_unix.h   \
  ascii.h keymap.h termdefs.h macros.h structs.h regexp.h gui.h beval.h \
  [.proto]gui_beval.pro option.h ex_cmds.h proto.h errors.h globals.h \

src/Makefile

@@ -1531,6 +1531,7 @@ BASIC_SRC = \
 	json.c \
 	list.c \
 	locale.c \
+	logfile.c \
 	main.c \
 	map.c \
 	mark.c \
@@ -1690,6 +1691,7 @@ OBJ_COMMON = \
 	objects/insexpand.o \
 	objects/list.o \
 	objects/locale.o \
+	objects/logfile.o \
 	objects/map.o \
 	objects/mark.o \
 	objects/match.o \
@@ -1874,6 +1876,7 @@ PRO_AUTO = \
 	json.pro \
 	list.pro \
 	locale.pro \
+	logfile.pro \
 	main.pro \
 	map.pro \
 	mark.pro \
@@ -3306,6 +3309,9 @@ objects/list.o: list.c
 objects/locale.o: locale.c
 	$(CCC) -o $@ locale.c
 
+objects/logfile.o: logfile.c
+	$(CCC) -o $@ logfile.c
+
 objects/main.o: main.c
 	$(CCC) -o $@ main.c
 
@@ -3897,6 +3903,11 @@ objects/locale.o: locale.c vim.h protodef.h auto/config.h feature.h os_unix.h \
  proto/gui_beval.pro structs.h regexp.h gui.h libvterm/include/vterm.h \
  libvterm/include/vterm_keycodes.h alloc.h ex_cmds.h spell.h proto.h \
  globals.h errors.h
+objects/logfile.o: logfile.c vim.h protodef.h auto/config.h feature.h os_unix.h \
+ auto/osdef.h ascii.h keymap.h termdefs.h macros.h option.h beval.h \
+ proto/gui_beval.pro structs.h regexp.h gui.h libvterm/include/vterm.h \
+ libvterm/include/vterm_keycodes.h alloc.h ex_cmds.h spell.h proto.h \
+ globals.h errors.h
 objects/main.o: main.c vim.h protodef.h auto/config.h feature.h os_unix.h \
  auto/osdef.h ascii.h keymap.h termdefs.h macros.h option.h beval.h \
  proto/gui_beval.pro structs.h regexp.h gui.h libvterm/include/vterm.h \

src/channel.c

@@ -81,8 +81,6 @@ static ch_part_T channel_part_read(channel_T *channel);
 // is safe to invoke callbacks.
 static int safe_to_invoke_callback = 0;
 
-static char *part_names[] = {"sock", "out", "err", "in"};
-
 #ifdef MSWIN
     static int
 fd_read(sock_T fd, char *buf, size_t len)
@@ -142,128 +140,6 @@ fd_close(sock_T fd)
 }
 #endif
 
-// Log file opened with ch_logfile().
-static FILE *log_fd = NULL;
-static char_u *log_name = NULL;
-#ifdef FEAT_RELTIME
-static proftime_T log_start;
-#endif
-
-    void
-ch_logfile(char_u *fname, char_u *opt)
-{
-    FILE	*file = NULL;
-    char	*mode = "a";
-
-    if (log_fd != NULL)
-    {
-	if (*fname != NUL)
-	    ch_log(NULL, "closing this logfile, opening %s", fname);
-	else
-	    ch_log(NULL, "closing logfile %s", log_name);
-	fclose(log_fd);
-    }
-
-    // The "a" flag overrules the "w" flag.
-    if (vim_strchr(opt, 'a') == NULL && vim_strchr(opt, 'w') != NULL)
-	mode = "w";
-    ch_log_output = vim_strchr(opt, 'o') != NULL ? LOG_ALWAYS : FALSE;
-
-    if (*fname != NUL)
-    {
-	file = fopen((char *)fname, mode);
-	if (file == NULL)
-	{
-	    semsg(_(e_cant_open_file_str), fname);
-	    return;
-	}
-	vim_free(log_name);
-	log_name = vim_strsave(fname);
-    }
-    log_fd = file;
-
-    if (log_fd != NULL)
-    {
-	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
-    }
-}
-
-    int
-ch_log_active(void)
-{
-    return log_fd != NULL;
-}
-
-    static void
-ch_log_lead(const char *what, channel_T *ch, ch_part_T part)
-{
-    if (log_fd == NULL)
-	return;
-
-#ifdef FEAT_RELTIME
-    proftime_T log_now;
-
-    profile_start(&log_now);
-    profile_sub(&log_now, &log_start);
-    fprintf(log_fd, "%s ", profile_msg(&log_now));
-#endif
-    if (ch != NULL)
-    {
-	if (part < PART_COUNT)
-	    fprintf(log_fd, "%son %d(%s): ",
-		    what, ch->ch_id, part_names[part]);
-	else
-	    fprintf(log_fd, "%son %d: ", what, ch->ch_id);
-    }
-    else
-	fprintf(log_fd, "%s: ", what);
-}
-
-#ifndef PROTO  // prototype is in proto.h
-    void
-ch_log(channel_T *ch, const char *fmt, ...)
-{
-    if (log_fd == NULL)
-	return;
-
-    va_list ap;
-
-    ch_log_lead("", ch, PART_COUNT);
-    va_start(ap, fmt);
-    vfprintf(log_fd, fmt, ap);
-    va_end(ap);
-    fputc('\n', log_fd);
-    fflush(log_fd);
-    did_repeated_msg = 0;
-}
-#endif
-
-    static void
-ch_error(channel_T *ch, const char *fmt, ...) ATTRIBUTE_FORMAT_PRINTF(2, 3);
-
-    static void
-ch_error(channel_T *ch, const char *fmt, ...)
-{
-    if (log_fd == NULL)
-	return;
-
-    va_list ap;
-
-    ch_log_lead("ERR ", ch, PART_COUNT);
-    va_start(ap, fmt);
-    vfprintf(log_fd, fmt, ap);
-    va_end(ap);
-    fputc('\n', log_fd);
-    fflush(log_fd);
-    did_repeated_msg = 0;
-}
-
 #ifdef MSWIN
 # undef PERROR
 # define PERROR(msg) (void)semsg("%s: %s", msg, strerror_win32(errno))
@@ -620,7 +496,7 @@ channel_gui_register_one(channel_T *channel, ch_part_T part UNUSED)
     if (channel->ch_part[part].ch_inputHandler == (XtInputId)NULL)
     {
 	ch_log(channel, "Registering part %s with fd %d",
-		part_names[part], channel->ch_part[part].ch_fd);
+		ch_part_names[part], channel->ch_part[part].ch_fd);
 
 	channel->ch_part[part].ch_inputHandler = XtAppAddInput(
 		(XtAppContext)app_context,
@@ -636,7 +512,7 @@ channel_gui_register_one(channel_T *channel, ch_part_T part UNUSED)
     if (channel->ch_part[part].ch_inputHandler == 0)
     {
 	ch_log(channel, "Registering part %s with fd %d",
-		part_names[part], channel->ch_part[part].ch_fd);
+		ch_part_names[part], channel->ch_part[part].ch_fd);
 #   if GTK_CHECK_VERSION(3,0,0)
 	GIOChannel *chnnl = g_io_channel_unix_new(
 		(gint)channel->ch_part[part].ch_fd);
@@ -694,7 +570,7 @@ channel_gui_unregister_one(channel_T *channel UNUSED, ch_part_T part UNUSED)
 # ifdef FEAT_GUI_X11
     if (channel->ch_part[part].ch_inputHandler != (XtInputId)NULL)
     {
-	ch_log(channel, "Unregistering part %s", part_names[part]);
+	ch_log(channel, "Unregistering part %s", ch_part_names[part]);
 	XtRemoveInput(channel->ch_part[part].ch_inputHandler);
 	channel->ch_part[part].ch_inputHandler = (XtInputId)NULL;
     }
@@ -702,7 +578,7 @@ channel_gui_unregister_one(channel_T *channel UNUSED, ch_part_T part UNUSED)
 #  ifdef FEAT_GUI_GTK
     if (channel->ch_part[part].ch_inputHandler != 0)
     {
-	ch_log(channel, "Unregistering part %s", part_names[part]);
+	ch_log(channel, "Unregistering part %s", ch_part_names[part]);
 #   if GTK_CHECK_VERSION(3,0,0)
 	g_source_remove(channel->ch_part[part].ch_inputHandler);
 #   else
@@ -1786,7 +1662,7 @@ channel_buffer_free(buf_T *buf)
 	    if (ch_part->ch_bufref.br_buf == buf)
 	    {
 		ch_log(channel, "%s buffer has been wiped out",
-							    part_names[part]);
+							  ch_part_names[part]);
 		ch_part->ch_bufref.br_buf = NULL;
 	    }
 	}
@@ -2165,12 +2041,8 @@ channel_save(channel_T *channel, ch_part_T part, char_u *buf, int len,
     }
 
     if (ch_log_active() && lead != NULL)
-    {
+	ch_log_literal(lead, channel, part, buf, len);
-	ch_log_lead(lead, channel, part);
+
-	fprintf(log_fd, "'");
-	vim_ignored = (int)fwrite(buf, len, 1, log_fd);
-	fprintf(log_fd, "'\n");
-    }
     return OK;
 }
 
@@ -3018,7 +2890,7 @@ may_invoke_callback(channel_T *channel, ch_part_T part)
 					       || buffer->b_ml.ml_mfp == NULL))
     {
 	// buffer was wiped out or unloaded
-	ch_log(channel, "%s buffer has been wiped out", part_names[part]);
+	ch_log(channel, "%s buffer has been wiped out", ch_part_names[part]);
 	ch_part->ch_bufref.br_buf = NULL;
 	buffer = NULL;
     }
@@ -3458,7 +3330,7 @@ channel_close(channel_T *channel, int invoke_close_cb)
 		++channel->ch_refcount;
 		if (channel->ch_close_cb.cb_name == NULL)
 		    ch_log(channel, "flushing %s buffers before closing",
-							     part_names[part]);
+							  ch_part_names[part]);
 		while (may_invoke_callback(channel, part))
 		    ;
 		--channel->ch_refcount;
@@ -3860,7 +3732,7 @@ channel_read(channel_T *channel, ch_part_T part, char *func)
     if (fd == INVALID_FD)
     {
 	ch_error(channel, "channel_read() called while %s part is closed",
-							    part_names[part]);
+							  ch_part_names[part]);
 	return;
     }
     use_socket = fd == channel->CH_SOCK_FD;
@@ -4129,7 +4001,7 @@ channel_read_json_block(
  * When "reading" is TRUE "check_open" considers typeahead useful.
  * "part" is used to check typeahead, when PART_COUNT use the default part.
  */
-    static channel_T *
+    channel_T *
 get_channel_arg(typval_T *tv, int check_open, int reading, ch_part_T part)
 {
     channel_T	*channel = NULL;
@@ -4375,11 +4247,7 @@ channel_send(
 
     if (ch_log_active())
     {
-	ch_log_lead("SEND ", channel, part);
+	ch_log_literal("SEND ", channel, part, buf_arg, len_arg);
-	fprintf(log_fd, "'");
-	vim_ignored = (int)fwrite(buf_arg, len_arg, 1, log_fd);
-	fprintf(log_fd, "'\n");
-	fflush(log_fd);
 	did_repeated_msg = 0;
     }
 
@@ -5292,52 +5160,6 @@ f_ch_info(typval_T *argvars, typval_T *rettv UNUSED)
 	channel_info(channel, rettv->vval.v_dict);
 }
 
-/*
- * "ch_log()" function
- */
-    void
-f_ch_log(typval_T *argvars, typval_T *rettv UNUSED)
-{
-    char_u	*msg;
-    channel_T	*channel = NULL;
-
-    if (in_vim9script()
-	    && (check_for_string_arg(argvars, 0) == FAIL
-		|| check_for_opt_chan_or_job_arg(argvars, 1) == FAIL))
-	return;
-
-    msg = tv_get_string(&argvars[0]);
-    if (argvars[1].v_type != VAR_UNKNOWN)
-	channel = get_channel_arg(&argvars[1], FALSE, FALSE, 0);
-
-    ch_log(channel, "%s", msg);
-}
-
-/*
- * "ch_logfile()" function
- */
-    void
-f_ch_logfile(typval_T *argvars, typval_T *rettv UNUSED)
-{
-    char_u *fname;
-    char_u *opt = (char_u *)"";
-    char_u buf[NUMBUFLEN];
-
-    // Don't open a file in restricted mode.
-    if (check_restricted() || check_secure())
-	return;
-
-    if (in_vim9script()
-	    && (check_for_string_arg(argvars, 0) == FAIL
-		|| check_for_opt_string_arg(argvars, 1) == FAIL))
-	return;
-
-    fname = tv_get_string(&argvars[0]);
-    if (argvars[1].v_type == VAR_STRING)
-	opt = tv_get_string_buf(&argvars[1], buf);
-    ch_logfile(fname, opt);
-}
-
 /*
  * "ch_open()" function
  */

src/clientserver.c

@@ -70,6 +70,10 @@ eval_client_expr_to_string(char_u *expr)
     funccal_entry_T funccal_entry;
     int		did_save_funccal = FALSE;
 
+#if defined(FEAT_EVAL)
+    ch_log(NULL, "eval_client_expr_to_string(\"%s\")", expr);
+#endif
+
     // Evaluate the expression at the toplevel, don't use variables local to
     // the calling function. Except when in debug mode.
     if (!debug_mode)

src/evalfunc.c

@@ -1750,9 +1750,9 @@ static funcentry_T global_functions[] =
     {"ch_info",		1, 1, FEARG_1,	    arg1_chan_or_job,
 			ret_dict_any,	    JOB_FUNC(f_ch_info)},
     {"ch_log",		1, 2, FEARG_1,	    arg2_string_chan_or_job,
-			ret_void,	    JOB_FUNC(f_ch_log)},
+			ret_void,	    f_ch_log},
     {"ch_logfile",	1, 2, FEARG_1,	    arg2_string,
-			ret_void,	    JOB_FUNC(f_ch_logfile)},
+			ret_void,	    f_ch_logfile},
     {"ch_open",		1, 2, FEARG_1,	    arg2_string_dict,
 			ret_channel,	    JOB_FUNC(f_ch_open)},
     {"ch_read",		1, 2, FEARG_1,	    arg2_chan_or_job_dict,

src/globals.h

@@ -20,12 +20,12 @@
 EXTERN long	Rows			// nr of rows in the screen
 #ifdef DO_INIT
 # if defined(MSWIN)
-			    = 25L
+		    = 25L
 # else
-			    = 24L
+		    = 24L
 # endif
 #endif
-			    ;
+		    ;
 EXTERN long	Columns INIT(= 80);	// nr of columns in the screen
 
 /*
@@ -1218,9 +1218,9 @@ EXTERN int	old_indent INIT(= 0);	// for ^^D command in insert mode
 
 EXTERN pos_T	saved_cursor		// w_cursor before formatting text.
 #ifdef DO_INIT
-	= {0, 0, 0}
+		    = {0, 0, 0}
 #endif
-	;
+		    ;
 
 /*
  * Stuff for insert mode.
@@ -1589,9 +1589,9 @@ EXTERN char_u	*autocmd_match INIT(= NULL); // name for <amatch> on cmdline
 EXTERN int	did_cursorhold INIT(= FALSE); // set when CursorHold t'gerd
 EXTERN pos_T	last_cursormoved	      // for CursorMoved event
 # ifdef DO_INIT
-			= {0, 0, 0}
+		    = {0, 0, 0}
 # endif
-			;
+		    ;
 
 EXTERN int	postponed_split INIT(= 0);  // for CTRL-W CTRL-] command
 EXTERN int	postponed_split_flags INIT(= 0);  // args for win_split()
@@ -1751,25 +1751,24 @@ extern cursorentry_T shape_table[SHAPE_IDX_COUNT];
 
 EXTERN option_table_T printer_opts[OPT_PRINT_NUM_OPTIONS]
 # ifdef DO_INIT
- =
+    = {
-{
+	{"top",	TRUE, 0, NULL, 0, FALSE},
-    {"top",	TRUE, 0, NULL, 0, FALSE},
+	{"bottom",	TRUE, 0, NULL, 0, FALSE},
-    {"bottom",	TRUE, 0, NULL, 0, FALSE},
+	{"left",	TRUE, 0, NULL, 0, FALSE},
-    {"left",	TRUE, 0, NULL, 0, FALSE},
+	{"right",	TRUE, 0, NULL, 0, FALSE},
-    {"right",	TRUE, 0, NULL, 0, FALSE},
+	{"header",	TRUE, 0, NULL, 0, FALSE},
-    {"header",	TRUE, 0, NULL, 0, FALSE},
+	{"syntax",	FALSE, 0, NULL, 0, FALSE},
-    {"syntax",	FALSE, 0, NULL, 0, FALSE},
+	{"number",	FALSE, 0, NULL, 0, FALSE},
-    {"number",	FALSE, 0, NULL, 0, FALSE},
+	{"wrap",	FALSE, 0, NULL, 0, FALSE},
-    {"wrap",	FALSE, 0, NULL, 0, FALSE},
+	{"duplex",	FALSE, 0, NULL, 0, FALSE},
-    {"duplex",	FALSE, 0, NULL, 0, FALSE},
+	{"portrait", FALSE, 0, NULL, 0, FALSE},
-    {"portrait", FALSE, 0, NULL, 0, FALSE},
+	{"paper",	FALSE, 0, NULL, 0, FALSE},
-    {"paper",	FALSE, 0, NULL, 0, FALSE},
+	{"collate",	FALSE, 0, NULL, 0, FALSE},
-    {"collate",	FALSE, 0, NULL, 0, FALSE},
+	{"jobsplit", FALSE, 0, NULL, 0, FALSE},
-    {"jobsplit", FALSE, 0, NULL, 0, FALSE},
+	{"formfeed", FALSE, 0, NULL, 0, FALSE},
-    {"formfeed", FALSE, 0, NULL, 0, FALSE},
+    }
-}
 # endif
-;
+    ;
 
 // For prt_get_unit().
 # define PRT_UNIT_NONE	-1
@@ -1871,9 +1870,9 @@ EXTERN int		need_cursor_line_redraw INIT(= FALSE);
 // Grow array to collect error messages in until they can be displayed.
 EXTERN garray_T error_ga
 # ifdef DO_INIT
-	= {0, 0, 0, 0, NULL}
+		    = {0, 0, 0, 0, NULL}
 # endif
-	;
+		    ;
 #endif
 
 #ifdef FEAT_NETBEANS_INTG
@@ -1991,7 +1990,14 @@ EXTERN int ctrl_break_was_pressed INIT(= FALSE);
 EXTERN HINSTANCE g_hinst INIT(= NULL);
 #endif
 
+
 #if defined(FEAT_JOB_CHANNEL)
+EXTERN char *ch_part_names[]
+# ifdef DO_INIT
+		= {"sock", "out", "err", "in"}
+# endif
+		;
+
 EXTERN int did_repeated_msg INIT(= 0);
 # define REPEATED_MSG_LOOKING	    1
 # define REPEATED_MSG_SAFESTATE	    2

src/gui_gtk_x11.c

@@ -407,7 +407,7 @@ static int using_gnome = 0;
  * See https://github.com/vim/vim/issues/10123
  */
 # if 0  // Change to 1 to enable ch_log() calls for debugging.
-#  ifdef FEAT_JOB_CHANNEL
+#  ifdef FEAT_EVAL
 #   define ENABLE_RESIZE_HISTORY_LOG
 #  endif
 # endif

src/if_xcmdsrv.c

@@ -388,11 +388,12 @@ serverSendToVim(
     if (name == NULL || *name == NUL)
 	name = (char_u *)"GVIM";    // use a default name
 
-    if (commProperty == None && dpy != NULL)
+    if (commProperty == None && dpy != NULL && SendInit(dpy) < 0)
-    {
+	return -1;
-	if (SendInit(dpy) < 0)
+
-	    return -1;
+#if defined(FEAT_EVAL)
-    }
+    ch_log(NULL, "serverSendToVim(%s, %s)", name, cmd);
+#endif
 
     // Execute locally if no display or target is ourselves
     if (dpy == NULL || (serverName != NULL && STRICMP(name, serverName) == 0))
@@ -494,6 +495,11 @@ serverSendToVim(
 		break;
 	    }
     }
+
+#if defined(FEAT_EVAL)
+    ch_log(NULL, "serverSendToVim() result: %s",
+	    pending.result == NULL ? "NULL" : (char *)pending.result);
+#endif
     if (result != NULL)
 	*result = pending.result;
     else
@@ -1221,6 +1227,10 @@ server_parse_message(
     int		code;
     char_u	*tofree;
 
+#if defined(FEAT_EVAL)
+    ch_log(NULL, "server_parse_message() numItems: %ld", numItems);
+#endif
+
     /*
      * Several commands and results could arrive in the property at
      * one time;  each iteration through the outer loop handles a
@@ -1240,7 +1250,7 @@ server_parse_message(
 	    continue;
 	}
 
-	if ((*p == 'c' || *p == 'k') && (p[1] == 0))
+	if ((*p == 'c' || *p == 'k') && p[1] == 0)
 	{
 	    Window	resWindow;
 	    char_u	*name, *script, *serial, *end;
@@ -1261,6 +1271,9 @@ server_parse_message(
 	    enc = NULL;
 	    while ((long_u)(p - propInfo) < numItems && *p == '-')
 	    {
+#if defined(FEAT_EVAL)
+		ch_log(NULL, "server_parse_message() item: %c, %s", p[-2], p);
+#endif
 		switch (p[1])
 		{
 		    case 'r':
@@ -1326,7 +1339,8 @@ server_parse_message(
 			    ga_concat(&reply, res);
 			else
 			{
-			    ga_concat(&reply, (char_u *)_(e_invalid_expression_received));
+			    ga_concat(&reply,
+				   (char_u *)_(e_invalid_expression_received));
 			    ga_append(&reply, 0);
 			    ga_concat(&reply, (char_u *)"-c 1");
 			}

src/logfile.c

@@ -0,0 +1,208 @@
+/* vi:set ts=8 sts=4 sw=4 noet:
+ *
+ * VIM - Vi IMproved	by Bram Moolenaar
+ *
+ * Do ":help uganda"  in Vim to read copying and usage conditions.
+ * Do ":help credits" in Vim to see a list of people who contributed.
+ */
+
+/*
+ * Implements logging.  Originally intended for the channel feature, which is
+ * why the "ch_" prefix is used.  Also useful for any kind of low-level and
+ * async debuging.
+ */
+
+#include "vim.h"
+
+#if defined(FEAT_EVAL) || defined(PROTO)
+
+// Log file opened with ch_logfile().
+static FILE *log_fd = NULL;
+static char_u *log_name = NULL;
+#ifdef FEAT_RELTIME
+static proftime_T log_start;
+#endif
+
+    void
+ch_logfile(char_u *fname, char_u *opt)
+{
+    FILE	*file = NULL;
+    char	*mode = "a";
+
+    if (log_fd != NULL)
+    {
+	if (*fname != NUL)
+	    ch_log(NULL, "closing this logfile, opening %s", fname);
+	else
+	    ch_log(NULL, "closing logfile %s", log_name);
+	fclose(log_fd);
+    }
+
+    // The "a" flag overrules the "w" flag.
+    if (vim_strchr(opt, 'a') == NULL && vim_strchr(opt, 'w') != NULL)
+	mode = "w";
+    ch_log_output = vim_strchr(opt, 'o') != NULL ? LOG_ALWAYS : FALSE;
+
+    if (*fname != NUL)
+    {
+	file = fopen((char *)fname, mode);
+	if (file == NULL)
+	{
+	    semsg(_(e_cant_open_file_str), fname);
+	    return;
+	}
+	vim_free(log_name);
+	log_name = vim_strsave(fname);
+    }
+    log_fd = file;
+
+    if (log_fd != NULL)
+    {
+	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
+    }
+}
+
+    int
+ch_log_active(void)
+{
+    return log_fd != NULL;
+}
+
+    static void
+ch_log_lead(const char *what, channel_T *ch, ch_part_T part)
+{
+    if (log_fd == NULL)
+	return;
+
+#ifdef FEAT_RELTIME
+    proftime_T log_now;
+
+    profile_start(&log_now);
+    profile_sub(&log_now, &log_start);
+    fprintf(log_fd, "%s ", profile_msg(&log_now));
+#endif
+#ifdef FEAT_JOB_CHANNEL
+    if (ch != NULL)
+    {
+	if (part < PART_COUNT)
+	    fprintf(log_fd, "%son %d(%s): ", what, ch->ch_id, ch_part_names[part]);
+	else
+	    fprintf(log_fd, "%son %d: ", what, ch->ch_id);
+    }
+    else
+#endif
+	fprintf(log_fd, "%s: ", what);
+}
+
+#ifndef PROTO  // prototype is in proto.h
+    void
+ch_log(channel_T *ch, const char *fmt, ...)
+{
+    if (log_fd == NULL)
+	return;
+
+    va_list ap;
+
+    ch_log_lead("", ch, PART_COUNT);
+    va_start(ap, fmt);
+    vfprintf(log_fd, fmt, ap);
+    va_end(ap);
+    fputc('\n', log_fd);
+    fflush(log_fd);
+    did_repeated_msg = 0;
+}
+
+    void
+ch_error(channel_T *ch, const char *fmt, ...)
+{
+    if (log_fd == NULL)
+	return;
+
+    va_list ap;
+
+    ch_log_lead("ERR ", ch, PART_COUNT);
+    va_start(ap, fmt);
+    vfprintf(log_fd, fmt, ap);
+    va_end(ap);
+    fputc('\n', log_fd);
+    fflush(log_fd);
+    did_repeated_msg = 0;
+}
+#endif
+
+#if defined(FEAT_JOB_CHANNEL) || defined(PROTO)
+/*
+ * Log a message "buf[len]" for channel "ch" part "part".
+ * Only to be called when ch_log_active() returns TRUE.
+ */
+    void
+ch_log_literal(
+	char	    *lead,
+	channel_T   *ch,
+	ch_part_T   part,
+	char_u	    *buf,
+	int	    len)
+{
+    ch_log_lead(lead, ch, part);
+    fprintf(log_fd, "'");
+    vim_ignored = (int)fwrite(buf, len, 1, log_fd);
+    fprintf(log_fd, "'\n");
+    fflush(log_fd);
+}
+#endif
+
+/*
+ * "ch_log()" function
+ */
+    void
+f_ch_log(typval_T *argvars, typval_T *rettv UNUSED)
+{
+    char_u	*msg;
+    channel_T	*channel = NULL;
+
+    if (in_vim9script()
+	    && (check_for_string_arg(argvars, 0) == FAIL
+		|| check_for_opt_chan_or_job_arg(argvars, 1) == FAIL))
+	return;
+
+    msg = tv_get_string(&argvars[0]);
+#if defined(FEAT_JOB_CHANNEL)
+    if (argvars[1].v_type != VAR_UNKNOWN)
+	channel = get_channel_arg(&argvars[1], FALSE, FALSE, 0);
+#endif
+
+    ch_log(channel, "%s", msg);
+}
+
+/*
+ * "ch_logfile()" function
+ */
+    void
+f_ch_logfile(typval_T *argvars, typval_T *rettv UNUSED)
+{
+    char_u *fname;
+    char_u *opt = (char_u *)"";
+    char_u buf[NUMBUFLEN];
+
+    // Don't open a file in restricted mode.
+    if (check_restricted() || check_secure())
+	return;
+
+    if (in_vim9script()
+	    && (check_for_string_arg(argvars, 0) == FAIL
+		|| check_for_opt_string_arg(argvars, 1) == FAIL))
+	return;
+
+    fname = tv_get_string(&argvars[0]);
+    if (argvars[1].v_type == VAR_STRING)
+	opt = tv_get_string_buf(&argvars[1], buf);
+    ch_logfile(fname, opt);
+}
+
+#endif // FEAT_EVAL

src/main.c

@@ -152,7 +152,7 @@ main
 	    TIME_MSG("--- VIM STARTING ---");
 	}
 # endif
-# ifdef FEAT_JOB_CHANNEL
+# ifdef FEAT_EVAL
 	if (STRICMP(argv[i], "--log") == 0)
 	    ch_logfile((char_u *)(argv[i + 1]), (char_u *)"ao");
 # endif
@@ -1084,7 +1084,7 @@ may_trigger_safestate(int safe)
 {
     int is_safe = safe && is_safe_now();
 
-#ifdef FEAT_JOB_CHANNEL
+#ifdef FEAT_EVAL
     if (was_safe != is_safe)
 	// Only log when the state changes, otherwise it happens at nearly
 	// every key stroke.
@@ -1104,7 +1104,7 @@ may_trigger_safestate(int safe)
     void
 state_no_longer_safe(char *reason UNUSED)
 {
-#ifdef FEAT_JOB_CHANNEL
+#ifdef FEAT_EVAL
     if (was_safe)
 	ch_log(NULL, "SafeState: reset: %s", reason);
 #endif
@@ -1133,14 +1133,14 @@ may_trigger_safestateagain(void)
 	// of calling feedkeys(), we check if it's now safe again (all keys
 	// were consumed).
 	was_safe = is_safe_now();
-#ifdef FEAT_JOB_CHANNEL
+#ifdef FEAT_EVAL
 	if (was_safe)
 	    ch_log(NULL, "SafeState: undo reset");
 #endif
     }
     if (was_safe)
     {
-#ifdef FEAT_JOB_CHANNEL
+#ifdef FEAT_EVAL
 	// Only do this message when another message was given, otherwise we
 	// get lots of them.
 	if ((did_repeated_msg & REPEATED_MSG_SAFESTATE) == 0)
@@ -1154,7 +1154,7 @@ may_trigger_safestateagain(void)
 #endif
 	apply_autocmds(EVENT_SAFESTATEAGAIN, NULL, NULL, FALSE, curbuf);
     }
-#ifdef FEAT_JOB_CHANNEL
+#ifdef FEAT_EVAL
     else
 	ch_log(NULL,
 		  "SafeState: back to waiting, not triggering SafeStateAgain");
@@ -1563,7 +1563,7 @@ getout_preserve_modified(int exitval)
 getout(int exitval)
 {
     exiting = TRUE;
-#if defined(FEAT_JOB_CHANNEL)
+#if defined(FEAT_EVAL)
     ch_log(NULL, "Exiting...");
 #endif
 

src/message.c

@@ -161,7 +161,7 @@ msg_attr_keep(
 		&& STRCMP(s, last_msg_hist->msg)))
 	add_msg_hist((char_u *)s, -1, attr);
 
-#ifdef FEAT_JOB_CHANNEL
+#ifdef FEAT_EVAL
     if (emsg_to_channel_log)
 	// Write message in the channel log.
 	ch_log(NULL, "ERROR: %s", s);
@@ -725,7 +725,7 @@ emsg_core(char_u *s)
 	    if (emsg_silent == emsg_silent_def)
 		++did_emsg_def;
 #endif
-#ifdef FEAT_JOB_CHANNEL
+#ifdef FEAT_EVAL
 	    ch_log(NULL, "ERROR silent: %s", (char *)s);
 #endif
 	    return TRUE;

src/os_unix.c

@@ -4747,7 +4747,7 @@ mch_call_shell_fork(
 	    reset_signals();		// handle signals normally
 	    UNBLOCK_SIGNALS(&curset);
 
-# ifdef FEAT_JOB_CHANNEL
+# ifdef FEAT_EVAL
 	    if (ch_log_active())
 	    {
 		ch_log(NULL, "closing channel log in the child process");
@@ -5465,7 +5465,7 @@ mch_call_shell(
     char_u	*cmd,
     int		options)	// SHELL_*, see vim.h
 {
-#ifdef FEAT_JOB_CHANNEL
+#ifdef FEAT_EVAL
     ch_log(NULL, "executing shell command: %s", cmd);
 #endif
 #if defined(FEAT_GUI) && defined(FEAT_TERMINAL)
@@ -5597,7 +5597,7 @@ mch_job_start(char **argv, job_T *job, jobopt_T *options, int is_terminal)
 	reset_signals();		// handle signals normally
 	UNBLOCK_SIGNALS(&curset);
 
-# ifdef FEAT_JOB_CHANNEL
+# ifdef FEAT_EVAL
 	if (ch_log_active())
 	    // close the log file in the child
 	    ch_logfile((char_u *)"", (char_u *)"");
@@ -8324,7 +8324,7 @@ start_timeout(long msec)
 	timer_created = TRUE;
     }
 
-# ifdef FEAT_JOB_CHANNEL
+# ifdef FEAT_EVAL
     ch_log(NULL, "setting timeout timer to %d sec %ld nsec",
 	       (int)interval.it_value.tv_sec, (long)interval.it_value.tv_nsec);
 # endif

src/os_win32.c

@@ -2222,7 +2222,7 @@ theend:
 	buf[len++] = typeahead[0];
 	mch_memmove(typeahead, typeahead + 1, --typeaheadlen);
     }
-# ifdef FEAT_JOB_CHANNEL
+# ifdef FEAT_EVAL
     if (len > 0)
     {
 	buf[len] = NUL;
@@ -4923,7 +4923,7 @@ mch_call_shell(
     int		tmode = cur_tmode;
     WCHAR	szShellTitle[512];
 
-#ifdef FEAT_JOB_CHANNEL
+#ifdef FEAT_EVAL
     ch_log(NULL, "executing shell command: %s", cmd);
 #endif
     // Change the title to reflect that we are in a subshell.

src/proto.h

@@ -104,6 +104,7 @@ extern int _stricoll(char *a, char *b);
 # include "json.pro"
 # include "list.pro"
 # include "locale.pro"
+# include "logfile.pro"
 # include "blob.pro"
 # include "main.pro"
 # include "map.pro"
@@ -263,8 +264,9 @@ void mbyte_im_set_active(int active_arg);
 #  include "job.pro"
 #  include "channel.pro"
 
-// Not generated automatically, to add extra attribute.
+// Not generated automatically so that we can add an extra attribute.
 void ch_log(channel_T *ch, const char *fmt, ...) ATTRIBUTE_FORMAT_PRINTF(2, 3);
+void ch_error(channel_T *ch, const char *fmt, ...) ATTRIBUTE_FORMAT_PRINTF(2, 3);
 
 # endif
 

src/proto/channel.pro

@@ -1,6 +1,4 @@
 /* channel.c */
-void ch_logfile(char_u *fname, char_u *opt);
-int ch_log_active(void);
 channel_T *add_channel(void);
 int has_any_channel(void);
 int channel_still_useful(channel_T *channel);
@@ -28,6 +26,7 @@ void channel_close(channel_T *channel, int invoke_close_cb);
 void channel_clear(channel_T *channel);
 void channel_free_all(void);
 int channel_in_blocking_wait(void);
+channel_T *get_channel_arg(typval_T *tv, int check_open, int reading, ch_part_T part);
 void channel_handle_events(int only_keep_open);
 int channel_any_keep_open(void);
 void channel_set_nonblock(channel_T *channel, ch_part_T part);
@@ -45,8 +44,6 @@ void f_ch_close_in(typval_T *argvars, typval_T *rettv);
 void f_ch_getbufnr(typval_T *argvars, typval_T *rettv);
 void f_ch_getjob(typval_T *argvars, typval_T *rettv);
 void f_ch_info(typval_T *argvars, typval_T *rettv);
-void f_ch_log(typval_T *argvars, typval_T *rettv);
-void f_ch_logfile(typval_T *argvars, typval_T *rettv);
 void f_ch_open(typval_T *argvars, typval_T *rettv);
 void f_ch_read(typval_T *argvars, typval_T *rettv);
 void f_ch_readblob(typval_T *argvars, typval_T *rettv);

src/proto/logfile.pro

@@ -0,0 +1,7 @@
+/* logfile.c */
+void ch_logfile(char_u *fname, char_u *opt);
+int ch_log_active(void);
+void ch_log_literal(char *lead, channel_T *ch, ch_part_T part, char_u *buf, int len);
+void f_ch_log(typval_T *argvars, typval_T *rettv);
+void f_ch_logfile(typval_T *argvars, typval_T *rettv);
+/* vim: set ft=c : */

src/regexp_bt.c

@@ -3163,7 +3163,7 @@ bt_did_time_out(int *timed_out)
     {
 	if (timed_out != NULL)
 	{
-# ifdef FEAT_JOB_CHANNEL
+# ifdef FEAT_EVAL
 	    if (!*timed_out)
 		ch_log(NULL, "BT regexp timed out");
 # endif

src/regexp_nfa.c

@@ -4250,7 +4250,7 @@ nfa_did_time_out(void)
     {
 	if (nfa_timed_out != NULL)
 	{
-# ifdef FEAT_JOB_CHANNEL
+# ifdef FEAT_EVAL
 	    if (!*nfa_timed_out)
 		ch_log(NULL, "NFA regexp timed out");
 # endif

src/term.c

@@ -2641,7 +2641,7 @@ out_flush(void)
 	len = out_pos;
 	out_pos = 0;
 	ui_write(out_buf, len, FALSE);
-#ifdef FEAT_JOB_CHANNEL
+#ifdef FEAT_EVAL
 	if (ch_log_output != FALSE)
 	{
 	    out_buf[len] = NUL;

src/time.c

@@ -491,7 +491,7 @@ timer_callback(timer_T *timer)
     typval_T	rettv;
     typval_T	argv[2];
 
-#ifdef FEAT_JOB_CHANNEL
+#ifdef FEAT_EVAL
     if (ch_log_active())
     {
 	callback_T *cb = &timer->tr_callback;
@@ -509,7 +509,7 @@ timer_callback(timer_T *timer)
     call_callback(&timer->tr_callback, -1, &rettv, 1, argv);
     clear_tv(&rettv);
 
-#ifdef FEAT_JOB_CHANNEL
+#ifdef FEAT_EVAL
     ch_log(NULL, "timer callback finished");
 #endif
 }

src/ui.c

@@ -538,8 +538,6 @@ ui_delay(long msec_arg, int ignoreinput)
 #ifdef FEAT_EVAL
     if (ui_delay_for_testing > 0)
 	msec = ui_delay_for_testing;
-#endif
-#ifdef FEAT_JOB_CHANNEL
     ch_log(NULL, "ui_delay(%ld)", msec);
 #endif
 #ifdef FEAT_GUI
@@ -968,7 +966,7 @@ fill_input_buf(int exit_on_error UNUSED)
 #  else
 	len = read(read_cmd_fd, (char *)inbuf + inbufcount, readlen);
 #  endif
-#  ifdef FEAT_JOB_CHANNEL
+#  ifdef FEAT_EVAL
 	if (len > 0)
 	{
 	    inbuf[inbufcount + len] = NUL;

src/version.c

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