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

From: [email-masked] (GNU bug Tracking System)
Date: Thu, 23 Nov 2017 22:36:02 +0000

Your bug report

#21760: timeout: Feature Request: --verbose ==> output if timeout was reached

which was filed against the coreutils package, has been closed.

The explanation is attached below, along with your original report.
If you require more details, please reply to [email-masked].

-- 
21760: http://debbugs.gnu.org/cgi/bugreport.cgi?bug=21760
GNU Bug Tracking System
Contact [email-masked] with problems

Subject: Re: bug#21760: timeout: Feature Request: --verbose ==> output if timeout
From: Pádraig Brady <[email-masked]>
To: Ian Jackson <[email-masked]>, [email-masked]
Date: Thu, 23 Nov 2017 14:35:44 -0800
List-Id: <debbugs-submit.debbugs.gnu.org>

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

Subject: timeout: Feature Request: --verbose ==> output if timeout was reached
From: Thomas Güttler <[email-masked]>
To: [email-masked]
Date: Mon, 26 Oct 2015 11:30:36 +0100
List-Id: <debbugs-submit.debbugs.gnu.org>

About commandline tool "timeout": Start COMMAND, and kill it if still running after DURATION.

A new team mate wasted some time to debug why
a process was killed with signal 15.

I think it would be nice to have an --verbose option, and a some
text which explains why the signal was send.

This is important in environments where the one who reads
the script failures is not the same person who writes the script.

What do you think?

Example:

Old:

   user@host:~$ timeout 1s ping localhost
   PING localhost (127.0.0.1) 56(84) bytes of data.
   64 bytes from localhost (127.0.0.1): icmp_seq=1 ttl=64 time=0.078 ms

New:

   user@host:~$ timeout 1s ping localhost
   PING localhost (127.0.0.1) 56(84) bytes of data.
   64 bytes from localhost (127.0.0.1): icmp_seq=1 ttl=64 time=0.078 ms
   ** Process "ping localhost" was killed with signal 16 since the timeout of 1s was reached. **

-- 
Thomas Guettler http://www.thomas-guettler.de/