piping stderr

piping stderr

[Atom Smasher]

i'd like to pipe all stderr from a script into a command to do logging... 
but this isn't synchronous:
 	exec 2> >( multilog /path/ )

i need it to be synchronous so that multiple scripts running at the same 
time (and also logging debug messages) can all log together and not 
clobber each others output.

is it possible to do what i'm trying?

thanks...


-- 
         ...atom

  ________________________
  http://atom.smasher.org/
  762A 3B98 A3C3 96C9 C6B7 582A B88D 52E4 D9F5 7808
  -------------------------------------------------

 	"America may be the best country in the world, but that's
 	 kind of like being the valedictorian of summer school."
 		-- Dennis Miller

Re: piping stderr

[Bart Schaefer]

On Thu, May 14, 2009 at 3:49 AM, Atom Smasher <atom@smasher.org> wrote:
> i'd like to pipe all stderr from a script into a command to do logging...
> but this isn't synchronous:
>        exec 2> >( multilog /path/ )
>
> i need it to be synchronous so that multiple scripts running at the same
> time (and also logging debug messages) can all log together and not clobber
> each others output.

I'm not sure what you think "synchronous" implies here.  Within a
particular "instance" of zsh, such as a single running script,
commands can be synchronous in the sense that zsh waits for the
command to finish before going on to the next one.  However, multiple
scripts "running at the same time" already implies that the zsh
instances are asynchronous with respect to one another, so no command
started by a particular zsh instance will be synchronous with respect
to other instances (unless you employ some sort of external locking
scheme, but then you're just preventing the scripts from "running at
the same time").

That said ... have you tried your example above?  I'd be mildly
surprised if multilog doesn't already do something to assure that
multiple loggers don't clobber one another's output.  They might
intermingle their output, in which case you need to tag each line of
it with a PID or some such, but Dan Bernstein is generally pretty
compulsive about preventing data loss.

Re: piping stderr

[Atom Smasher]

On Thu, 14 May 2009, Bart Schaefer wrote:

> On Thu, May 14, 2009 at 3:49 AM, Atom Smasher <atom@smasher.org> wrote:
>> i'd like to pipe all stderr from a script into a command to do logging...
>> but this isn't synchronous:
>>        exec 2> >( multilog /path/ )
>>
>> i need it to be synchronous so that multiple scripts running at the 
>> same time (and also logging debug messages) can all log together and 
>> not clobber each others output.
>
> I'm not sure what you think "synchronous" implies here.  Within a 
> particular "instance" of zsh, such as a single running script, commands 
> can be synchronous in the sense that zsh waits for the command to finish 
> before going on to the next one.  However, multiple scripts "running at 
> the same time" already implies that the zsh instances are asynchronous 
> with respect to one another, so no command started by a particular zsh 
> instance will be synchronous with respect to other instances (unless you 
> employ some sort of external locking scheme, but then you're just 
> preventing the scripts from "running at the same time").
==============

among different scripts (different invocations of the same script) things 
are wildly asynchronous. but within each script, which is logging debug 
output into multilog, i want to make sure that the stderr and debug 
messages appear in the right order. this script shows how that doesn't 
(always) happen:

  #!/bin/zsh

  exec 2> >(rot13)

  date
  dattxxx
  date
  dattxxx
  date
  dattxxx
  date
  dattxxx

the "dattxxx" commands are there to produce "command not found" errors on 
stderr. with zsh 4.2.1 the redirect into a coproc makes it just hang.


> That said ... have you tried your example above?  I'd be mildly 
> surprised if multilog doesn't already do something to assure that 
> multiple loggers don't clobber one another's output.  They might 
> intermingle their output, in which case you need to tag each line of it 
> with a PID or some such, but Dan Bernstein is generally pretty 
> compulsive about preventing data loss.
============

if there's one thing multilog does, it makes sure that multiple inputs 
don't clobber each other. i am tagging each line with a PID so i can grep 
out a particular process and see what's going on.

the problem i'm seeing with the script above, and variations on it, is 
that sometimes the output is in the right order, but sometimes all of 
stdout appears, followed by all of stderr.


-- 
         ...atom

  ________________________
  http://atom.smasher.org/
  762A 3B98 A3C3 96C9 C6B7 582A B88D 52E4 D9F5 7808
  -------------------------------------------------

 	"HEY! HO! LET'S GO!"
 		-- The Ramones

Re: piping stderr

[Kurtis Rader]

The behavior you're seeing is due to how the Unix stdio library buffers 
output. The stderr stream is always line buffered by default. When the 
file descriptor is open on a tty both stdout is line buffered. When 
directed to a pipe, fifo, or file stdout is fully buffered. Which means 
that when you redirect the output to a file or a coprocess (which sends 
the output through a pipe) the stderr output will typically be seen 
first because it is flushed as soon as an entire line is written. But 
even that isn't guaranteed since if the program writes a large amount of 
data to stdout some or all of the data could be flushed before the first 
line is written to stderr. The only reliable way to solve this is to 
redirect the output to a pty (psuedo-tty). One way is to use the 
script(1) command to run your script and capture its output.

On 09-05-15 04:47, Atom Smasher wrote:
> On Thu, 14 May 2009, Bart Schaefer wrote:
>
>> On Thu, May 14, 2009 at 3:49 AM, Atom Smasher <atom@smasher.org> wrote:
>>> i'd like to pipe all stderr from a script into a command to do
>>> logging...
>>> but this isn't synchronous:
>>> exec 2> >( multilog /path/ )
>>>
>>> i need it to be synchronous so that multiple scripts running at the
>>> same time (and also logging debug messages) can all log together and
>>> not clobber each others output.
>>
>> I'm not sure what you think "synchronous" implies here. Within a
>> particular "instance" of zsh, such as a single running script,
>> commands can be synchronous in the sense that zsh waits for the
>> command to finish before going on to the next one. However, multiple
>> scripts "running at the same time" already implies that the zsh
>> instances are asynchronous with respect to one another, so no command
>> started by a particular zsh instance will be synchronous with respect
>> to other instances (unless you employ some sort of external locking
>> scheme, but then you're just preventing the scripts from "running at
>> the same time").
> ==============
>
> among different scripts (different invocations of the same script)
> things are wildly asynchronous. but within each script, which is logging
> debug output into multilog, i want to make sure that the stderr and
> debug messages appear in the right order. this script shows how that
> doesn't (always) happen:
>
> #!/bin/zsh
>
> exec 2> >(rot13)
>
> date
> dattxxx
> date
> dattxxx
> date
> dattxxx
> date
> dattxxx
>
> the "dattxxx" commands are there to produce "command not found" errors
> on stderr. with zsh 4.2.1 the redirect into a coproc makes it just hang.
>
>
>> That said ... have you tried your example above? I'd be mildly
>> surprised if multilog doesn't already do something to assure that
>> multiple loggers don't clobber one another's output. They might
>> intermingle their output, in which case you need to tag each line of
>> it with a PID or some such, but Dan Bernstein is generally pretty
>> compulsive about preventing data loss.
> ============
>
> if there's one thing multilog does, it makes sure that multiple inputs
> don't clobber each other. i am tagging each line with a PID so i can
> grep out a particular process and see what's going on.
>
> the problem i'm seeing with the script above, and variations on it, is
> that sometimes the output is in the right order, but sometimes all of
> stdout appears, followed by all of stderr.
>
>

coloring stderr - was Re: piping stderr

[Atom Smasher]

this has me thinking about an old problem... coloring stderr. the two 
problems i've found previously are (1) keeping stdout and stderr in sync, 
and (2) stderr that doesn't end with a newline, such as messages from "rm 
-i".

this [below] fixes the second problem, but it's still got some unintended 
consequences... the problem i'm having now with it is that if i start bash 
as a child of zsh, bash is a bit messed up. if i start a bourne shell 
(which doesn't actually exist on most/all linux distros, so don't bother 
testing it there) i can see that PS1 is going through stderr, as it's 
being piped the zsh's "color_err" function. if i start a few levels of zsh 
children all with this function, i'm not even sure i want to know how ugly 
things are under the hood. of course all children of the process will have 
their stderr going through this, but with interactive applications that 
can result in some weird stuff...

## colorize std_err
zmodload zsh/terminfo zsh/system
autoload colors is-at-least
if [[ "${terminfo[colors]}" -ge 8 ]] { colors }
color_err () {
   ## sysread & syswrite are part of zsh/system
    while sysread std_err_color
    do
      syswrite -o 2 "${fg_bold[red]}${std_err_color}${terminfo[sgr0]}"
    done
}
## i'm not sure exactly how far back it's safe to go with this
## 4.3.4 works; 4.2.1 hangs.
is-at-least 4.3.4 && exec 2> >( color_err )


-- 
         ...atom

  ________________________
  http://atom.smasher.org/
  762A 3B98 A3C3 96C9 C6B7 582A B88D 52E4 D9F5 7808
  -------------------------------------------------

 	"I believe that banking institutions are more dangerous
 	 to our liberties than standing armies."
 		-- Thomas Jefferson

Re: coloring stderr - was Re: piping stderr

[Atom Smasher]

http://smasher.org/tmp/snapshot152.png

another unintended consequence of redirecting stderr in an interactive 
shell... note that "cal" is actually "gcal".


-- 
         ...atom

  ________________________
  http://atom.smasher.org/
  762A 3B98 A3C3 96C9 C6B7 582A B88D 52E4 D9F5 7808
  -------------------------------------------------

 	"It is well enough that people of the nation do not
 	 understand our banking and monetary system, for if
 	 they did, I believe there would be a revolution before
 	 tomorrow morning."
 		-- Henry Ford

Re: coloring stderr - was Re: piping stderr

[Vincent Lefevre]

[-- Attachment #1: Type: text/plain, Size: 1312 bytes --]

On 2009-05-16 12:25:50 +1200, Atom Smasher wrote:
> this has me thinking about an old problem... coloring stderr. the two 
> problems i've found previously are (1) keeping stdout and stderr in sync, 
> and (2) stderr that doesn't end with a newline, such as messages from "rm 
> -i".
> 
> this [below] fixes the second problem,

I also solved the second problem a few years ago (see my solution in C,
attached). But I've checked again... the first problem is not solved by
my solution:

$ echo L1; echo L2 >&2; echo L3; echo L4 >&2
L1
L3
L2
L4

Also I disabled stderr coloring because some programs do not use stderr
consistently and I had various problems with them (perhaps because of
lack of synchronization).

> but it's still got some unintended consequences... the problem i'm
> having now with it is that if i start bash as a child of zsh, bash
> is a bit messed up.

I can notice that the bash prompt doesn't appear, because bash has
not been started in interactive mode ('i' is not in "$-"). If I force
interactive mode, I get:

prunille:~> bash -i
zsh: suspended (tty input)  bash -i

-- 
Vincent Lefèvre <vincent@vinc17.org> - Web: <http://www.vinc17.org/>
100% accessible validated (X)HTML - Blog: <http://www.vinc17.org/blog/>
Work: CR INRIA - computer arithmetic / Arenaire project (LIP, ENS-Lyon)

[-- Attachment #2: colorize.c --]
[-- Type: text/plain, Size: 2843 bytes --]

/* $Id: colorize.c 29330 2009-05-18 00:27:09Z vinc17/prunille $
 *
 * Colorize the standard input. Written for zsh stderr coloring.
 *
 * Bug: stdout and stderr are not synchronized. For instance,
 *   $ echo L1; echo L2 >&2; echo L3; echo L4 >&2
 *   L1
 *   L3
 *   L2
 *   L4
 */

#include <stdio.h>
#include <stdlib.h>
#include <limits.h>
#include <errno.h>
#include <signal.h>
#include <unistd.h>
#include <fcntl.h>
#include <sys/select.h>
#include <sys/types.h>

#define BUFFSIZE 512

static volatile sig_atomic_t usr1;

static void sigusr1(int sig)
{
  usr1 = 1;
}

static void writepid(char *tmpfile)
{
  FILE *f;

  f = fopen(tmpfile, "w");
  if (f == NULL)
    {
      perror("colorize (fopen)");
      exit(EXIT_FAILURE);
    }
  fprintf(f, "%ld\n", (long) getpid());
  if (fclose(f) != 0)
    {
      perror("colorize (fclose)");
      exit(EXIT_FAILURE);
    }
}

int main(int argc, char **argv)
{
  pid_t zshpid = 0;
  char *begstr, *endstr;
  fd_set rfds;
  int ret;

  if (argc != 3 && argc != 5)
    {
      fprintf(stderr,
              "Usage: colorize <begstr> <endstr> [ <zshpid> <tmpfile> ]\n");
      exit(EXIT_FAILURE);
    }

  /* Assume that the arguments are correct. Anyway, it is not possible
     to check them entirely. */
  begstr = argv[1];
  endstr = argv[2];
  if (argc == 5)
    {
      /* To do the synchronization with the zsh prompt output...
         Seems to be useless in practice, hence the argc == 3 case. */
      zshpid = atol(argv[3]);
      signal(SIGUSR1, sigusr1);
      writepid(argv[4]);
    }

  fcntl(0, F_SETFL, fcntl(0, F_GETFL) | O_NONBLOCK);

  /* To watch stdin (fd 0). */
  FD_ZERO(&rfds);
  FD_SET(0, &rfds);

  for (;;)
    {
      ret = select(1, &rfds, NULL, NULL, NULL);

      if (ret < 0 && errno != EINTR)
        {
          perror("colorize (pselect)");
          exit(EXIT_FAILURE);
        }

      if (ret > 0)
        {
          static unsigned char buffer[BUFFSIZE];
          static int dontcol = 0;
          ssize_t n;

          while ((n = read(0, buffer, BUFFSIZE)) >= 0)
            {
              ssize_t i;

              if (n == 0)
                return 0;  /* stdin has been closed */
              for (i = 0; i < n; i++)
                {
                  if (buffer[i] == 27)
                    dontcol = 1;
                  if (buffer[i] == '\n')
                    dontcol = 0;
                  if (!dontcol)
                    fputs(begstr, stdout);
                  putchar(buffer[i]);
                  if (!dontcol)
                    fputs(endstr, stdout);
                }
            }
          fflush(stdout);
        }

      if (usr1)
        {
          usr1 = 0;
          if (kill(zshpid, SIGUSR1) != 0)
            {
              perror("colorize (kill)");
              exit(EXIT_FAILURE);
            }
        }
    }
}

Re: coloring stderr - was Re: piping stderr

[Atom Smasher]

On Mon, 18 May 2009, Vincent Lefevre wrote:

>> but it's still got some unintended consequences... the problem i'm 
>> having now with it is that if i start bash as a child of zsh, bash is a 
>> bit messed up.
>
> I can notice that the bash prompt doesn't appear, because bash has not 
> been started in interactive mode ('i' is not in "$-"). If I force 
> interactive mode, I get:
>
> prunille:~> bash -i
> zsh: suspended (tty input)  bash -i
=================

yeah, that counts as messed up ;)

http://smasher.org/tmp/snapshot153.png

it's not every day that something on the command line dies from SIGTTIN.

back to the drawing board....


-- 
         ...atom

  ________________________
  http://atom.smasher.org/
  762A 3B98 A3C3 96C9 C6B7 582A B88D 52E4 D9F5 7808
  -------------------------------------------------

 	"That's hard to tell. I think that, you know, I would hope
 	 to be able to convince people I could handle the Iraqi
 	 situation better."
 		-- George "dubya" Bush
 		Bush-Gore debate, 11 Oct 2000