From: Karel Zak <kzak@redhat.com>
Date: Fri, 12 Apr 2019 14:27:54 +0000 (+0200)
Subject: script: support multi-stream logging
X-Git-Tag: v2.35-rc1~169
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=c1c2ee0b3afec6e05d044b611362d9a5a6966467;p=thirdparty%2Futil-linux.git

script: support multi-stream logging

* allow to use --log-in <infile> and --log-out <outfile> in the same time
* add --log-io <file> to log stdout and stdin to the one log file
* introduce a new timing file format with entry type identifirs

   I <delay> <size>   : info about input stream
   O <delay> <size>   : info about output stream

in the next commits it's possible to add 'S' for signals and 'H' for
extra (header) information.

* the new file format is optional and enabled only if multiple streams
  logging is requested.

Signed-off-by: Karel Zak <kzak@redhat.com>
---

diff --git a/term-utils/script.1 b/term-utils/script.1
index 5d822d498d..75ad24f032 100644
--- a/term-utils/script.1
+++ b/term-utils/script.1
@@ -44,6 +44,10 @@ makes a typescript of everything displayed on your terminal.  It is useful for
 students who need a hardcopy record of an interactive session as proof of an
 assignment, as the typescript file can be printed out later with
 .BR lpr (1).
+Since version 2.35
+.B script
+supports multiple streams and allows to log input and output to separate
+files or all the one file.
 .PP
 If the argument
 .I file
@@ -87,6 +91,12 @@ being done using `cat foo'.
 Allow the default output destination, i.e. the typescript file, to be a hard
 or symbolic link.  The command will follow a symbolic link.
 .TP
+\fB\-B\fR, \fB\-\-log\-io\fR \fIfile\fR
+Log input and output to the same
+\fIfile\fR.  Note, this option makes sense only if \fB\-\-log\-timing\fR is
+also specified, otherwise it's impossible to separate output and input streams from
+the log \fIfile\fR.
+.TP
 \fB\-I\fR, \fB\-\-log\-in\fR \fIfile\fR
 Log input to the \fIfile\fR.  The log output is disabled if only \fB\-\-log\-in\fR
 specified.
@@ -100,12 +110,23 @@ name 'typescript' if the option \fB\-\-log\-out\fR or \fB\-\-log\-in\fR is not
 given.  The log output is disabled if only \fB\-\-log\-in\fR specified.
 .TP
 \fB\-T\fR, \fB\-\-log\-timing\fR \fIfile\fR
-Log timing information to the \fIfile\fR.
+Log timing information to the \fIfile\fR. Two timing file formats are supporte
+now.  The classic format is used when only one stream (input or output) logging
+is enabled. The multi-stream format is used on \fB\-\-log\-io\fR or when
+\fB\-\-log\-in\fR and \fB\-\-log\-out\fR are used together.
 .sp
-This log data contains two fields, separated by a space.  The first
+.RS
+.B Classic format
+.PP
+The log contains two fields, separated by a space.  The first
 field indicates how much time elapsed since the previous output.  The second
-field indicates how many characters were output this time.  This information
-can be used to replay typescripts with realistic typing and output delays.
+field indicates how many characters were output this time.
+.sp
+.B Multi-stream format
+.PP
+The first field is entry type itentifier ('I'nput, 'O'utput, 'H'eader, 'S'ignal).
+The socond field is how much time elapsed since the previous entry, and rest of the entry is type specific data.
+.RE
 .TP
 \fB\-o\fR, \fB\-\-output-limit\fR \fIsize\fR
 Limit the size of the typescript and timing files to
diff --git a/term-utils/script.c b/term-utils/script.c
index 9b5aa778d8..37725162c0 100644
--- a/term-utils/script.c
+++ b/term-utils/script.c
@@ -102,7 +102,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 "<time> <delta>" format */
+	SCRIPT_FMT_TIMING_SIMPLE,	/* timing info in classic "<delta> <offset>" format */
+	SCRIPT_FMT_TIMING_MULTI,	/* multiple streams in format "<type> <delta> <offset|etc> */
 };
 
 struct script_log {
@@ -110,12 +111,15 @@ struct script_log {
 	int	format;			/* SCRIPT_FMT_* */
 	char	*filename;		/* on command line specified name */
 	struct timeval oldtime;		/* previous entry log time */
+
+	unsigned int	initialized : 1;
 };
 
 struct script_stream {
 	struct timeval oldtime;		/* last update */
 	struct script_log **logs;	/* logs where to write data from stream */
 	size_t nlogs;			/* number of logs */
+	char ident;			/* stream identifier */
 };
 
 struct script_control {
@@ -191,6 +195,7 @@ static void __attribute__((__noreturn__)) usage(void)
 	fputs(USAGE_OPTIONS, out);
 	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(_(" -T, --log-timing <file>       log timing information to file\n"), out);
 	fputs(_(" -a, --append                  append the output\n"), out);
 	fputs(_(" -c, --command <command>       run command rather than interactive shell\n"), out);
@@ -227,6 +232,8 @@ static struct script_log *log_associate(struct script_control *ctl,
 {
 	struct script_log *log;
 
+	DBG(MISC, ul_debug("associate %s with stream", filename));
+
 	assert(ctl);
 	assert(filename);
 	assert(stream);
@@ -257,6 +264,9 @@ static void log_close(struct script_control *ctl __attribute__((unused)),
 		      const char *msg,
 		      int status)
 {
+	if (!log->initialized)
+		return;
+
 	DBG(MISC, ul_debug("closing %s", log->filename));
 
 	switch (log->format) {
@@ -280,21 +290,24 @@ static void log_close(struct script_control *ctl __attribute__((unused)),
 		err(EXIT_FAILURE, "write failed: %s", log->filename);
 
 	log->fp = NULL;
+	log->initialized = 0;
 }
 
 static void log_start(struct script_control *ctl,
 		      struct script_log *log)
 {
-
-	assert(log->fp == NULL);
+	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);
+			"a" UL_CLOEXECSTR :
+			"w" UL_CLOEXECSTR);
 	if (!log->fp) {
 		restore_tty(ctl, TCSANOW);
 		warn(_("cannot open %s"), log->filename);
@@ -335,9 +348,12 @@ static void log_start(struct script_control *ctl,
 		gettime_monotonic(&log->oldtime);
 		break;
 	}
+
+	log->initialized = 1;
 }
 
 static size_t log_write(struct script_control *ctl,
+		      struct script_stream *stream,
 		      struct script_log *log,
 		      char *obuf, size_t bytes)
 {
@@ -368,6 +384,21 @@ static size_t log_write(struct script_control *ctl,
 		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"));
+
+		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;
 	}
@@ -387,7 +418,7 @@ static uint64_t log_stream_activity(
 	uint64_t outsz = 0;
 
 	for (i = 0; i < stream->nlogs; i++)
-		outsz += log_write(ctl, stream->logs[i], buf, bytes);
+		outsz += log_write(ctl, stream, stream->logs[i], buf, bytes);
 
 	return outsz;
 }
@@ -885,9 +916,12 @@ int main(int argc, char **argv)
 		.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;
 
@@ -901,6 +935,7 @@ int main(int argc, char **argv)
 		{"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'},
 		{"output-limit", required_argument, NULL, 'o'},
 		{"quiet", no_argument, NULL, 'q'},
@@ -929,7 +964,7 @@ int main(int argc, char **argv)
 
 	script_init_debug();
 
-	while ((ch = getopt_long(argc, argv, "ac:efI:O:o:qT:t::Vh", longopts, NULL)) != -1) {
+	while ((ch = getopt_long(argc, argv, "aB:c:efI:O:o:qT:t::Vh", longopts, NULL)) != -1) {
 
 		err_exclusive_options(ch, longopts, excl, excl_st);
 
@@ -949,6 +984,11 @@ 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;
@@ -973,7 +1013,6 @@ int main(int argc, char **argv)
 			timingfile = optarg ? optarg : "stderr";
 			break;
 		case 'T' :
-			log_associate(&ctl, &ctl.out, optarg, SCRIPT_FMT_TIMING_SIMPLE);
 			timingfile = optarg;
 			break;
 		case 'V':
@@ -1000,6 +1039,17 @@ int main(int argc, char **argv)
 		log_associate(&ctl, &ctl.out, outfile, SCRIPT_FMT_RAW);
 	}
 
+	if (timingfile) {
+		if (!format)
+			format = outfile && infile ?
+					SCRIPT_FMT_TIMING_MULTI :
+					SCRIPT_FMT_TIMING_SIMPLE;
+		if (outfile)
+			log_associate(&ctl, &ctl.out, timingfile, format);
+		if (infile)
+			log_associate(&ctl, &ctl.in, timingfile, format);
+	}
+
 	ctl.shell = getenv("SHELL");
 	if (ctl.shell == NULL)
 		ctl.shell = _PATH_BSHELL;