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.

diff --git a/Filelist b/Filelist
index 30d5d589dc02c1bdf48c4f5a1c75af6b85b5fbf6..483275135075499f19a12263ad3ff3b2899adf0d 100644 (file)
--- 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 c4441f3a18a7a33f24cea7a7fe0cfecd096b8569..619fc18ed27987c1f89642aa33b2a17a463602d7 100644 (file)
--- 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 1d74b3e5a98132bafd11077e2d4354edb6fc4d31..a642d91285fe5597a866b0dc99f591448a469bf4 100644 (file)
--- 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 5e1822c77b2bcb25a6d714ef57face871b5f516a..b559467c19e8d408bf64949042af0fbf1cceefb8 100644 (file)
--- 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 639ae2f8932d51232850a8a3fa5c7d9ef9b74418..501446e542bb727c8b66f205e6e5dbd4d8688e63 100644 (file)
--- 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 20cf52f39129c31a49b41fdc696c2548f95e63bb..53e1ce15a47501a58309c64405f22155e2cb3c87 100644 (file)
--- 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 57f9aade0f8a49c9b25a9b8e2edc3ded4633c0e7..7f9d173a1824541245190a50f5679960e3920328 100644 (file)
--- 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 4e6457546ae30d794e0639148595a2b63b2d8a4e..db4568d49e7952783ab92b0977ca951f77ba18fb 100644 (file)
--- 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;
     }
 
@@ -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
  */

diff --git a/src/clientserver.c b/src/clientserver.c
index 63aec10d86967d802066b304d9b8714c43557251..ccb723872558614750b0b2eeca3b209ddf880662 100644 (file)
--- 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 112a2e70b83e0cf2f7123da4f784f834b5b1a98b..e72f8610fec11cf729af47dc7f95de5ece621db8 100644 (file)
--- 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 e69856801e9ddd06974e110b627cba3a9567e5c3..0cc7c9bc47496fade9ba36de6e645e96c71c9aa3 100644 (file)
--- 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 25685ddb28c2177092e572d974f68ad4893a9102..8b75ba8c3ee43ff38d5a4f8d624a7f72f87f4146 100644 (file)
--- 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 1f6b8d212f2a0afe749f998ef893a4e6ebd71cf3..1aa09fd4a3c8d417dcf797d23f7374a3632b9993 100644 (file)
--- 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 (file)
index 0000000..3ab2c0f
--- /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 db81a3f3cffd36f7473d0f27bd61140da64657e7..90816576918d27254b4b6c6abd887944c168d7d1 100644 (file)
--- 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);
     }
-#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
 

diff --git a/src/message.c b/src/message.c
index 3ba1a592b87eb83ae768725cfe28b11446d24a26..a2fc008c2e63dde2960ec8854259a3868880aa3f 100644 (file)
--- a/src/message.c
+++ b/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;

diff --git a/src/os_unix.c b/src/os_unix.c
index c43d9c172da8fab7c612266ff60d94b71b02de60..79d7f17d98bb0edd25a060d1b7f7b32f5cb9b609 100644 (file)
--- a/src/os_unix.c
+++ b/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

diff --git a/src/os_win32.c b/src/os_win32.c
index acbc4cb7d067b2b85f6af0df431f939af2b68d5d..334d9735eec9ecd922c46ca3d2dc2a1ce5af93ce 100644 (file)
--- a/src/os_win32.c
+++ b/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.

diff --git a/src/proto.h b/src/proto.h
index 7ddf1037b4857e6a5b2fcc8316cb79a5240c5b38..4c7f8c9dade6b840d406615075def92f8e974851 100644 (file)
--- a/src/proto.h
+++ b/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
 

diff --git a/src/proto/channel.pro b/src/proto/channel.pro
index 17ce77711d9bde2267bdb67a26d4ff77fb06195d..794e60b2200749b132405e0dc5d495cb9b768b62 100644 (file)
--- a/src/proto/channel.pro
+++ b/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);

diff --git a/src/proto/logfile.pro b/src/proto/logfile.pro
new file mode 100644 (file)
index 0000000..1c4334e
--- /dev/null
+++ b/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 : */

diff --git a/src/regexp_bt.c b/src/regexp_bt.c
index 42b6ac20137cf92d27078a6b7f57be6c784e3e40..d2acbc2032139ad7a28ab15e504c2b2498cc77eb 100644 (file)
--- a/src/regexp_bt.c
+++ b/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

diff --git a/src/regexp_nfa.c b/src/regexp_nfa.c
index 17025108a767abe9b32e1e8347eec971d042a8b0..c298f85d3aade5d0f63349e2789c5a8ef9f1e0fa 100644 (file)
--- a/src/regexp_nfa.c
+++ b/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

diff --git a/src/term.c b/src/term.c
index 9a45f46c39e1f8c695d7d4bdaf8a258489d08093..40728f2440e735ee911e84e748cd6503c13a416a 100644 (file)
--- a/src/term.c
+++ b/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;

diff --git a/src/time.c b/src/time.c
index a7daaf176ec2cc48f453872870154f8def24d7af..891a9f49edde23e15772db48d52a53f6240017b0 100644 (file)
--- a/src/time.c
+++ b/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
 }

diff --git a/src/ui.c b/src/ui.c
index 9fc88e5e842eaf3f9ca16f4cbdf1f28f0b35dd55..7658c52817349491d3a4962fd2309eac140fc3fd 100644 (file)
--- a/src/ui.c
+++ b/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;

diff --git a/src/version.c b/src/version.c
index 37d7c8f51d8e48b284a0bb3356c8bf8cd1d74f3a..528b804c429c3607fecaa94d2125f95fd10afaad 100644 (file)
--- a/src/version.c
+++ b/src/version.c
@@ -695,6 +695,8 @@ static char *(features[]) =
 
 static int included_patches[] =
 {   /* Add new patch number below this line */
+/**/
+    977,
 /**/
     976,
 /**/