Subject: Re: bug#21760: timeout: Feature Request: --verbose ==> output if timeout

From: Pádraig Brady <[email-masked]>
Date: Thu, 23 Nov 2017 14:35:44 -0800

On 03/10/17 23:36, Pádraig Brady wrote:
> On 02/10/17 07:04, Ian Jackson wrote:
>> I have to say that I find this bug thread quite perplexing.
>>
>> It is completely normal for a GNU/Unix command line utility to print a
>> message to stderr in error cases.  Almost every program that exits
>> nonzero prints a message to stderr.
>>
>> The normal convention in shell scripts (and other contexts where
>> commands are invoked) is to:
>>   * use the exit status to decide whether to continue executing
>>   * rely on the failing command to print a message to the script's
>>     stderr
>>
>> The stderr error message from a failing command appears on the user's
>> terminal in a script run interactively; it appears in emailed logs
>> from cron; it can appear in logfiles; etc.
>>
>> When I first discovered that GNU timeout(1) does not print an error
>> message when the timeout occurs, I was astonished.  IMO that ought to
>> have been the default behaviour.  Unfortunately that is too late to
>> fix now but we should at least have a one-letter option to request
>> behaviour compatible with normal shell programming conventions.
>>
>>
>> The alternative is that at most times when use of timeout is added to
>> some program or config file, the programmer/administrator will have to
>> write a clumsy shell circumlocution to arrange that an appropriate
>> message is sent to stderr.
>>
>> These runic shell circumlocutions will proliferate.  They will have
>> bugs.  The bugs will propagate by cut-and-paste, followed by fixes for
>> the bugs.  Everyone's commands will become verbose and hard to
>> understand.
>>
>> All of this could be prevented by simply providing a way to make
>> timeout print a message to stderr.
>>
>>
>> I guess I need to dispose of some the potential problems which have
>> been advanced as counterarguments, even though to my mind they are
>> extremely weak.
>>
>> A key observation I would make is that the arguments against
>> timeout(1) printing a message are fully general counterarguments
>> against _any_ program printing _any_ error message.  Surely that shows
>> that they can't be right.
>>
>>> For example I don't like the N seconds, or N.012 more detailed
>>> output.  As soon as this is produced there will be other people
>>> trying to parse it.
>>
>> Most of the people who are asking for this feature don't care exactly
>> what the message is.  It should mention the program which was invoked
>> and the fact that there was a timeout.  The exact format is
>> immaterial.
>>
>> The purpose is not for it to be parsed, but for it to be read by
>> humans who are trying to debug something.  This is generally true of
>> error messages.
>>
>> If anyone complains that they are trying to parse this error message
>> you can tell them not to be so silly.  There will be many fewer of
>> those than there will be people inconvenienced by the lack of a
>> message at all.
>>
>> Likewise, if someone sends a patch to add more information to the
>> message, that is not a problem.  You can just accept it, or not, as
>> you like.
>>
>>> BTW: timeout shares stdout/stderr with its child; therefore,
>>> wouldn't the interleaved output be problematic?
>>
>> No.  The purpose is precisely to have the error report from timeout(1)
>> to go to the same place as errors from the command are reported.
>>
>> This is not a problem with any other adverbial command, of which there
>> are very many nowadays.  See for example xargs, fakeroot, faketime,
>> authbind, etc. etc.
>>
>>> A good example of a possible problem due to the law of unintended
>>> consequences.
>>
>> How bogglesome.  This "interleaving" is precisely the intended
>> consequence.  (Actually, what will normally happen is that the message
>> from timeout will follow all of the program's output.)
>>
>>> And if this leads to the request for --output-fd=N to
>>> reroute file descriptors just to work around it then that is much too
>>> much and shouldn't be done.
>>
>> Other adverbial commands have not had such requests and in general I
>> agree that they should be rejected.  If this is a problem then a shell
>> rune can be used to replumb the fds.
>>
>> That is a hypothetical timeout -v --output-fd=42 blah blah
>> can be replaced with
>>    timeout 3>&2 2>&42 -v sh -ec 'exec 2>&3 3>&- "$@"' x blah blah
>> (assuming fd 3 is not used for something else in $@).  This is
>> a fully general technique which can be deployed to implement any
>> such minority use case.
>>
>>
>> The main point is that "want it to print an error message if there is
>> an error" is not a minority use case.
> 
> Thanks for detailing your arguments, and +2 for the phrase:
> "runic shell circumlocutions will proliferate" :)
> 
> A reason we don't output a message by default is that
> timeout(1) could be used to run a process which runs
> for an indeterminate amount of time like:
> 
>   timeout --preserve-status 1d ./simulation
> 
> Whether we support `timeout --verbose` is one of those marginal cases.
> Using shell works with all versions of timeout, but it's not
> trivial due to differing exit status. For example if a SIGKILL was sent
> most shells return 137, while ksh returns 265.
> 
> I agree with you that the stderr interleaving is probably not a practical issue.
> 
> So I'm leaning towards supporting --verbose which would output something like:
> 
>   timeout: aborting command 'blah' with signal SIGTERM
>   timeout: aborting command 'blah' with signal SIGKILL

Handled in the attached.
Marking this as done.

cheers,
Pádraig

>From 9240a4d7d3c4ef9e31325de96ece5904f0884ee2 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?P=C3=A1draig=20Brady?= <[email-masked]>
Date: Thu, 23 Nov 2017 14:30:59 -0800
Subject: [PATCH] timeout: add --verbose to diagnose timeouts

This is useful as handling in shell is complicated
with the varying exit status in the --kill-after case.

* src/timeout.c (main): Handle '-v' and store
COMMAND for the diagnostic.
(cleanup): Diagnose the signal name before sending.
(usage): Document -v, --verbose.
* doc/coreutils.texi (timeout invocation): Likewise.
* tests/misc/timeout.sh: Add a test case.
* NEWS: Mention the new feature
Fixes https://bugs.gnu.org/21760
---
 NEWS                  |  4 ++++
 doc/coreutils.texi    |  6 ++++++
 src/timeout.c         | 20 +++++++++++++++++++-
 tests/misc/timeout.sh |  8 ++++++++
 4 files changed, 37 insertions(+), 1 deletion(-)

diff --git a/NEWS b/NEWS
index bc5d5be..2f387d8 100644
--- a/NEWS
+++ b/NEWS
@@ -31,6 +31,10 @@ GNU coreutils NEWS                                    -*- outline -*-
   timeout would have then waited for the time limit to expire.
   [bug introduced in coreutils-8.27]
 
+** New features
+
+  timeout now supports the --verbose option to diagnose force termination.
+
 ** Improvements
 
   tail --bytes=NUM will efficiently seek to the end of block devices,
diff --git a/doc/coreutils.texi b/doc/coreutils.texi
index d374b4a..57ec227 100644
--- a/doc/coreutils.texi
+++ b/doc/coreutils.texi
@@ -17388,6 +17388,12 @@ the @var{command}.
 Send this @var{signal} to @var{command} on timeout, rather than the
 default @samp{TERM} signal.  @var{signal} may be a name like @samp{HUP}
 or a number.  @xref{Signal specifications}.
+
+@item -v
+@itemx --verbose
+@opindex -v
+@opindex --verbose
+Diagnose to stderr, the signal sent upon timeout.
 @end table
 
 @cindex time units
diff --git a/src/timeout.c b/src/timeout.c
index 5627819..8ba58dd 100644
--- a/src/timeout.c
+++ b/src/timeout.c
@@ -83,6 +83,8 @@ static pid_t monitored_pid;
 static double kill_after;
 static bool foreground;      /* whether to use another program group.  */
 static bool preserve_status; /* whether to use a timeout status or not.  */
+static bool verbose;         /* whether to diagnose timeouts or not.  */
+static char const* command;
 
 /* for long options with no corresponding short option, use enum */
 enum
@@ -95,6 +97,7 @@ static struct option const long_options[] =
 {
   {"kill-after", required_argument, NULL, 'k'},
   {"signal", required_argument, NULL, 's'},
+  {"verbose", no_argument, NULL, 'v'},
   {"foreground", no_argument, NULL, FOREGROUND_OPTION},
   {"preserve-status", no_argument, NULL, PRESERVE_STATUS_OPTION},
   {GETOPT_HELP_OPTION_DECL},
@@ -196,6 +199,14 @@ cleanup (int sig)
       /* Send the signal directly to the monitored child,
          in case it has itself become group leader,
          or is not running in a separate group.  */
+      if (verbose)
+        {
+          char signame[MAX (SIG2STR_MAX, INT_BUFSIZE_BOUND (int))];
+          if (sig2str (sig, signame) != 0)
+            snprintf (signame, sizeof signame, "%d", sig);
+          error (0, 0, _("aborting command %s with signal %s"),
+                 quote (command), signame);
+        }
       send_sig (monitored_pid, sig);
 
       /* The normal case is the job has remained in our
@@ -246,6 +257,8 @@ Start COMMAND, and kill it if still running after DURATION.\n\
                  specify the signal to be sent on timeout;\n\
                    SIGNAL may be a name like 'HUP' or a number;\n\
                    see 'kill -l' for a list of signals\n"), stdout);
+      fputs (_("\
+  -v, --verbose  diagnose to stderr the signal sent upon timeout\n"), stdout);
 
       fputs (HELP_OPTION_DESCRIPTION, stdout);
       fputs (VERSION_OPTION_DESCRIPTION, stdout);
@@ -443,6 +456,10 @@ main (int argc, char **argv)
             usage (EXIT_CANCELED);
           break;
 
+        case 'v':
+          verbose = true;
+          break;
+
         case FOREGROUND_OPTION:
           foreground = true;
           break;
@@ -467,6 +484,7 @@ main (int argc, char **argv)
   timeout = parse_duration (argv[optind++]);
 
   argv += optind;
+  command = argv[0];
 
   /* Ensure we're in our own group so all subprocesses can be killed.
      Note we don't just put the child in a separate group as
@@ -498,7 +516,7 @@ main (int argc, char **argv)
 
       /* exit like sh, env, nohup, ...  */
       int exit_status = errno == ENOENT ? EXIT_ENOENT : EXIT_CANNOT_INVOKE;
-      error (0, errno, _("failed to run command %s"), quote (argv[0]));
+      error (0, errno, _("failed to run command %s"), quote (command));
       return exit_status;
     }
   else
diff --git a/tests/misc/timeout.sh b/tests/misc/timeout.sh
index 1c76589..f75e2be 100755
--- a/tests/misc/timeout.sh
+++ b/tests/misc/timeout.sh
@@ -57,4 +57,12 @@ out=$(sleep .1 & exec timeout .5 sh -c 'sleep 2; echo foo')
 status=$?
 test "$out" = "" && test $status = 124 || fail=1
 
+# Verify --verbose output
+timeout --verbose -s0 -k .1 .1 sleep 10 2> err
+cat > exp <<\EOF
+timeout: aborting command 'sleep' with signal EXIT
+timeout: aborting command 'sleep' with signal KILL
+EOF
+compare exp err || fail=1
+
 Exit $fail
-- 
2.9.3