Confusing newsyslog R flag

[spky]

Somehow I am puzzled by newsyslog.

Background/Situation:
I have some cronjob that runs every two minutes and (sometimes) produces output. I do not want receive a mail every two minutes, but once daily. So I thought I will use newsyslog for this job.

Crontab:

 */2  *   *   *   *   /usr/home/user/code/verify.sh >> /var/log/verify.log 2>&1

/usr/local/etc/newsyslog.conf.d/verify.conf:

# logfilename          [owner:group]    mode count size when  flags [/pid_file] [sig_num]
/var/log/verify.log                     644  4     *    @T00  BCXR  /usr/home/user/code/verify_mailer.sh

Inside verify_mailer.sh I do some xzcat onto /var/log/verify.log.0.xz and pipe that (with more E-Mail stuff) into some sendmail -t command.

All those scripts do work, mail setup works as well, that is not the issue.

The thing I am puzzled:

The man page newsyslog.conf(5) states:

R if this flag is set the newsyslog(8) will run shell command defined in path_to_pid_cmd_file after rotation instead of trying to send signal to a process id stored in the file.

run shell command [...] after rotation

Any time verify_mailer.sh is executed via newsyslog it states that /var/log/verify.log.0.xz does not exist.
I tried to introduce some sleep, but the behaviour is the same.

Is the man page wrong? Should I increase the sleep (currently 10 seconds, it's not much text, max. 1000 lines, that should be enough time).
What am I missing here?
Thanks for your help!

 

[dkh]

Hard to say without know what it is in verify_mailer.sh.

The manual page is correct - it runs the command after rotation.

I expect it's something simple - I'd recommend doing some basic debugging - say have verify_mailer.sh drop the current time stamp followed by the directory listing for /var/log into a run log somewhere.

What command/test is reporting that the log file doesn't exist? How are you testing for that? Could you be testing against a value that doesn't actually contain /var/log/verify.log.0.xz but reporting out that that that file doesn't exist (ie do you test against $FILE but echo out "/var/log/verify.log.0.xz doesn't exist" rather than "'$FILE' doesn't exist")?

 

[spky]

Debugging by outputting some simple ls alongside some timestamp is a great idea. Thanks..

According to the scripts: It's more complicated than in the example above..
The source is here: https://github.com/spookey/dirty_little_helpers/tree/dev/newsys_mail

verify_mailer.sh would be some variant of example_wrapper.sh with my mail addresses filled in, as well as
the LOG_FILE="/var/log/verify.log.0.xz".

It's in the making, so they might change any time (At least the branch will vanish when merged back to main branch).

What command/test is reporting that the log file doesn't exist? How are you testing for that?

Simple:
It's just some plain

[ ! -f "$LOG_FILE" ] && _fatal "log file" "$LOG_FILE" "does not exist"

whereas _fatal is

_msg() { >&2 echo "$*"; }
_fatal() { _msg "$*"; exit 1; }

And that error message "log file /var/log/verify.log.0.xz does not exist" is all I get in the mail when the scripts are invoked by newsyslog.

(ie do you test against $FILE but echo out "/var/log/verify.log.0.xz doesn't exist" rather than "'$FILE' doesn't exist")?

I think not. I tend to use shellcheck a lot. It would warn me about mistakes like this.

If I start the mailing manually everything works.

My hunch (and reason why I'm asking here) is that newsyslog does indeed call path_to_pid_cmd_file before rotation is done.

Tonight I will change the setup to try to mail me the non rotated version of the script to see if that works (/var/log/verify.log instead of /var/log/verify.log.0.xz).

 

[SirDice]

I expect it's something simple - I'd recommend doing some basic debugging - say have verify_mailer.sh drop the current time stamp followed by the directory listing for /var/log into a run log somewhere.

Debugging by outputting some simple ls alongside some timestamp is a great idea. Thanks..

Another way of debugging shell scripts is to run it with /bin/sh -x.

     -x xtrace
             Write each command (preceded by the value of the PS4 variable
             subjected to parameter expansion and arithmetic expansion) to
             standard error before it is executed.  Useful for debugging.

 

[spky]

Okay, I figured out something.

Thanks for all the hints about debugging inside shell scripts - but as I said - the scripts are not the issue.
They work fine when manually invoked.
Only when run by newsyslog the issues occur.

Recap:

• I have some task every two minutes inside the crontab that appends some lines to some logfile.
• Second there is a statement for newsyslog that rotates the logfile.
  • It is calling some wrapper script when rotating.
• The wrapper script then calls the mailer script.
  • Which reads in the logfile.0.xz and pipes it into sendmail -t (more or less).

There are two things that do the trick:

• Inside the mailer script I do some sleep before it reads the logfile.0.xz.
  • Initially it was set to 10 seconds which does not seem to be enough. Bumping it to 60 seconds now works reliably.
• Invoking the mailer script from the wrapper script in a subshell finally works.
  • For newsyslog the wrapper script immediately returns so it can continue rotating files.
  • So the mailer script sleeps asynchronously for the logfile to be rotated.

It boils down to a three character bugfix - Changing the sleep argument from 10 to 60 and itroducing the & character when calling the mailer script. \o/

It seems that newsyslog.conf(5) for the R flag is correct - The script is indeed launched after rotation.
But it takes time to rotate the existing files around, and it seems to block, waiting for the invoked script to finish.

Thanks for all your help, and being my debugging rubber ducks