Project

General

Profile

Bug #11460

logadm docmd() can't handle too much on stderr

Added by Mike Gerdts 5 months ago. Updated 5 months ago.

Status:
Closed
Priority:
Normal
Assignee:
Category:
cmd - userland programs
Start date:
Due date:
% Done:

100%

Estimated time:
Difficulty:
Bite-size
Tags:

Description

As described at https://smartos.org/bugview/OS-3772, logadm:

1. Creates a pipe for child stderr
2. Forks a child to run a command
3. Waits for the command to exit
4. Reads from the pipe.

If the child needs to write more to stderr than the pipe can buffer, logadm is deadlocked waiting for the child to die while the child is waiting for logadm to free some space in the pipe. It does this while holding a file lock on the logadm config and timstamp files, preventing any other logadm commands from doing their own log rotation or config file updates.

History

#1

Updated by Mike Gerdts 5 months ago

  • Subject changed from logadm docmd() can't handle too much stdout or stderr to logadm docmd() can't handle too much on stderr
#2

Updated by Mike Gerdts 5 months ago

  • Description updated (diff)
#3

Updated by Mike Gerdts 5 months ago

This bug can be reproduced with:

# rm -f /var/tmp/foo.log*

# echo stuff > /var/tmp/foo.log

# truss -f -t \!nanosleep logadm -v -p now -b 'exec 1>&2; for i in {1..2500}; do echo $i blah blah blah; done' /var/tmp/foo.log
...
16503:    write(1, " 8 6 8   b l a h   b l a".., 19)    = 19
16502:    waitid(P_PID, 16503, 0x0803EFE0, WEXITED|WTRAPPED) (sleeping...)
16503:    write(1, 0x0894D3E0, 19)    (sleeping...)

With the fix, the command runs to completion, prints the proper number of lines of output, and only prints the "Warning" line once.

root@bloody:/home/mgerdts# rm -f /var/tmp/foo.log*; echo stuff > /var/tmp/foo.log; \
    logadm -v -p now -b 'exec 1>&2; for i in {1..250000}; do echo blah blah blah; done' /var/tmp/foo.log 2>&1 | uniq -c
   1 # loading /etc/logadm.conf
   1 # processing logname: /var/tmp/foo.log
   1 #     using default expire rule: -C10
   1 #     using default template: $file.$n
   1 sh -c exec 1>&2; for i in {1..250000}; do echo blah blah blah; done # -b cmd
   1 logadm: Warning: command failed: /bin/sh -c exec 1>&2; for i in {1..250000}; do echo blah blah blah; done
250000 blah blah blah
   1 mkdir -p /var/tmp # verify directory exists
   1 mv -f /var/tmp/foo.log /var/tmp/foo.log.0 # rotate log file
   1 touch /var/tmp/foo.log
   1 chown 0:0 /var/tmp/foo.log
   1 chmod 644 /var/tmp/foo.log
   1 #     recording rotation date Wed Jul 17 13:01:46 2019 for /var/tmp/foo.log
   1 # writing changes to /var/logadm/timestampsaxaG2d

If the child does not write to stderr, stdout is printed and no warning is printed.

root@bloody:/home/mgerdts# rm -f /var/tmp/foo.log*; echo stuff > /var/tmp/foo.log; \
    logadm -v -p now -b ' for i in {1..250000}; do echo blah blah blah; done' /var/tmp/foo.log 2>&1 | uniq -c
   1 # loading /etc/logadm.conf
   1 # processing logname: /var/tmp/foo.log
   1 #     using default expire rule: -C10
   1 #     using default template: $file.$n
   1 sh -c  for i in {1..250000}; do echo blah blah blah; done # -b cmd
250000 blah blah blah
   1 mkdir -p /var/tmp # verify directory exists
   1 mv -f /var/tmp/foo.log /var/tmp/foo.log.0 # rotate log file
   1 touch /var/tmp/foo.log
   1 chown 0:0 /var/tmp/foo.log
   1 chmod 644 /var/tmp/foo.log
   1 #     recording rotation date Wed Jul 17 13:02:14 2019 for /var/tmp/foo.log
   1 # writing changes to /var/logadm/timestampsqmaO3d

It still mails errors if the -e option is used.

root@bloody:/home/mgerdts# cp /dev/null /var/mail/root
root@bloody:/home/mgerdts# rm -f /var/tmp/foo.log*; echo stuff > /var/tmp/foo.log; \
    logadm -e root -p now -b 'exec 1>&2; for i in {1..250000}; do echo blah blah blah; done' /var/tmp/foo.log 2>&1 | uniq -c
   1 logadm: Warning: command failed: /bin/sh -c exec 1>&2; for i in {1..250000}; do echo blah blah blah; done
250000 blah blah blah
root@bloody:/home/mgerdts# grep blah /var/mail/root | uniq -c
   1 logadm: Warning: command failed: /bin/sh -c exec 1>&2; for i in {1..250000}; do echo blah blah blah; done
250000 blah blah blah
You have mail in /var/mail/root
root@bloody:/home/mgerdts#

All existing and new automated tests pass.

$ bldenv $(git root)/../nondebug.sh
$ make test
...
/usr/bin/perl -w ./tester `pwd`
Running conftest1...pass
Running conftest2...pass
Running globtest1...pass
Running globtest2...pass
Running kwtest1...pass
Running kwtest2...pass
Running luttest1...pass
Running optstest1...pass
Running optstest2...pass
Running logadmV1...pass
Running logadmV2...pass
Running logadmr...pass
Running logadmw...pass
Running logadm1...pass
Running logadm1c...pass
Running logadm2...pass
Running logadm3...pass
Running logadm4...pass
Running logadm5...pass
Running logadm6...pass
Running logadm7...pass
Running logadm8...pass
Running logadm9...pass
Running logadm9d...pass
Running logadm10...pass
Running logadm11...pass
Running logadm12...pass
Running logadm13...pass
Running logadm14...pass
Running logadm15...pass
Running logadm16...pass
Running logadm17...pass
Running logadm18...pass
Running logadm19...pass
Running logadm20...pass
Running logadm21...pass
Running logadm22...pass
Running logadm23...pass
Running stderr1...pass
#4

Updated by Electric Monk 5 months ago

  • Status changed from New to Closed
  • % Done changed from 0 to 100

git commit d5dace520a9f491fa6261d247f92b69fc3a5c7f5

commit  d5dace520a9f491fa6261d247f92b69fc3a5c7f5
Author: Mike Gerdts <mike.gerdts@joyent.com>
Date:   2019-07-19T21:07:05.000Z

    11460 logadm docmd() can't handle too much on stderr
    Reviewed by: Toomas Soome <tsoome@me.com>
    Reviewed by: Jason King <jason.king@joyent.com>
    Reviewed by: Andy Fiddaman <omnios@citrus-it.co.uk>
    Approved by: Robert Mustacchi <rm@joyent.com>

Also available in: Atom PDF