]> git.ipfire.org Git - thirdparty/util-linux.git/blobdiff - term-utils/script.c
script: cleanup info logging
[thirdparty/util-linux.git] / term-utils / script.c
index f901a0227ee1788f7bb0991471578c6384e85679..e133de58c939df4291f153fef996a29d776350ab 100644 (file)
@@ -74,6 +74,7 @@
 #include "strutils.h"
 #include "xalloc.h"
 #include "optutils.h"
+#include "signames.h"
 
 #include "debug.h"
 
@@ -111,8 +112,8 @@ UL_DEBUG_DEFINE_MASKNAMES(script) = UL_DEBUG_EMPTY_MASKNAMES;
  */
 enum {
        SCRIPT_FMT_RAW = 1,             /* raw slave/master data */
-       SCRIPT_FMT_TIMING_SIMPLE,       /* timing info in classic "<delta> <offset>" format */
-       SCRIPT_FMT_TIMING_MULTI,        /* multiple streams in format "<type> <delta> <offset|etc> */
+       SCRIPT_FMT_TIMING_SIMPLE,       /* (classic) in format "<delta> <offset>" */
+       SCRIPT_FMT_TIMING_MULTI,        /* (advanced) multiple streams in format "<type> <delta> <offset|etc> */
 };
 
 struct script_log {
@@ -142,6 +143,14 @@ struct script_control {
        struct script_stream    out;    /* output */
        struct script_stream    in;     /* input */
 
+       struct script_log       *siglog;        /* log for signal entries */
+       struct script_log       *infolog;       /* log for info entries */
+
+       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 */
        int childstatus;        /* child process exit value */
@@ -166,12 +175,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
  */
@@ -204,15 +224,20 @@ static void __attribute__((__noreturn__)) usage(void)
        fputs(_(" -I, --log-in <file>           log stdin to file\n"), out);
        fputs(_(" -O, --log-out <file>          log stdout to file (default)\n"), out);
        fputs(_(" -B, --log-io <file>           log stdin and stdout to file\n"), out);
+       fputs(USAGE_SEPARATOR, out);
+
        fputs(_(" -T, --log-timing <file>       log timing information to file\n"), out);
-       fputs(_(" -a, --append                  append the output\n"), out);
+       fputs(_(" -t[<file>], --timing[=<file>] deprecated alias to -T (default file is stderr)\n"), out);
+       fputs(_(" -m, --logging-format <name>   force to 'classic' or 'advanced' format\n"), out);
+       fputs(USAGE_SEPARATOR, out);
+
+       fputs(_(" -a, --append                  append to the log file\n"), out);
        fputs(_(" -c, --command <command>       run command rather than interactive shell\n"), out);
        fputs(_(" -e, --return                  return exit code of the child process\n"), out);
        fputs(_(" -f, --flush                   run flush after each write\n"), out);
        fputs(_("     --force                   use output file even when it is a link\n"), out);
        fputs(_(" -o, --output-limit <size>     terminate if output files exceed size\n"), out);
        fputs(_(" -q, --quiet                   be quiet\n"), out);
-       fputs(_(" -t[<file>], --timing[=<file>] deprecated alias to -T (default file is stderr)\n"), out);
 
        fputs(USAGE_SEPARATOR, out);
        printf(USAGE_HELP_OPTIONS(31));
@@ -264,6 +289,14 @@ static struct script_log *log_associate(struct script_control *ctl,
        stream->logs[stream->nlogs] = log;
        stream->nlogs++;
 
+       /* remember where to write info about signals */
+       if (format == SCRIPT_FMT_TIMING_MULTI) {
+               if (!ctl->siglog)
+                       ctl->siglog = log;
+               if (!ctl->infolog)
+                       ctl->infolog = log;
+       }
+
        return log;
 }
 
@@ -333,19 +366,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, _("<not executed on terminal>"));
 
@@ -353,6 +381,7 @@ static void log_start(struct script_control *ctl,
                break;
        }
        case SCRIPT_FMT_TIMING_SIMPLE:
+       case SCRIPT_FMT_TIMING_MULTI:
                gettime_monotonic(&log->oldtime);
                break;
        }
@@ -360,6 +389,19 @@ static void log_start(struct script_control *ctl,
        log->initialized = 1;
 }
 
+static void start_logging(struct script_control *ctl)
+{
+       size_t i;
+
+       /* start all output logs */
+       for (i = 0; i < ctl->out.nlogs; i++)
+               log_start(ctl, ctl->out.logs[i]);
+
+       /* start all input logs */
+       for (i = 0; i < ctl->in.nlogs; i++)
+               log_start(ctl, ctl->in.logs[i]);
+}
+
 static size_t log_write(struct script_control *ctl,
                      struct script_stream *stream,
                      struct script_log *log,
@@ -431,6 +473,80 @@ static uint64_t log_stream_activity(
        return outsz;
 }
 
+static uint64_t log_signal(struct script_control *ctl, int signum, char *msgfmt, ...)
+{
+       struct script_log *log;
+       struct timeval now, delta;
+       char msg[BUFSIZ] = {0};
+       va_list ap;
+       int sz;
+
+       assert(ctl);
+
+       log = ctl->siglog;
+       if (!log)
+               return 0;
+
+       assert(log->format == SCRIPT_FMT_TIMING_MULTI);
+       DBG(IO, ul_debug("  writing signal to multi-stream timing"));
+
+       gettime_monotonic(&now);
+       timersub(&now, &log->oldtime, &delta);
+
+       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, "S %ld.%06ld SIG%s %s\n",
+                       (long)delta.tv_sec, (long)delta.tv_usec,
+                       signum_to_signame(signum), msg);
+       else
+               sz = fprintf(log->fp, "S %ld.%06ld SIG%s\n",
+                       (long)delta.tv_sec, (long)delta.tv_usec,
+                       signum_to_signame(signum));
+
+       log->oldtime = now;
+       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)
 {
@@ -673,6 +789,10 @@ static void handle_signal(struct script_control *ctl, int fd)
                if (ctl->isterm) {
                        ioctl(STDIN_FILENO, TIOCGWINSZ, (char *)&ctl->win);
                        ioctl(ctl->slave, TIOCSWINSZ, (char *)&ctl->win);
+                       log_signal(ctl, info.ssi_signo,
+                                       "ROWS=%d COLS=%d",
+                                       ctl->win.ws_row,
+                                       ctl->win.ws_col);
                }
                break;
        case SIGTERM:
@@ -680,6 +800,7 @@ static void handle_signal(struct script_control *ctl, int fd)
        case SIGINT:
                /* fallthrough */
        case SIGQUIT:
+               log_signal(ctl, info.ssi_signo, NULL);
                DBG(SIGNAL, ul_debug(" get signal SIG{TERM,INT,QUIT}"));
                fprintf(stderr, _("\nSession terminated.\n"));
                /* Child termination is going to generate SIGCHILD (see above) */
@@ -694,7 +815,6 @@ static void handle_signal(struct script_control *ctl, int fd)
 static void do_io(struct script_control *ctl)
 {
        int ret, eof = 0;
-       size_t i;
        enum {
                POLLFD_SIGNAL = 0,
                POLLFD_MASTER,
@@ -707,15 +827,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]);
-
-       /* start all input logs */
-       for (i = 0; i < ctl->in.nlogs; i++)
-               log_start(ctl, ctl->in.logs[i]);
-
        while (!ctl->die) {
                size_t i;
                int errsv;
@@ -945,6 +1056,7 @@ int main(int argc, char **argv)
                {"log-out", required_argument, NULL, 'O'},
                {"log-io", required_argument, NULL, 'B'},
                {"log-timing", required_argument, NULL, 'T'},
+               {"logging-format", required_argument, NULL, 'm'},
                {"output-limit", required_argument, NULL, 'o'},
                {"quiet", no_argument, NULL, 'q'},
                {"timing", optional_argument, NULL, 't'},
@@ -972,7 +1084,7 @@ int main(int argc, char **argv)
 
        script_init_debug();
 
-       while ((ch = getopt_long(argc, argv, "aB:c:efI:O:o:qT:t::Vh", longopts, NULL)) != -1) {
+       while ((ch = getopt_long(argc, argv, "aB:c:efI:O:o:qm:T:t::Vh", longopts, NULL)) != -1) {
 
                err_exclusive_options(ch, longopts, excl, excl_st);
 
@@ -1011,6 +1123,14 @@ int main(int argc, char **argv)
                case 'q':
                        ctl.quiet = 1;
                        break;
+               case 'm':
+                       if (strcasecmp(optarg, "classic") == 0)
+                               format = SCRIPT_FMT_TIMING_SIMPLE;
+                       else if (strcasecmp(optarg, "advanced") == 0)
+                               format = SCRIPT_FMT_TIMING_MULTI;
+                       else
+                               errx(EXIT_FAILURE, _("unssuported logging format: '%s'"), optarg);
+                       break;
                case 't':
                        if (optarg && *optarg == '=')
                                optarg++;
@@ -1048,10 +1168,17 @@ int main(int argc, char **argv)
        }
 
        if (timingfile) {
+               /* the old SCRIPT_FMT_TIMING_SIMPLE should be used when
+                * recoding output only (just for backward compatibility),
+                * otherwise switch to new format. */
                if (!format)
-                       format = outfile && infile ?
+                       format = infile || (outfile && infile) ?
                                        SCRIPT_FMT_TIMING_MULTI :
                                        SCRIPT_FMT_TIMING_SIMPLE;
+
+               else if (format == SCRIPT_FMT_TIMING_SIMPLE && outfile && infile)
+                       errx(EXIT_FAILURE, _("log multiple streams is mutually "
+                                            "exclusive with 'classic' format"));
                if (outfile)
                        log_associate(&ctl, &ctl.out, timingfile, format);
                if (infile)
@@ -1063,6 +1190,7 @@ int main(int argc, char **argv)
                ctl.shell = _PATH_BSHELL;
 
        getmaster(&ctl);
+
        if (!ctl.quiet) {
                printf(_("Script started"));
                if (outfile)
@@ -1107,6 +1235,23 @@ int main(int argc, char **argv)
                do_shell(&ctl);
                break;
        default: /* parent */
+               start_logging(&ctl);
+
+               if (timingfile && format == SCRIPT_FMT_TIMING_MULTI) {
+                       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);
+                       log_info(&ctl, "TIMING_LOG", timingfile);
+                       if (outfile)
+                               log_info(&ctl, "OUTPUT_LOG", outfile);
+                       if (infile)
+                               log_info(&ctl, "INPUT_LOG", infile);
+               }
                do_io(&ctl);
                break;
        }