Struggling with logrotate and unicorn

Struggling with logrotate and unicorn

[Emmanuel Gomez]

Hi,

First of all, thanks for Unicorn, it's a fantastic tool.

I'm starting a Unicorn 3.3.1 master process as root on an Ubuntu 10.04 LTS host, and dropping to an unprivileged user in the workers after forking. This all works fine. 

I have confirmed that logrotate creates the logs with a 0600 umask and the uid/gid of my unprivileged user (per my logrotate config, loosely based on the example logrotate.conf from 3.4 or 3.5). 

The problem occurs when I send a USR1 signal to the master process (as root, because the master is running as root) after the logs have been rotated. As near as I can tell, after that the Unicorn master chowns the logs to root ownership. Then, the workers attempt to chown the logs back to ownership by the unprivileged user, which repeatedly fails, spewing megabytes of errors that look like:

worker=0 reopening logs...
Unhandled listen loop exception #<Errno::EPERM: Operation not permitted - /opt/wp/src/nascar/current/log/staging.log>.
/opt/wp/src/nascar/shared/bundle/ruby/1.8/gems/unicorn-3.3.1/lib/unicorn/util.rb:57:in `chown'
/opt/wp/src/nascar/shared/bundle/ruby/1.8/gems/unicorn-3.3.1/lib/unicorn/util.rb:57:in `reopen_logs'
/opt/wp/src/nascar/shared/bundle/ruby/1.8/gems/unicorn-3.3.1/lib/unicorn/util.rb:37:in `each'
/opt/wp/src/nascar/shared/bundle/ruby/1.8/gems/unicorn-3.3.1/lib/unicorn/util.rb:37:in `reopen_logs'
/opt/wp/src/nascar/shared/bundle/ruby/1.8/gems/unicorn-3.3.1/lib/unicorn/http_server.rb:569:in `reopen_worker_logs'
/opt/wp/src/nascar/shared/bundle/ruby/1.8/gems/unicorn-3.3.1/lib/unicorn/http_server.rb:592:in `worker_loop'
/opt/wp/src/nascar/shared/bundle/ruby/1.8/gems/unicorn-3.3.1/lib/unicorn/http_server.rb:496:in `spawn_missing_workers'
/opt/wp/src/nascar/shared/bundle/ruby/1.8/gems/unicorn-3.3.1/lib/unicorn/http_server.rb:493:in `fork'
/opt/wp/src/nascar/shared/bundle/ruby/1.8/gems/unicorn-3.3.1/lib/unicorn/http_server.rb:493:in `spawn_missing_workers'
/opt/wp/src/nascar/shared/bundle/ruby/1.8/gems/unicorn-3.3.1/lib/unicorn/http_server.rb:489:in `each'
/opt/wp/src/nascar/shared/bundle/ruby/1.8/gems/unicorn-3.3.1/lib/unicorn/http_server.rb:489:in `spawn_missing_workers'
/opt/wp/src/nascar/shared/bundle/ruby/1.8/gems/unicorn-3.3.1/lib/unicorn/http_server.rb:503:in `maintain_worker_count'
/opt/wp/src/nascar/shared/bundle/ruby/1.8/gems/unicorn-3.3.1/lib/unicorn/http_server.rb:297:in `join'
/opt/wp/src/nascar/shared/bundle/ruby/1.8/gems/unicorn-3.3.1/lib/unicorn.rb:13:in `run'
/opt/wp/src/nascar/shared/bundle/ruby/1.8/gems/unicorn-3.3.1/bin/unicorn_rails:208
/opt/wp/src/nascar/shared/bundle/ruby/1.8/bin/unicorn_rails:19:in `load'
/opt/wp/src/nascar/shared/bundle/ruby/1.8/bin/unicorn_rails:19


I looked at Unicorn::Util.reopen_logs, which is where the exception originates, and clearly has code intended to deal with this (https://github.com/defunkt/unicorn/blob/v3.3.1/lib/unicorn/util.rb#L56), but it doesn't appear to be doing the right thing in my circumstance. It's not apparent to me at a glance why this is failing.

I'm not subscribed to the list, so please cc: my on replies.

Thanks for any input you may have,
Emmanuel Gomez
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: Struggling with logrotate and unicorn

[Eric Wong]

Emmanuel Gomez <emmanuel.gomez@gmail.com> wrote:
> I have confirmed that logrotate creates the logs with a 0600 umask and
> the uid/gid of my unprivileged user (per my logrotate config, loosely
> based on the example logrotate.conf from 3.4 or 3.5). 

Did the permissions of the old (rotated) log files change?

> The problem occurs when I send a USR1 signal to the master process (as
> root, because the master is running as root) after the logs have been
> rotated. As near as I can tell, after that the Unicorn master chowns
> the logs to root ownership. Then, the workers attempt to chown the
> logs back to ownership by the unprivileged user, which repeatedly
> fails, spewing megabytes of errors that look like:

The rotation error handling should probably just exit! the worker
and rely on the master to restart it...

-- 
Eric Wong
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: Struggling with logrotate and unicorn

[Emmanuel Gomez]

On Apr 12, 2011, at 10:58 AM, Eric Wong wrote:
> Emmanuel Gomez <emmanuel.gomez@gmail.com> wrote:
>> I have confirmed that logrotate creates the logs with a 0600 umask and
>> the uid/gid of my unprivileged user (per my logrotate config, loosely
>> based on the example logrotate.conf from 3.4 or 3.5). 
> 
> Did the permissions of the old (rotated) log files change?

No, they remained owned by root.

>> The problem occurs when I send a USR1 signal to the master process (as
>> root, because the master is running as root) after the logs have been
>> rotated. As near as I can tell, after that the Unicorn master chowns
>> the logs to root ownership. Then, the workers attempt to chown the
>> logs back to ownership by the unprivileged user, which repeatedly
>> fails, spewing megabytes of errors that look like:
> 
> The rotation error handling should probably just exit! the worker
> and rely on the master to restart it...

That would probably be better behavior, although in this specific case the worker would immediately die on respawn because the log is still owned by root and unwriteable by my unprivileged user.

I did find a resolution: in the after_fork block, I had copied the code to switch users from the GitHub blog post on unicorn (https://github.com/blog/517-unicorn). I didn't see Unicorn::Worker#user, which implements the same code with the addition of a call to Unicorn::Util.chown_logs. When I replace the inline GitHub-blog-derived code with a call to Unicorn::Worker#user, it works. 

My understanding is that this (after_fork/Unicorn::Util.chown_logs) shouldn't be executed on USR1; I don't see how the Unicorn::Util.chown_logs call on after_fork (startup) would make a difference w/r/t rotation (much later), but my understanding is obviously incomplete, because it works.

Thanks for your reply, I'm off to comment on the GitHub blog post to try to warn others to use Unicorn::Worker#user instead of the example code in after_fork.

-- Emmanuel
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: Struggling with logrotate and unicorn

[Eric Wong]

Emmanuel Gomez <emmanuel.gomez@gmail.com> wrote:
> On Apr 12, 2011, at 10:58 AM, Eric Wong wrote:
> > Emmanuel Gomez <emmanuel.gomez@gmail.com> wrote:
> >> I have confirmed that logrotate creates the logs with a 0600 umask
> >> and the uid/gid of my unprivileged user (per my logrotate config,
> >> loosely based on the example logrotate.conf from 3.4 or 3.5). 
> > 
> > Did the permissions of the old (rotated) log files change?
> 
> No, they remained owned by root.

Remained owned by root?  Yes that sounds like the problem.

> >> The problem occurs when I send a USR1 signal to the master process
> >> (as root, because the master is running as root) after the logs
> >> have been rotated. As near as I can tell, after that the Unicorn
> >> master chowns the logs to root ownership. Then, the workers attempt
> >> to chown the logs back to ownership by the unprivileged user, which
> >> repeatedly fails, spewing megabytes of errors that look like:
> > 
> > The rotation error handling should probably just exit! the worker
> > and rely on the master to restart it...
> 
> That would probably be better behavior, although in this specific case
> the worker would immediately die on respawn because the log is still
> owned by root and unwriteable by my unprivileged user.
> 
> I did find a resolution: in the after_fork block, I had copied the
> code to switch users from the GitHub blog post on unicorn
> (https://github.com/blog/517-unicorn). I didn't see
> Unicorn::Worker#user, which implements the same code with the addition
> of a call to Unicorn::Util.chown_logs. When I replace the inline
> GitHub-blog-derived code with a call to Unicorn::Worker#user, it
> works. 

Yes, the old versions of Unicorn didn't change users at all.

I always knew user-switching is a pain in the ass to deal with due to
issues like this.   Due to work on Rainbows! (designed to run on port
80) and users starting as root anyways (due to init scripts), I needed
add this feature.

> My understanding is that this (after_fork/Unicorn::Util.chown_logs)
> shouldn't be executed on USR1; I don't see how the
> Unicorn::Util.chown_logs call on after_fork (startup) would make a
> difference w/r/t rotation (much later), but my understanding is
> obviously incomplete, because it works.

It's the rotation that attempts to chown since it thinks (incorrectly)
that it's in the master process.  I'll make that more robust and release
3.6.0 sometime this week with (hopefully) a few other minor
improvements.

> Thanks for your reply, I'm off to comment on the GitHub blog post to
> try to warn others to use Unicorn::Worker#user instead of the example
> code in after_fork.

Thanks, that seems to be a general problem with people relying on
blog/mailing list posts instead of consistently updated documentation.

-- 
Eric Wong
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: Struggling with logrotate and unicorn

[Emmanuel Gomez]

On Apr 12, 2011, at 11:59 AM, Eric Wong wrote:
> I'll make that more robust and release
> 3.6.0 sometime this week with (hopefully) a few other minor
> improvements.

Great. This is apparently an infrequent circumstance (uncommon configuration?), but there will be a next person who does this (or comparable silliness).

>> Thanks for your reply, I'm off to comment on the GitHub blog post to
>> try to warn others to use Unicorn::Worker#user instead of the example
>> code in after_fork.
> 
> Thanks, that seems to be a general problem with people relying on
> blog/mailing list posts instead of consistently updated documentation.

Indeed, but I read most of the unicorn docs, and examples/unicorn.conf.rb in 3.3.1 doesn't mention Unicorn::Worker#user, so I remained unaware until I read through worker.rb. 

Hey, I can help here. Here's a patch:


>From de3178d98c81de3c8765cebd579ef3f7dd4b2d64 Mon Sep 17 00:00:00 2001
From: Emmanuel Gomez <emmanuel.gomez@gmail.com>
Date: Tue, 12 Apr 2011 15:36:36 -0700
Subject: [PATCH] Document Unicorn::Worker#user in example unicorn conf.

---
 examples/unicorn.conf.rb |    4 ++++
 1 files changed, 4 insertions(+), 0 deletions(-)

diff --git a/examples/unicorn.conf.rb b/examples/unicorn.conf.rb
index 28a9e65..8b7ad47 100644
--- a/examples/unicorn.conf.rb
+++ b/examples/unicorn.conf.rb
@@ -84,4 +84,8 @@ after_fork do |server, worker|
   # and Redis.  TokyoCabinet file handles are safe to reuse
   # between any number of forked children (assuming your kernel
   # correctly implements pread()/pwrite() system calls)
+
+  # if running the master process as root and the workers as an unprivileged
+  # user, do this to switch euid/egid in the workers (also chowns logs):
+  # worker.user("unprivileged_user", "unprivileged_group")
 end
-- 
1.7.3.4

_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: Struggling with logrotate and unicorn

[Eric Wong]

Emmanuel Gomez <emmanuel.gomez@gmail.com> wrote:
> On Apr 12, 2011, at 11:59 AM, Eric Wong wrote:
> > I'll make that more robust and release 3.6.0 sometime this week with
> > (hopefully) a few other minor improvements.
> 
> Great. This is apparently an infrequent circumstance (uncommon
> configuration?), but there will be a next person who does this (or
> comparable silliness).

Yes, I think most people still deploy and start as non-root
(Capistrano/Vlad).  But I also distribute init scripts and those
are usually run as root :x

> >> Thanks for your reply, I'm off to comment on the GitHub blog post
> >> to try to warn others to use Unicorn::Worker#user instead of the
> >> example code in after_fork.
> > 
> > Thanks, that seems to be a general problem with people relying on
> > blog/mailing list posts instead of consistently updated
> > documentation.
> 
> Indeed, but I read most of the unicorn docs, and
> examples/unicorn.conf.rb in 3.3.1 doesn't mention
> Unicorn::Worker#user, so I remained unaware until I read through
> worker.rb.

Actually the (usually) user-visible one should be
Unicorn::Configurator#user which should be in the top-level.
Worker#user is just the internal call.

> Hey, I can help here. Here's a patch:

Perhaps this is better? I added a blurb discouraging people from
running as root in the first place.  You'll still get credit :)

>From c4d3cd7d7b32ed133e25e3740c8e7a3493592eec Mon Sep 17 00:00:00 2001
From: Emmanuel Gomez <emmanuel.gomez@gmail.com>
Date: Tue, 12 Apr 2011 15:36:36 -0700
Subject: [PATCH] Document "user" directive in example unicorn conf

---
 examples/unicorn.conf.rb |    7 +++++++
 1 files changed, 7 insertions(+), 0 deletions(-)

diff --git a/examples/unicorn.conf.rb b/examples/unicorn.conf.rb
index 28a9e65..61f0b4b 100644
--- a/examples/unicorn.conf.rb
+++ b/examples/unicorn.conf.rb
@@ -12,6 +12,13 @@
 # more will usually help for _short_ waits on databases/caches.
 worker_processes 4
 
+# Since Unicorn is never exposed to outside clients, it does not need to
+# run on the standard HTTP port (80), there is no reason to start Unicorn
+# as root unless it's from system init scripts.
+# If running the master process as root and the workers as an unprivileged
+# user, do this to switch euid/egid in the workers (also chowns logs):
+# user "unprivileged_user", "unprivileged_group"
+
 # Help ensure your application will always spawn in the symlinked
 # "current" directory that Capistrano sets up.
 working_directory "/path/to/app/current" # available in 0.94.0+
-- 
Eric Wong
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying

Re: Struggling with logrotate and unicorn

[Emmanuel Gomez]

On Apr 12, 2011, at 3:51 PM, Eric Wong wrote:
> Yes, I think most people still deploy and start as non-root
> (Capistrano/Vlad).  But I also distribute init scripts and those
> are usually run as root :x

And it's because of init scripts that I'm running unicorn as root.

> Actually the (usually) user-visible one should be
> Unicorn::Configurator#user which should be in the top-level.
> Worker#user is just the internal call.

Oh, great, I'm glad you pointed that out. Since the worker instance is yielded into the after_fork block, I started looking there. I'll update my config to use the public interface. Also, I'll go correct my github blog post comment, oops.

>> Hey, I can help here. Here's a patch:
> 
> Perhaps this is better? I added a blurb discouraging people from
> running as root in the first place.  

Looks great. 

> You'll still get credit :)

It's a nothing, I don't need any credit :)
_______________________________________________
Unicorn mailing list - mongrel-unicorn@rubyforge.org
http://rubyforge.org/mailman/listinfo/mongrel-unicorn
Do not quote signatures (like this one) or top post when replying