Log line formatting

Log line formatting

[Lee Bankewitz]

Howdy.

I'm running Unicorn 0.94 in production (its working wonderfully).  One
question about the log line formats in the unicorn log.

In my unicorn config file, I have:
logger Logger.new("log/unicorn.log")

I see timestamps on the the initial log lines when unicorn first starts, i.e.:
"I, [2009-11-06T12:25:13.812367 #2437]  INFO -- : listening on
addr=0.0.0.0:3000 fd=5"

But the format of the log line changes soon thereafter:
"master process ready"
"worker=0 ready"

any ideas why this is happening? I'd prefer to have the initial format
for every line.

thx, -lee

Re: Log line formatting

[Eric Wong]

Lee Bankewitz <leebankewitz@gmail.com> wrote:
> Howdy.
> 
> I'm running Unicorn 0.94 in production (its working wonderfully).  One
> question about the log line formats in the unicorn log.
> 
> In my unicorn config file, I have:
> logger Logger.new("log/unicorn.log")
> 
> I see timestamps on the the initial log lines when unicorn first starts, i.e.:
> "I, [2009-11-06T12:25:13.812367 #2437]  INFO -- : listening on
> addr=0.0.0.0:3000 fd=5"
> 
> But the format of the log line changes soon thereafter:
> "master process ready"
> "worker=0 ready"
> 
> any ideas why this is happening? I'd prefer to have the initial format
> for every line.

Hi Lee,

This with Rails?  Unfortunately, Rails seems to monkey patch the core
Logger format methods.  If you find a clean solution to this without
bad side effects, please let the rest of us know, thanks.

-- 
Eric Wong

Re: Log line formatting

[Lee Bankewitz]

On Fri, Nov 6, 2009 at 4:40 PM, Eric Wong <normalperson@yhbt.net> wrote:
> Lee Bankewitz <leebankewitz@gmail.com> wrote:
>> Howdy.
>>
>> I'm running Unicorn 0.94 in production (its working wonderfully).  One
>> question about the log line formats in the unicorn log.
>>
>> In my unicorn config file, I have:
>> logger Logger.new("log/unicorn.log")
>>
>> I see timestamps on the the initial log lines when unicorn first starts, i.e.:
>> "I, [2009-11-06T12:25:13.812367 #2437]  INFO -- : listening on
>> addr=0.0.0.0:3000 fd=5"
>>
>> But the format of the log line changes soon thereafter:
>> "master process ready"
>> "worker=0 ready"
>>
>> any ideas why this is happening? I'd prefer to have the initial format
>> for every line.
>
> Hi Lee,
>
> This with Rails?  Unfortunately, Rails seems to monkey patch the core
> Logger format methods.  If you find a clean solution to this without
> bad side effects, please let the rest of us know, thanks.
>
> --
> Eric Wong
> _______________________________________________
> mongrel-unicorn mailing list
> mongrel-unicorn@rubyforge.org
> http://rubyforge.org/mailman/listinfo/mongrel-unicorn
>

Thanks Eric,

Rails does indeed override the default formatting of Logger.  I got
around it for now by setting the formatter explicitly to the ruby
default formatter, as follows:

# config/unicorn.rb
unicorn_logger = Logger.new("unicorn.log")
unicorn_logger.formatter = Logger::Formatter.new
logger unicorn_logger

I think its bad behavior by rails though, so I'll see if there's any
interest in a Rails patch to address this.

-lee

Re: Log line formatting

[Eric Wong]

Lee Bankewitz <leebankewitz@gmail.com> wrote:
> On Fri, Nov 6, 2009 at 4:40 PM, Eric Wong <normalperson@yhbt.net> wrote:
> > Lee Bankewitz <leebankewitz@gmail.com> wrote:
> >> Howdy.
> >>
> >> I'm running Unicorn 0.94 in production (its working wonderfully).  One
> >> question about the log line formats in the unicorn log.
> >>
> >> In my unicorn config file, I have:
> >> logger Logger.new("log/unicorn.log")
> >>
> >> I see timestamps on the the initial log lines when unicorn first starts, i.e.:
> >> "I, [2009-11-06T12:25:13.812367 #2437]  INFO -- : listening on
> >> addr=0.0.0.0:3000 fd=5"
> >>
> >> But the format of the log line changes soon thereafter:
> >> "master process ready"
> >> "worker=0 ready"
> >>
> >> any ideas why this is happening? I'd prefer to have the initial format
> >> for every line.
> >
> > Hi Lee,
> >
> > This with Rails?  Unfortunately, Rails seems to monkey patch the core
> > Logger format methods.  If you find a clean solution to this without
> > bad side effects, please let the rest of us know, thanks.
> 
> Thanks Eric,
> 
> Rails does indeed override the default formatting of Logger.  I got
> around it for now by setting the formatter explicitly to the ruby
> default formatter, as follows:
> 
> # config/unicorn.rb
> unicorn_logger = Logger.new("unicorn.log")
> unicorn_logger.formatter = Logger::Formatter.new
> logger unicorn_logger

Thanks, I've been meaning to start an FAQ RDoc for stuff like
this.

I wonder if:

  Configurator::DEFAULTS[:logger].formatter = Logger::Formatter.new

is enough.  I still try to avoid relative paths in config files,
especially since Logger.new("unicorn.log") sets the path immediately
and can't be affected by the new "working_directory" directive in
0.94.0

> I think its bad behavior by rails though, so I'll see if there's any
> interest in a Rails patch to address this.

Completely agreed that this is bad behavior by Rails.  I'm very much
against the idea of propagating/encouraging things like this and fixing
the problem at the source is the way to go.

-- 
Eric Wong