Nova services do not log to new log file after log rotation

[Jordan Rinke]

When log rotation is setup for /var/log/nova the Nova services will not log to the new file after log rotation occurs.

For instance, you have Nova-Compute running and it is logging to /var/log/nova/nova-compute.log, log rotation occurs and moves the file to nova-compute.log.1 and creates a new file named nova-compute.log. Nova-Compute continues to log in the nova-compute.log.1 file (I have seen this as deep as 4 rotations, so nova-compute.log.4) leaving the nova-compute.log file empty. Stopping and starting the service makes it start logging to the proper file again.

This occurs with all of the Nova services.

[Todd Willey (xtoddx)]

Can you paste your logrotate config somewhere public?

[Jordan Rinke (jordanrinke)]

It is the default log rotation config in Ubuntu 10.x with a Nova specific addition (I assume added by the PPA since I did not add it)

http://paste.openstack.org/show/124/

[Ryan Lucio (rlucio)]

I actually just finally looked into this issue myself because another symptom of this bug is that you end up with a bazillion log files after a few weeks. Here's my understanding of the issue:

- Nova's logging does not support log rotation, because it currently opens the logfile at launch and holds that one filehandle for the duration of the daemon's existence. When logrotate runs, the file descriptor changes but nova never finds out. One way to deal with this would be to allow nova daemons to reopen the logfile file handle when it receives a SIGHUP. See nova/server.py for the logging setup.

- The logrotate script is included with Soren's ppa-lucid branch and is not part of trunk. I assume it was an afterthought, because the configuration simply tells logrotate to rotate *every* file in the /var/log/nova directory. So even the rotated logs get rotated.

- There is one possible workaround: If you don't include the --logfile flag but set --use_syslog=1 then the nova daemon will log to syslog, so logrotate should work OK.

[Todd Willey (xtoddx)]

I'm reassigning this to Soren for review of the logrotate issues. It may be as simple as using the "copytruncate" configuration to get it working.

If we want support for HUP to re-open log files, make a blueprint and assign it to me and I'll include it with the logging changes I need to push to trunk (from ~anso/nova/deploy).

[Ryan Lucio (rlucio)]

Todd: WRT supporting HUP I don't have any particular preference. If copytruncate works that is fine for me. In fact I'll test that out right now.

This is what I will be testing in /etc/logrotate.d/nova-common:

/var/log/nova/*.log {
daily
missingok
copytruncate
postrotate
}

[Ryan Lucio (rlucio)]

I am currently testing on Austin release, and finally settled on this:

/var/log/nova/*.log {
  daily
  missingok
  rotate 7
  compress
  delaycompress
  copytruncate
}

The rotation works great now. However, the scheduler and the objectstore logs both log a bunch of junk the first time they write to their logfiles each day. "^@^@^@^@^@^@^@^@^@" repeated many times. Not sure what's up with that. Any ideas?

[Todd Willey (xtoddx)]

I've never seen it before, and google isn't particularly helpful with such strange symbols. You may want to do a postrotate that restarts the service?

[Ewan Mellor (ewanmellor)]

Those symbols are a common symptom of null bytes ('\0' in C syntax) being in the file. ^@ means Ctrl-@, which means \0.

You're either writing nulls to the log, or writing at an offset into a blank file (which will give nulls as a side-effect).

[Soren Hansen (soren)]

This is really a packaging problem, mostly.

We need to fix up the logrotate config files in the Ubuntu packages.

a) It's configured to rotate /var/log/nova/*, rather than /var/log/nova/*.log
b) We should make sure the daemons start using the new logfile. Some of them may need SIGHUP'ing, some may need nothing at all, some may need patching.
b) We should probably have a logrotate config file for each nova package, since they need to be restarted individually.

[Soren Hansen (soren)]

Sorry it took so long.

This somehow fell off my radar.

[Thierry Carrez (ttx)]

Switched to RotatingFileHandler as of rev92 on the packaging branch.

[Chuck Short (zulcss)]

This is fixed in Ubuntu as well.