From 3cecd1761008588aff338e009c7eb777f9060f9d Mon Sep 17 00:00:00 2001 From: Karel Zak Date: Wed, 26 Jun 2019 17:32:18 +0200 Subject: [PATCH] script: log additional information Signed-off-by: Karel Zak --- term-utils/script.c | 100 ++++++++++++++++++++++++++++++++++++-------- 1 file changed, 82 insertions(+), 18 deletions(-) diff --git a/term-utils/script.c b/term-utils/script.c index 15ca648a1c..55a6d82d02 100644 --- a/term-utils/script.c +++ b/term-utils/script.c @@ -143,7 +143,14 @@ struct script_control { struct script_stream out; /* output */ struct script_stream in; /* input */ - struct script_log *siglog; /* log for signals */ + struct script_log *siglog; /* log for signal entries */ + struct script_log *infolog; /* log for info entries */ + struct script_log *tmlog; /* timing log */ + + const char *ttyname; + const char *ttytype; + int ttycols; + int ttylines; int poll_timeout; /* poll() timeout, used in end of execution */ pid_t child; /* child pid */ @@ -169,12 +176,23 @@ struct script_control { static void restore_tty(struct script_control *ctl, int mode); static void __attribute__((__noreturn__)) fail(struct script_control *ctl); +static uint64_t log_info(struct script_control *ctl, const char *name, const char *msgfmt, ...); static void script_init_debug(void) { __UL_INIT_DEBUG_FROM_ENV(script, SCRIPT_DEBUG_, 0, SCRIPT_DEBUG); } +static void init_terminal_info(struct script_control *ctl) +{ + if (ctl->ttyname || !ctl->isterm) + return; /* already initialized */ + + get_terminal_dimension(&ctl->ttycols, &ctl->ttylines); + get_terminal_name(&ctl->ttyname, NULL, NULL); + get_terminal_type(&ctl->ttytype); +} + /* * For tests we want to be able to control time output */ @@ -273,8 +291,14 @@ static struct script_log *log_associate(struct script_control *ctl, stream->nlogs++; /* remember where to write info about signals */ - if (format == SCRIPT_FMT_TIMING_MULTI && !ctl->siglog) - ctl->siglog = log; + if (format == SCRIPT_FMT_TIMING_MULTI) { + if (!ctl->siglog) + ctl->siglog = log; + if (!ctl->infolog) + ctl->infolog = log; + if (!ctl->tmlog) + ctl->tmlog = log; + } return log; } @@ -345,19 +369,14 @@ static void log_start(struct script_control *ctl, fprintf(log->fp, _("Script started on %s ["), buf); if (ctl->isterm) { - int cols = 0, lines = 0; - const char *tty = NULL, *term = NULL; + init_terminal_info(ctl); - get_terminal_dimension(&cols, &lines); - get_terminal_name(&tty, NULL, NULL); - get_terminal_type(&term); + if (ctl->ttytype) + fprintf(log->fp, "TERM=\"%s\" ", ctl->ttytype); + if (ctl->ttyname) + fprintf(log->fp, "TTY=\"%s\" ", ctl->ttyname); - if (term) - fprintf(log->fp, "TERM=\"%s\" ", term); - if (tty) - fprintf(log->fp, "TTY=\"%s\" ", tty); - - fprintf(log->fp, "COLUMNS=\"%d\" LINES=\"%d\"", cols, lines); + fprintf(log->fp, "COLUMNS=\"%d\" LINES=\"%d\"", ctl->ttycols, ctl->ttylines); } else fprintf(log->fp, _("")); @@ -459,7 +478,6 @@ static uint64_t log_signal(struct script_control *ctl, int signum, char *msgfmt, return 0; assert(log->format == SCRIPT_FMT_TIMING_MULTI); - DBG(IO, ul_debug(" writing signal to multi-stream timing")); gettime_monotonic(&now); @@ -475,7 +493,7 @@ static uint64_t log_signal(struct script_control *ctl, int signum, char *msgfmt, } if (*msg) - sz = fprintf(log->fp, "S %ld.%06ld SIG%s %s\n", + sz = fprintf(log->fp, "S %ld.%06ld SIG%s [%s]\n", (long)delta.tv_sec, (long)delta.tv_usec, signum_to_signame(signum), msg); else @@ -487,6 +505,39 @@ static uint64_t log_signal(struct script_control *ctl, int signum, char *msgfmt, return sz > 0 ? sz : 0; } +static uint64_t log_info(struct script_control *ctl, const char *name, const char *msgfmt, ...) +{ + struct script_log *log; + char msg[BUFSIZ] = {0}; + va_list ap; + int sz; + + assert(ctl); + + log = ctl->infolog; + if (!log) + return 0; + + assert(log->format == SCRIPT_FMT_TIMING_MULTI); + DBG(IO, ul_debug(" writing info to multi-stream log")); + + if (msgfmt) { + int rc; + va_start(ap, msgfmt); + rc = vsnprintf(msg, sizeof(msg), msgfmt, ap); + va_end(ap); + if (rc < 0) + *msg = '\0';; + } + + if (*msg) + sz = fprintf(log->fp, "H 0 %s [%s]\n", name, msg); + else + sz = fprintf(log->fp, "H 0 %s\n", name); + + return sz > 0 ? sz : 0; +} + static void die_if_link(struct script_control *ctl, const char *filename) { struct stat s; @@ -729,7 +780,7 @@ static void handle_signal(struct script_control *ctl, int fd) ioctl(STDIN_FILENO, TIOCGWINSZ, (char *)&ctl->win); ioctl(ctl->slave, TIOCSWINSZ, (char *)&ctl->win); log_signal(ctl, info.ssi_signo, - "[ROWS=%d COLS=%d]", + "ROWS=%d COLS=%d", ctl->win.ws_row, ctl->win.ws_col); } @@ -767,7 +818,6 @@ static void do_io(struct script_control *ctl) [POLLFD_STDIN] = { .fd = STDIN_FILENO, .events = POLLIN | POLLERR | POLLHUP } }; - /* start all output logs */ for (i = 0; i < ctl->out.nlogs; i++) log_start(ctl, ctl->out.logs[i]); @@ -776,6 +826,18 @@ static void do_io(struct script_control *ctl) for (i = 0; i < ctl->in.nlogs; i++) log_start(ctl, ctl->in.logs[i]); + /* log basic information */ + if (ctl->isterm) { + init_terminal_info(ctl); + log_info(ctl, "TERM", ctl->ttytype); + log_info(ctl, "TTY", ctl->ttyname); + log_info(ctl, "COLUMNS", "%d", ctl->ttycols); + log_info(ctl, "LINES", "%d", ctl->ttylines); + } + log_info(ctl, "SHELL", ctl->shell); + if (ctl->tmlog) + log_info(ctl, "TIMING_LOG", ctl->tmlog->filename); + while (!ctl->die) { size_t i; int errsv; @@ -1139,6 +1201,8 @@ int main(int argc, char **argv) ctl.shell = _PATH_BSHELL; getmaster(&ctl); + + if (!ctl.quiet) { printf(_("Script started")); if (outfile) -- 2.39.2