Add option to log to file

[mrnugget]

While looking for opinions on file logging for Sidekiq I stumbled upon this comment. So I went ahead and gave it a try.

This is a rather simple solution but mostly just a step towards a discussion around this topic.

So, what do you think? Feedback is welcome!

[mperham]

I'm trying to determine if this really gives us anything valuable that we don't already have. I can redirect stdout to a file or syslog very easily with zero lines of code.

[mrnugget]

I've found that logrotation doesn't work really well with STDOUT redirection, so that's my main angle here. If sidekiq handles its own log file and reopens it on request that would be (at least for me) pretty handy.

But you're absolutely right. This is just a proposal, so if you think the added comfort is not worth the introduction of more complexity and responsibility, that's fine too.

[mperham]

Can you update this PR to implement reopening of stdout for log rotation purposes?

On 11 Dec 2012, at 22:34, Thorsten Ball notifications@github.com wrote:

I've found that logrotation doesn't work really well with STDOUT redirection, so that's my main angle here. If sidekiq handles its own log file and reopens it on request that would be (at least for me) pretty handy.

But you're absolutely right. This is just a proposal, so if you think the added comfort is not worth the introduction of more complexity and responsibility, that's fine too.

—
Reply to this email directly or view it on GitHub.

[mrnugget]

I'd be happy to do it, but what do you mean exactly? Reopening the STDOUT in Sidekiq does not have an impact on a command like this:

bundle exec ../bin/sidekiq -r myapp -r . >> log/sidekiq.log

At least from what I understand and observed, the following happens: when executing the command the STDOUT of Sidekiq gets redirected to a file. Now, let's say a log rotation is happening and sidekiq.log is moved to sidekiq.log.1: the output will now be written to sidekiq.log.1, since the filename changed but not the actual file descriptor used in the above command. That's the main reason why I gave file logging a go. The above command would have to be reevaluated for it to redirect to the new sidekiq.log file after logrotation. And I don't know how that is possible from within Sidekiq, since it just outputs to STDOUT and where that gets redirected to is not within its reach.

But as I said, that's just what I know and observed. Maybe it's possible to get around that. And I'd be happy to do it, but I'd need further explanations on how to do it.

I hacked together a quick solution instantiating a new STDOUT-logger on USR2, but the problem persists: output will be written to sidekiq.log.1. But maybe my solution is wrong too!

[mperham]

@mrnugget You're right, bash is what does the redirection and so it would need to do the rotation. Ugh, bit by bit I'm starting to understand why every Unix daemon has to reimplement this stuff. I'll read through this again tonight and merge it if it looks good. Thanks for helping me understand the issue better!

[mrnugget]

Sounds good! If there's anything that can be done in a better way, any bugs I'm missing, or something else wrong with the code: let me know!

[mrnugget]

I've refactored some of the stuff I wrote. I think it does make more sense now and does not include as much duplication as before. Also: since Sidekiq::CLI now has a initialize_logger method which includes the handling of the --verbose method, I removed the duplication in the actual parse method. In order to do so, without having the tests blowing up with the log messages I adjusted the one concerning the verbose option, I hope that's okay.

There's still some stuff going on in the test concerning blowing up with log messages or not, which I don't fully understand. But as the code is now, no test messages and the file logging, as well as STDOUT logging, and the handling of the USR2 signal (when file logging) works.

So if there's still something I didn't see, which could be better, please tell!

[mperham]

Update the changelog to give yourself some credit. 🍭

[mrnugget]

Great! When this gets merged (I hope the changes in Changes.md won't be a git-merge-conflict-deal-breaker here...) I'll update the Logging-page in the Wiki to reflect the changes. Thanks a lot 👍

[mperham]

Ugh, merge conflict.

[mrnugget]

I rebased this branch onto the current master and force pushed it. Now it shouldn't clash with the changes in Changes.md.

[mperham]

Still says it can't be merged. Hmm.

[mrnugget]

Did another rebase. Somehow some changes didn't get pulled the first time when rebasing. Sorry about that. Does it look better now?

[mperham]

Thanks @mrnugget!

[mrnugget]

Thank you for merging this!

[bradical]

I believe I'm running into the issue described here where, after logrotation, sidekiq is logging to sidekiq.log.1 instead of sidekiq.log. I wasn't really clear on what the solution here provided. Is there some flag I need to pass to sidekiq on startup.

[rmehner]

@bradical are you sending USR2 to your sidekiq processes? That signals sidekiq to reopen the logfiles and it should log to the correct file afterwards.

[bradical]

To be honest, I'm not sure. I'm using logrotate to rotate files. Perhaps I need to adjust my configuration?

/path/to/my/rails/app/log/*.log {
  daily
  missingok
  rotate 8
  compress
  delaycompress
  sharedscripts
}

[mrnugget]

You need to tell logrotate to send the USR2 signal to Sidekiq:

/path/to/my/rails/app/log/*.log {
  daily
  missingok
  rotate 8
  compress
  delaycompress
  sharedscripts
  lastaction
    test -s /path/to/rails/app/tmp/pids/sidekiq.pid && kill -USR2 $(cat /path/to/rails/app/tmp/pids/sidekiq.pid)
  endscript
}

Something like that, depending on your configuration. :) Here's an example for Unicorn, which you can adapt to your needs.

[bradical]

Thanks. I'm not familiar with that signal. Will that actually the kill process? Do I need to start it back up in my logrotate config? Also, was something different done in #1008 for this issue?

[rmehner]

kill with -USR2 just sends a signal to the process, it won't kill it. If you don't give kill a signal as argument it'll send TERM as signal, which will terminate your process by default.

See the manpage of kill: http://linux.die.net/man/1/kill

[bradical]

Thanks for the explanation! I'll give that example Unicorn config a try.

[bradical]

I'm using Sidekiq 2.6.5 and I can't get this to work. I've taken logrotate out of the equation and am doing:

mv sidekiq.log sidekiq.log.bak # sidekiq still writing to the moved log file as expected
pid=/path/to/app/pids/sidekiq.pid
kill -USR2 $(cat $pid)

However, after the command runs, Sidekiq is still writing to sidekiq.log.bak instead of sidekiq.log. I thought this might be related to #1008 (released in v2.13.0) but that issues just seems to be about closing the old logger and not re-opening the new one.

[mperham]

@bradical I believe you are hitting that bug. Time to upgrade.

[bradical]

Thanks @mperham! Will do.