]> 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 b7bec7e76084e4af0af4502dfc87a28e95a8ed2f..e133de58c939df4291f153fef996a29d776350ab 100644 (file)
@@ -72,6 +72,9 @@
 #include "monotonic.h"
 #include "timeutils.h"
 #include "strutils.h"
+#include "xalloc.h"
+#include "optutils.h"
+#include "signames.h"
 
 #include "debug.h"
 
@@ -98,18 +101,56 @@ UL_DEBUG_DEFINE_MASKNAMES(script) = UL_DEBUG_EMPTY_MASKNAMES;
 
 #define DEFAULT_TYPESCRIPT_FILENAME "typescript"
 
+/*
+ * Script is driven by stream (stdout/stdin) activity. It's possible to
+ * associate arbitrary number of log files with the stream. We have two basic
+ * types of log files: "timing file" (simple or multistream) and "data file"
+ * (raw).
+ *
+ * The same log file maybe be shared between both streams. For exmaple
+ * multi-stream timing file is possible to use for stdin as well as for stdout.
+ */
+enum {
+       SCRIPT_FMT_RAW = 1,             /* raw slave/master data */
+       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 {
+       FILE    *fp;                    /* file pointer (handler) */
+       int     format;                 /* SCRIPT_FMT_* */
+       char    *filename;              /* on command line specified name */
+       struct timeval oldtime;         /* previous entry log time (SCRIPT_FMT_TIMING_* only) */
+
+       unsigned int    initialized : 1;
+};
+
+struct script_stream {
+       struct script_log **logs;       /* logs where to write data from stream */
+       size_t nlogs;                   /* number of logs */
+       char ident;                     /* stream identifier */
+};
+
 struct script_control {
        char *shell;            /* shell to be executed */
        char *command;          /* command to be executed */
-       char *fname;            /* output file path */
-       FILE *typescriptfp;     /* output file pointer */
-       char *tname;            /* timing file path */
-       FILE *timingfp;         /* timing file pointer */
-       uint64_t outsz;         /* current output file size */
-       uint64_t maxsz;         /* maximum output file size */
-       struct timeval oldtime; /* previous write or command start time */
+       uint64_t outsz;         /* current output files size */
+       uint64_t maxsz;         /* maximum output files size */
+
        int master;             /* pseudoterminal master file descriptor */
        int slave;              /* pseudoterminal slave file descriptor */
+
+       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 */
@@ -123,7 +164,6 @@ struct script_control {
         rc_wanted:1,           /* return child exit value */
         flush:1,               /* flush after each write */
         quiet:1,               /* suppress most output */
-        timing:1,              /* include timing file */
         force:1,               /* write output to links */
         isterm:1,              /* is child process running as terminal */
         die:1;                 /* terminate program */
@@ -133,11 +173,25 @@ struct script_control {
        int sigfd;              /* file descriptor for signalfd() */
 };
 
+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
  */
@@ -167,62 +221,344 @@ static void __attribute__((__noreturn__)) usage(void)
        fputs(_("Make a typescript of a terminal session.\n"), out);
 
        fputs(USAGE_OPTIONS, out);
-       fputs(_(" -a, --append                  append the output\n"
-               " -c, --command <command>       run command rather than interactive shell\n"
-               " -e, --return                  return exit code of the child process\n"
-               " -f, --flush                   run flush after each write\n"
-               "     --force                   use output file even when it is a link\n"
-               " -o, --output-limit <size>     terminate if output files exceed size\n"
-               " -q, --quiet                   be quiet\n"
-               " -t[<file>], --timing[=<file>] output timing data to stderr or to FILE\n"
-               ), out);
-       printf(USAGE_HELP_OPTIONS(31));
+       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(_(" -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(USAGE_SEPARATOR, out);
+       printf(USAGE_HELP_OPTIONS(31));
        printf(USAGE_MAN_TAIL("script(1)"));
+
        exit(EXIT_SUCCESS);
 }
 
-static void typescript_message_start(const struct script_control *ctl, time_t *tvec)
+static struct script_log *get_log_by_name(struct script_stream *stream,
+                                         const char *name)
 {
-       char buf[FORMAT_TIMESTAMP_MAX];
-       int cols = 0, lines = 0;
-       const char *tty = NULL, *term = NULL;
+       size_t i;
+
+       for (i = 0; i < stream->nlogs; i++) {
+               struct script_log *log = stream->logs[i];
+               if (strcmp(log->filename, name) == 0)
+                       return log;
+       }
+       return NULL;
+}
+
+static struct script_log *log_associate(struct script_control *ctl,
+                                       struct script_stream *stream,
+                                       const char *filename, int format)
+{
+       struct script_log *log;
+
+       DBG(MISC, ul_debug("associate %s with stream", filename));
+
+       assert(ctl);
+       assert(filename);
+       assert(stream);
+
+       log = get_log_by_name(stream, filename);
+       if (log)
+               return log;     /* already defined */
+
+       log = get_log_by_name(stream == &ctl->out ? &ctl->in : &ctl->out, filename);
+       if (!log) {
+               /* create a new log */
+               log = xcalloc(1, sizeof(*log));
+               log->filename = xstrdup(filename);
+               log->format = format;
+       }
 
-       if (!ctl->typescriptfp)
+       /* add log to the stream */
+       stream->logs = xrealloc(stream->logs,
+                       (stream->nlogs + 1) * sizeof(log));
+       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;
+}
+
+static void log_close(struct script_control *ctl __attribute__((unused)),
+                     struct script_log *log,
+                     const char *msg,
+                     int status)
+{
+       if (!log->initialized)
                return;
 
-       strtime_iso(tvec, ISO_TIMESTAMP, buf, sizeof(buf));
+       DBG(MISC, ul_debug("closing %s", log->filename));
 
-       fprintf(ctl->typescriptfp, _("Script started on %s ["), buf);
+       switch (log->format) {
+       case SCRIPT_FMT_RAW:
+       {
+               char buf[FORMAT_TIMESTAMP_MAX];
+               time_t tvec = script_time((time_t *)NULL);
 
-       if (ctl->isterm) {
-               get_terminal_dimension(&cols, &lines);
-               get_terminal_name(&tty, NULL, NULL);
-               get_terminal_type(&term);
+               strtime_iso(&tvec, ISO_TIMESTAMP, buf, sizeof(buf));
+               if (msg)
+                       fprintf(log->fp, _("\nScript done on %s [<%s>]\n"), buf, msg);
+               else
+                       fprintf(log->fp, _("\nScript done on %s [COMMAND_EXIT_CODE=\"%d\"]\n"), buf, status);
+               break;
+       }
+       case SCRIPT_FMT_TIMING_SIMPLE:
+               break;
+       }
 
-               if (term)
-                       fprintf(ctl->typescriptfp, "TERM=\"%s\" ", term);
-               if (tty)
-                       fprintf(ctl->typescriptfp, "TTY=\"%s\" ", tty);
+       if (close_stream(log->fp) != 0)
+               err(EXIT_FAILURE, "write failed: %s", log->filename);
 
-               fprintf(ctl->typescriptfp, "COLS=\"%d\" LINES=\"%d\"", cols, lines);
-       } else
-               fprintf(ctl->typescriptfp, _("<not executed on terminal>"));
+       log->fp = NULL;
+       log->initialized = 0;
+}
+
+static void log_start(struct script_control *ctl,
+                     struct script_log *log)
+{
+       if (log->initialized)
+               return;
+
+       DBG(MISC, ul_debug("opening %s", log->filename));
+
+       assert(log->fp == NULL);
+
+       /* open the log */
+       log->fp = fopen(log->filename,
+                       ctl->append && log->format == SCRIPT_FMT_RAW ?
+                       "a" UL_CLOEXECSTR :
+                       "w" UL_CLOEXECSTR);
+       if (!log->fp) {
+               restore_tty(ctl, TCSANOW);
+               warn(_("cannot open %s"), log->filename);
+               fail(ctl);
+       }
+
+       /* write header, etc. */
+       switch (log->format) {
+       case SCRIPT_FMT_RAW:
+       {
+               char buf[FORMAT_TIMESTAMP_MAX];
+               time_t tvec = script_time((time_t *)NULL);
+
+               strtime_iso(&tvec, ISO_TIMESTAMP, buf, sizeof(buf));
+               fprintf(log->fp, _("Script started on %s ["), buf);
+
+               if (ctl->isterm) {
+                       init_terminal_info(ctl);
+
+                       if (ctl->ttytype)
+                               fprintf(log->fp, "TERM=\"%s\" ", ctl->ttytype);
+                       if (ctl->ttyname)
+                               fprintf(log->fp, "TTY=\"%s\" ", ctl->ttyname);
+
+                       fprintf(log->fp, "COLUMNS=\"%d\" LINES=\"%d\"", ctl->ttycols, ctl->ttylines);
+               } else
+                       fprintf(log->fp, _("<not executed on terminal>"));
+
+               fputs("]\n", log->fp);
+               break;
+       }
+       case SCRIPT_FMT_TIMING_SIMPLE:
+       case SCRIPT_FMT_TIMING_MULTI:
+               gettime_monotonic(&log->oldtime);
+               break;
+       }
+
+       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,
+                     char *obuf, size_t bytes)
+{
+       if (!log->fp)
+               return 0;
+
+       DBG(IO, ul_debug("  writining %s", log->filename));
+
+       switch (log->format) {
+       case SCRIPT_FMT_RAW:
+               if (fwrite_all(obuf, 1, bytes, log->fp)) {
+                       warn(_("cannot write %s"), log->filename);
+                       fail(ctl);
+               }
+               break;
+       case SCRIPT_FMT_TIMING_SIMPLE:
+       {
+               struct timeval now, delta;
+               int sz;
+
+               DBG(IO, ul_debug("  writing timing info"));
+
+               gettime_monotonic(&now);
+               timersub(&now, &log->oldtime, &delta);
+               sz = fprintf(log->fp, "%ld.%06ld %zd\n",
+                       (long)delta.tv_sec, (long)delta.tv_usec, bytes);
+               log->oldtime = now;
+               bytes = sz > 0 ? sz : 0;
+               break;
+       }
+       case SCRIPT_FMT_TIMING_MULTI:
+       {
+               struct timeval now, delta;
+               int sz;
+
+               DBG(IO, ul_debug("  writing multi-stream timing info"));
 
-       fputs("]\n", ctl->typescriptfp);
+               gettime_monotonic(&now);
+               timersub(&now, &log->oldtime, &delta);
+               sz = fprintf(log->fp, "%c %ld.%06ld %zd\n",
+                       stream->ident,
+                       (long)delta.tv_sec, (long)delta.tv_usec, bytes);
+               log->oldtime = now;
+               bytes = sz > 0 ? sz : 0;
+       }
+       default:
+               break;
+       }
+
+       if (ctl->flush)
+               fflush(log->fp);
+
+       return bytes;
+}
+
+static uint64_t log_stream_activity(
+                       struct script_control *ctl,
+                       struct script_stream *stream,
+                       char *buf, size_t bytes)
+{
+       size_t i;
+       uint64_t outsz = 0;
+
+       for (i = 0; i < stream->nlogs; i++)
+               outsz += log_write(ctl, stream, stream->logs[i], buf, bytes);
+
+       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(const struct script_control *ctl)
+static void die_if_link(struct script_control *ctl, const char *filename)
 {
        struct stat s;
 
        if (ctl->force)
                return;
-       if (lstat(ctl->fname, &s) == 0 && (S_ISLNK(s.st_mode) || s.st_nlink > 1))
+       if (lstat(filename, &s) == 0 && (S_ISLNK(s.st_mode) || s.st_nlink > 1))
                errx(EXIT_FAILURE,
                     _("output file `%s' is a link\n"
                       "Use --force if you really want to use it.\n"
-                      "Program not started."), ctl->fname);
+                      "Program not started."), filename);
 }
 
 static void restore_tty(struct script_control *ctl, int mode)
@@ -249,40 +585,45 @@ static void enable_rawmode_tty(struct script_control *ctl)
        tcsetattr(STDIN_FILENO, TCSANOW, &rtt);
 }
 
-static void __attribute__((__noreturn__)) done(struct script_control *ctl)
+static void __attribute__((__noreturn__)) done_log(struct script_control *ctl, const char *msg)
 {
+       int status;
+       size_t i;
+
        DBG(MISC, ul_debug("done!"));
 
        restore_tty(ctl, TCSADRAIN);
 
-       if (ctl->typescriptfp) {
-               char buf[FORMAT_TIMESTAMP_MAX];
-               time_t tvec = script_time((time_t *)NULL);
+       if (WIFSIGNALED(ctl->childstatus))
+               status = WTERMSIG(ctl->childstatus) + 0x80;
+       else
+               status = WEXITSTATUS(ctl->childstatus);
 
-               strtime_iso(&tvec, ISO_TIMESTAMP, buf, sizeof(buf));
-               fprintf(ctl->typescriptfp, _("\nScript done on %s\n"), buf);
-       }
 
-       if (!ctl->quiet && ctl->typescriptfp)
-               printf(_("Script done, file is %s\n"), ctl->fname);
+       DBG(MISC, ul_debug(" status=%d", status));
+
+       /* close all output logs */
+       for (i = 0; i < ctl->out.nlogs; i++)
+               log_close(ctl, ctl->out.logs[i], msg, status);
+
+       /* close all input logs */
+       for (i = 0; i < ctl->in.nlogs; i++)
+               log_close(ctl, ctl->in.logs[i], msg, status);
+
+       if (!ctl->quiet)
+               printf(_("Script done.\n"));
+
 #ifdef HAVE_LIBUTEMPTER
        if (ctl->master >= 0)
                utempter_remove_record(ctl->master);
 #endif
        kill(ctl->child, SIGTERM);      /* make sure we don't create orphans */
+       exit(ctl->rc_wanted ? status : EXIT_SUCCESS);
+}
 
-       if (ctl->timingfp && close_stream(ctl->timingfp) != 0)
-               err(EXIT_FAILURE, "write failed: %s", ctl->tname);
-       if (ctl->typescriptfp && close_stream(ctl->typescriptfp) != 0)
-               err(EXIT_FAILURE, "write failed: %s", ctl->fname);
-
-       if (ctl->rc_wanted) {
-               if (WIFSIGNALED(ctl->childstatus))
-                       exit(WTERMSIG(ctl->childstatus) + 0x80);
-               else
-                       exit(WEXITSTATUS(ctl->childstatus));
-       }
-       exit(EXIT_SUCCESS);
+static void __attribute__((__noreturn__)) done(struct script_control *ctl)
+{
+       done_log(ctl, NULL);
 }
 
 static void __attribute__((__noreturn__)) fail(struct script_control *ctl)
@@ -305,38 +646,10 @@ static void wait_for_child(struct script_control *ctl, int wait)
                        ctl->childstatus = status;
 }
 
+/* data from master to stdout */
 static void write_output(struct script_control *ctl, char *obuf,
                            ssize_t bytes)
 {
-       int timing_bytes = 0;
-
-       DBG(IO, ul_debug(" writing output"));
-
-       if (ctl->timing && ctl->timingfp) {
-               struct timeval now, delta;
-
-               DBG(IO, ul_debug("  writing timing info"));
-
-               gettime_monotonic(&now);
-               timersub(&now, &ctl->oldtime, &delta);
-               timing_bytes = fprintf(ctl->timingfp, "%ld.%06ld %zd\n",
-                       (long)delta.tv_sec, (long)delta.tv_usec, bytes);
-               if (ctl->flush)
-                       fflush(ctl->timingfp);
-               ctl->oldtime = now;
-               if (timing_bytes < 0)
-                       timing_bytes = 0;
-       }
-
-       DBG(IO, ul_debug("  writing to script file"));
-
-       if (fwrite_all(obuf, 1, bytes, ctl->typescriptfp)) {
-               warn(_("cannot write script file"));
-               fail(ctl);
-       }
-       if (ctl->flush)
-               fflush(ctl->typescriptfp);
-
        DBG(IO, ul_debug("  writing to output"));
 
        if (write_all(STDOUT_FILENO, obuf, bytes)) {
@@ -344,11 +657,6 @@ static void write_output(struct script_control *ctl, char *obuf,
                warn(_("write failed"));
                fail(ctl);
        }
-
-       if (ctl->maxsz != 0)
-               ctl->outsz += bytes + timing_bytes;
-
-       DBG(IO, ul_debug("  writing output *done*"));
 }
 
 static int write_to_shell(struct script_control *ctl,
@@ -426,19 +734,21 @@ static void handle_io(struct script_control *ctl, int fd, int *eof)
                /* without sync write_output() will write both input &
                 * shell output that looks like double echoing */
                fdatasync(ctl->master);
+               ctl->outsz += log_stream_activity(ctl, &ctl->in, buf, (size_t) bytes);
 
        /* from command (master) to stdout and log */
        } else if (fd == ctl->master) {
                DBG(IO, ul_debug(" master --> stdout %zd bytes", bytes));
                write_output(ctl, buf, bytes);
+               ctl->outsz += log_stream_activity(ctl, &ctl->out, buf, (size_t) bytes);
+       }
 
-               /* check output limit */
-               if (ctl->maxsz != 0 && ctl->outsz >= ctl->maxsz) {
-                       if (!ctl->quiet)
-                               printf(_("Script terminated, max output file size %zd exceeded.\n"), ctl->maxsz);
-                       DBG(IO, ul_debug("output size %zd, exceeded limit %zd", ctl->outsz, ctl->maxsz));
-                       done(ctl);
-               }
+       /* check output limit */
+       if (ctl->maxsz != 0 && ctl->outsz >= ctl->maxsz) {
+               if (!ctl->quiet)
+                       printf(_("Script terminated, max output files size %"PRIu64" exceeded.\n"), ctl->maxsz);
+               DBG(IO, ul_debug("output size %"PRIu64", exceeded limit %"PRIu64, ctl->outsz, ctl->maxsz));
+               done_log(ctl, _("max output size exceeded"));
        }
 }
 
@@ -458,10 +768,15 @@ static void handle_signal(struct script_control *ctl, int fd)
 
        switch (info.ssi_signo) {
        case SIGCHLD:
-               DBG(SIGNAL, ul_debug(" get signal SIGCHLD"));
-               if (info.ssi_code == CLD_EXITED) {
+               DBG(SIGNAL, ul_debug(" get signal SIGCHLD [ssi_code=%d, ssi_status=%d]",
+                                                       info.ssi_code, info.ssi_status));
+               if (info.ssi_code == CLD_EXITED
+                   || info.ssi_code == CLD_KILLED
+                   || info.ssi_code == CLD_DUMPED) {
                        wait_for_child(ctl, 0);
                        ctl->poll_timeout = 10;
+
+               /* In case of ssi_code is CLD_TRAPPED, CLD_STOPPED, or CLD_CONTINUED */
                } else if (info.ssi_status == SIGSTOP && ctl->child) {
                        DBG(SIGNAL, ul_debug(" child stop by SIGSTOP -- stop parent too"));
                        kill(getpid(), SIGSTOP);
@@ -474,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:
@@ -481,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) */
@@ -489,12 +809,12 @@ static void handle_signal(struct script_control *ctl, int fd)
        default:
                abort();
        }
+       DBG(SIGNAL, ul_debug("signal handle on FD %d done", fd));
 }
 
 static void do_io(struct script_control *ctl)
 {
        int ret, eof = 0;
-       time_t tvec = script_time((time_t *)NULL);
        enum {
                POLLFD_SIGNAL = 0,
                POLLFD_MASTER,
@@ -507,30 +827,6 @@ static void do_io(struct script_control *ctl)
                [POLLFD_STDIN]  = { .fd = STDIN_FILENO, .events = POLLIN | POLLERR | POLLHUP }
        };
 
-
-       if ((ctl->typescriptfp =
-            fopen(ctl->fname, ctl->append ? "a" UL_CLOEXECSTR : "w" UL_CLOEXECSTR)) == NULL) {
-
-               restore_tty(ctl, TCSANOW);
-               warn(_("cannot open %s"), ctl->fname);
-               fail(ctl);
-       }
-       if (ctl->timing) {
-               const char *tname = ctl->tname ? ctl->tname : "/dev/stderr";
-
-               if (!(ctl->timingfp = fopen(tname, "w" UL_CLOEXECSTR))) {
-                       restore_tty(ctl, TCSANOW);
-                       warn(_("cannot open %s"), tname);
-                       fail(ctl);
-               }
-       }
-
-
-       if (ctl->typescriptfp)
-               typescript_message_start(ctl, &tvec);
-
-       gettime_monotonic(&ctl->oldtime);
-
        while (!ctl->die) {
                size_t i;
                int errsv;
@@ -737,9 +1033,16 @@ int main(int argc, char **argv)
                .line = "/dev/ptyXX",
 #endif
                .master = -1,
+               .slave  = -1,
+
+               .out = { .ident = 'O' },
+               .in  = { .ident = 'I' },
+
                .poll_timeout = -1
        };
-       int ch;
+       int ch, format = 0;
+       const char *outfile = NULL, *infile = NULL;
+       const char *timingfile = NULL;
 
        enum { FORCE_OPTION = CHAR_MAX + 1 };
 
@@ -749,6 +1052,11 @@ int main(int argc, char **argv)
                {"return", no_argument, NULL, 'e'},
                {"flush", no_argument, NULL, 'f'},
                {"force", no_argument, NULL, FORCE_OPTION,},
+               {"log-in", required_argument, NULL, 'I'},
+               {"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'},
@@ -756,7 +1064,11 @@ int main(int argc, char **argv)
                {"help", no_argument, NULL, 'h'},
                {NULL, 0, NULL, 0}
        };
-
+       static const ul_excl_t excl[] = {       /* rows and cols in ASCII order */
+               { 'T', 't' },
+               { 0 }
+       };
+       int excl_st[ARRAY_SIZE(excl)] = UL_EXCL_STATUS_INIT;
        setlocale(LC_ALL, "");
        /*
         * script -t prints time delays as floating point numbers.  The example
@@ -768,11 +1080,14 @@ int main(int argc, char **argv)
        setlocale(LC_NUMERIC, "C");
        bindtextdomain(PACKAGE, LOCALEDIR);
        textdomain(PACKAGE);
-       atexit(close_stdout);
+       close_stdout_atexit();
 
        script_init_debug();
 
-       while ((ch = getopt_long(argc, argv, "ac:efo:qt::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);
+
                switch (ch) {
                case 'a':
                        ctl.append = 1;
@@ -789,35 +1104,85 @@ int main(int argc, char **argv)
                case FORCE_OPTION:
                        ctl.force = 1;
                        break;
+               case 'B':
+                       log_associate(&ctl, &ctl.in, optarg, SCRIPT_FMT_RAW);
+                       log_associate(&ctl, &ctl.out, optarg, SCRIPT_FMT_RAW);
+                       infile = outfile = optarg;
+                       break;
+               case 'I':
+                       log_associate(&ctl, &ctl.in, optarg, SCRIPT_FMT_RAW);
+                       infile = optarg;
+                       break;
+               case 'O':
+                       log_associate(&ctl, &ctl.out, optarg, SCRIPT_FMT_RAW);
+                       outfile = optarg;
+                       break;
                case 'o':
                        ctl.maxsz = strtosize_or_err(optarg, _("failed to parse output limit size"));
                        break;
                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)
-                               ctl.tname = optarg;
-                       ctl.timing = 1;
+                       if (optarg && *optarg == '=')
+                               optarg++;
+                       log_associate(&ctl, &ctl.out,
+                               optarg ? optarg : "/dev/stderr",
+                               SCRIPT_FMT_TIMING_SIMPLE);
+                       /* used for message only */
+                       timingfile = optarg ? optarg : "stderr";
                        break;
-               case 'V':
-                       printf(UTIL_LINUX_VERSION);
-                       exit(EXIT_SUCCESS);
+               case 'T' :
+                       timingfile = optarg;
                        break;
+               case 'V':
+                       print_version(EXIT_SUCCESS);
                case 'h':
                        usage();
-                       break;
                default:
                        errtryhelp(EXIT_FAILURE);
                }
+       }
        argc -= optind;
        argv += optind;
 
-       if (argc > 0)
-               ctl.fname = argv[0];
-       else {
-               ctl.fname = DEFAULT_TYPESCRIPT_FILENAME;
-               die_if_link(&ctl);
+       /* default if no --log-* specified */
+       if (!outfile && !infile) {
+               if (argc > 0)
+                       outfile = argv[0];
+               else {
+                       die_if_link(&ctl, DEFAULT_TYPESCRIPT_FILENAME);
+                       outfile = DEFAULT_TYPESCRIPT_FILENAME;
+               }
+
+               /* associate stdout with typescript file */
+               log_associate(&ctl, &ctl.out, outfile, SCRIPT_FMT_RAW);
+       }
+
+       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 = 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)
+                       log_associate(&ctl, &ctl.in, timingfile, format);
        }
 
        ctl.shell = getenv("SHELL");
@@ -825,8 +1190,17 @@ int main(int argc, char **argv)
                ctl.shell = _PATH_BSHELL;
 
        getmaster(&ctl);
-       if (!ctl.quiet)
-               printf(_("Script started, file is %s\n"), ctl.fname);
+
+       if (!ctl.quiet) {
+               printf(_("Script started"));
+               if (outfile)
+                       printf(_(", output log file is '%s'"), outfile);
+               if (infile)
+                       printf(_(", input log file is '%s'"), infile);
+               if (timingfile)
+                       printf(_(", timing file is '%s'"), timingfile);
+               printf(_(".\n"));
+       }
        enable_rawmode_tty(&ctl);
 
 #ifdef HAVE_LIBUTEMPTER
@@ -861,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;
        }