Mercurial > vim
changeset 31287:fa309d9af73c v9.0.0977
patch 9.0.0977: it is not easy to see what client-server commands are doing
Commit: https://github.com/vim/vim/commit/4c5678ff0c376661d4a8183a5a074a1203413b9d
Author: Bram Moolenaar <Bram@vim.org>
Date: Wed Nov 30 18:12:19 2022 +0000
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.
| author | Bram Moolenaar <Bram@vim.org> |
|---|---|
| date | Wed, 30 Nov 2022 19:15:10 +0100 |
| parents | 33c4af586833 |
| children | 6195f37efb92 |
| files | Filelist runtime/doc/starting.txt src/Make_ami.mak src/Make_cyg_ming.mak src/Make_mvc.mak src/Make_vms.mms src/Makefile src/channel.c src/clientserver.c src/evalfunc.c src/globals.h src/gui_gtk_x11.c src/if_xcmdsrv.c src/logfile.c src/main.c src/message.c src/os_unix.c src/os_win32.c src/proto.h src/proto/channel.pro src/proto/logfile.pro src/regexp_bt.c src/regexp_nfa.c src/term.c src/time.c src/ui.c src/version.c |
| diffstat | 27 files changed, 341 insertions(+), 257 deletions(-) [+] |
line wrap: on
line diff
--- 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 \
--- a/runtime/doc/starting.txt +++ b/runtime/doc/starting.txt @@ -348,7 +348,7 @@ a slash. Thus "-R" means recovery and " 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
--- 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 \
--- 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 \
--- 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 @@ lib$(MZSCHEME_MAIN_LIB)$(MZSCHEME_VER).l $(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 \
--- 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]confi 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 \
--- 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 protode 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 \
--- a/src/channel.c +++ b/src/channel.c @@ -81,8 +81,6 @@ static ch_part_T channel_part_read(chann // 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 *chan 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 *chan 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 *ch # 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 *ch # 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 } 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, || 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 in ++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 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 *r } /* - * "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
--- 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)
--- 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,
--- 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 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 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_I 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 // 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(= 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
--- 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
--- 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"); }
new file mode 100644 --- /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
--- 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
--- 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;
--- 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, j 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
--- 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.
--- 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
--- 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, i 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, ty 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);
new file mode 100644 --- /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 : */
--- 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
--- 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
--- 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;
--- 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 }
--- 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;