patch 9.0.0977: it is not easy to see what client-server commands are doingv9.0.0977

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.

27 files changed, 341 insertions, 257 deletions

diff --git a/Filelist b/Filelist
index 30d5d589dc..4832751350 100644
--- a/Filelist
+++ b/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 \
diff --git a/runtime/doc/starting.txt b/runtime/doc/starting.txt
index c4441f3a18..619fc18ed2 100644
--- a/runtime/doc/starting.txt
+++ b/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
diff --git a/src/Make_ami.mak b/src/Make_ami.mak
index 1d74b3e5a9..a642d91285 100644
--- a/src/Make_ami.mak
+++ b/src/Make_ami.mak
@@ -124,6 +124,7 @@ SRC += \
 	json.c \
 	list.c \
 	locale.c \
+	logfile.c \
 	main.c \
 	mark.c \
 	map.c \
diff --git a/src/Make_cyg_ming.mak b/src/Make_cyg_ming.mak
index 5e1822c77b..b559467c19 100644
--- a/src/Make_cyg_ming.mak
+++ b/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 \
diff --git a/src/Make_mvc.mak b/src/Make_mvc.mak
index 639ae2f893..501446e542 100644
--- a/src/Make_mvc.mak
+++ b/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 \
diff --git a/src/Make_vms.mms b/src/Make_vms.mms
index 20cf52f391..53e1ce15a4 100644
--- a/src/Make_vms.mms
+++ b/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 \
diff --git a/src/Makefile b/src/Makefile
index 57f9aade0f..7f9d173a18 100644
--- a/src/Makefile
+++ b/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 \
diff --git a/src/channel.c b/src/channel.c
index 4e6457546a..db4568d49e 100644
--- a/src/channel.c
+++ b/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_lead(lead, channel, part);
-	fprintf(log_fd, "'");
-	vim_ignored = (int)fwrite(buf, len, 1, log_fd);
-	fprintf(log_fd, "'\n");
-    }
+	ch_log_literal(lead, channel, part, buf, len);
+
     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);
-	fprintf(log_fd, "'");
-	vim_ignored = (int)fwrite(buf_arg, len_arg, 1, log_fd);
-	fprintf(log_fd, "'\n");
-	fflush(log_fd);
+	ch_log_literal("SEND ", channel, part, buf_arg, len_arg);
 	did_repeated_msg = 0;
     }
 
@@ -5293,52 +5161,6 @@ f_ch_info(typval_T *argvars, typval_T *rettv UNUSED)
 }
 
 /*
- * "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
  */
     void
diff --git a/src/clientserver.c b/src/clientserver.c
index 63aec10d86..ccb7238725 100644
--- a/src/clientserver.c
+++ b/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)
diff --git a/src/evalfunc.c b/src/evalfunc.c
index 112a2e70b8..e72f8610fe 100644
--- a/src/evalfunc.c
+++ b/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,
diff --git a/src/globals.h b/src/globals.h
index e69856801e..0cc7c9bc47 100644
--- a/src/globals.h
+++ b/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},
-    {"bottom",	TRUE, 0, NULL, 0, FALSE},
-    {"left",	TRUE, 0, NULL, 0, FALSE},
-    {"right",	TRUE, 0, NULL, 0, FALSE},
-    {"header",	TRUE, 0, NULL, 0, FALSE},
-    {"syntax",	FALSE, 0, NULL, 0, FALSE},
-    {"number",	FALSE, 0, NULL, 0, FALSE},
-    {"wrap",	FALSE, 0, NULL, 0, FALSE},
-    {"duplex",	FALSE, 0, NULL, 0, FALSE},
-    {"portrait", FALSE, 0, NULL, 0, FALSE},
-    {"paper",	FALSE, 0, NULL, 0, FALSE},
-    {"collate",	FALSE, 0, NULL, 0, FALSE},
-    {"jobsplit", FALSE, 0, NULL, 0, FALSE},
-    {"formfeed", FALSE, 0, NULL, 0, FALSE},
-}
+    = {
+	{"top",	TRUE, 0, NULL, 0, FALSE},
+	{"bottom",	TRUE, 0, NULL, 0, FALSE},
+	{"left",	TRUE, 0, NULL, 0, FALSE},
+	{"right",	TRUE, 0, NULL, 0, FALSE},
+	{"header",	TRUE, 0, NULL, 0, FALSE},
+	{"syntax",	FALSE, 0, NULL, 0, FALSE},
+	{"number",	FALSE, 0, NULL, 0, FALSE},
+	{"wrap",	FALSE, 0, NULL, 0, FALSE},
+	{"duplex",	FALSE, 0, NULL, 0, FALSE},
+	{"portrait", FALSE, 0, NULL, 0, FALSE},
+	{"paper",	FALSE, 0, NULL, 0, FALSE},
+	{"collate",	FALSE, 0, NULL, 0, FALSE},
+	{"jobsplit", 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
diff --git a/src/gui_gtk_x11.c b/src/gui_gtk_x11.c
index 25685ddb28..8b75ba8c3e 100644
--- a/src/gui_gtk_x11.c
+++ b/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
diff --git a/src/if_xcmdsrv.c b/src/if_xcmdsrv.c
index 1f6b8d212f..1aa09fd4a3 100644
--- a/src/if_xcmdsrv.c
+++ b/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 (SendInit(dpy) < 0)
-	    return -1;
-    }
+    if (commProperty == None && dpy != NULL && 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");
 			}
diff --git a/src/logfile.c b/src/logfile.c
new file mode 100644
index 0000000000..3ab2c0f398
--- /dev/null
+++ b/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
diff --git a/src/main.c b/src/main.c
index db81a3f3cf..9081657691 100644
--- a/src/main.c
+++ b/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);