Formatting unicorn logs in json format for $stderr

Formatting unicorn logs in json format for $stderr

[Cenon Del Rosario]

Hi,

I am using rails 3.2.22 / ruby 2.1.8 and am trying to reformat the
unicorn log output from stderr into json format and have had partial
success.

I have a basic json formatter:
class JsonLogFormatter < Logger::Formatter
  def call(severity, datetime, progname, msg)
    log_msg = {
      time: "#{datetime}",
      severity: "#{severity}",
      source: "#{progname}"
    }
    msg.is_a?(Hash) ? log_msg.merge!(msg) : log_msg.merge!(message: "#{msg}")
    "#{log_msg.to_json}\n"
  end
end

I have this in my unicorn config:
Logger.new($stderr).tap do |newlgr|
  newlgr.formatter = JsonLogFormatter.new
end

I have this in my application.rb:
Logger.new(STDOUT).tap do |logr|
  JsonLogFormatter.new.tap do |frmtr|
    logr.formatter = frmtr
    Rails.logger = config.logger = logr
  end
end

For the most part it works and I get the stdout and stderr in json but
I also see some other non-json formatted messages, for example:
{"time":"2021-07-06 17:14:01
+1000","severity":"INFO","source":"","message":"Started GET \"/admin\"
for 127.0.0.1 at 2021-07-06 17:14:01 +1000"}
127.0.0.1 - - [06/Jul/2021 17:14:01] "GET /admin HTTP/1.1" 301 102 0.4243

It seems that rails logs are working and then the unicorn process
itself is outputting its own logs because I can see duplicates of the
same log message one in json and the other in plain text.

Just want to know if there is a way to get this working consistently?

Thank you,
Cenon Del Rosario

-- 
The information contained in this e-mail message and any accompanying files 
is or may be confidential. If you are not the intended recipient, any use, 
dissemination, reliance, forwarding, printing or copying of this e-mail or 
any attached files is unauthorised. This e-mail is subject to copyright. No 
part of it should be reproduced, adapted or communicated without the 
written consent of the copyright owner. If you have received this e-mail in 
error please advise the sender immediately by return e-mail or telephone 
and delete all copies. Nine Group does not guarantee the accuracy or 
completeness of any information contained in this e-mail or attached files. 
Internet communications are not secure, therefore Nine Group does not 
accept legal responsibility for the contents of this message or attached 
files.

Re: Formatting unicorn logs in json format for $stderr

[Eric Wong]

Cenon Del Rosario <cdelrosario@publishing.nine.com.au> wrote:
> Hi,
> 
> I am using rails 3.2.22 / ruby 2.1.8 and am trying to reformat the
> unicorn log output from stderr into json format and have had partial
> success.
> 
> I have a basic json formatter:
> class JsonLogFormatter < Logger::Formatter
>   def call(severity, datetime, progname, msg)
>     log_msg = {
>       time: "#{datetime}",
>       severity: "#{severity}",
>       source: "#{progname}"
>     }
>     msg.is_a?(Hash) ? log_msg.merge!(msg) : log_msg.merge!(message: "#{msg}")
>     "#{log_msg.to_json}\n"
>   end
> end
> 
> I have this in my unicorn config:
> Logger.new($stderr).tap do |newlgr|
>   newlgr.formatter = JsonLogFormatter.new
> end

I suspect that needs "logger()" around it, like so:

    logger(Logger.new($stderr).tap do |newlgr|
      newlgr.formatter = JsonLogFormatter.new
    end)

cf. https://yhbt.net/unicorn/Unicorn/Configurator.html#method-i-logger

> For the most part it works and I get the stdout and stderr in json but
> I also see some other non-json formatted messages, for example:
> {"time":"2021-07-06 17:14:01
> +1000","severity":"INFO","source":"","message":"Started GET \"/admin\"
> for 127.0.0.1 at 2021-07-06 17:14:01 +1000"}
> 127.0.0.1 - - [06/Jul/2021 17:14:01] "GET /admin HTTP/1.1" 301 102 0.4243

I suspect one of those lines could be the result of
Rack::CommonLogger from RACK_ENV=deployment or similar
(which matched "rackup" defaults back in 2009).

Personally, I always used something non-standard like "RACK_ENV=none"
to disable all default Rack middleware (--no-default-middleware
exists nowadays, too).

> It seems that rails logs are working and then the unicorn process
> itself is outputting its own logs because I can see duplicates of the
> same log message one in json and the other in plain text.
> 
> Just want to know if there is a way to get this working consistently?

I've never used the "logger" directive much myself; maybe others
here can chime in with experience using non-standard loggers.

Re: Formatting unicorn logs in json format for $stderr

[Cenon Del Rosario]

> I suspect that needs "logger()" around it, like so:
>     logger(Logger.new($stderr).tap do |newlgr|
>       newlgr.formatter = JsonLogFormatter.new
>     end)

Sorry for incomplete code snippets but yes I do have this (I was doing
it for either stdout or stderr) and it did not make a difference.

On Tue, 6 Jul 2021 at 20:41, Eric Wong <e@80x24.org> wrote:
>
> Cenon Del Rosario <cdelrosario@publishing.nine.com.au> wrote:
> > Hi,
> >
> > I am using rails 3.2.22 / ruby 2.1.8 and am trying to reformat the
> > unicorn log output from stderr into json format and have had partial
> > success.
> >
> > I have a basic json formatter:
> > class JsonLogFormatter < Logger::Formatter
> >   def call(severity, datetime, progname, msg)
> >     log_msg = {
> >       time: "#{datetime}",
> >       severity: "#{severity}",
> >       source: "#{progname}"
> >     }
> >     msg.is_a?(Hash) ? log_msg.merge!(msg) : log_msg.merge!(message: "#{msg}")
> >     "#{log_msg.to_json}\n"
> >   end
> > end
> >
> > I have this in my unicorn config:
> > Logger.new($stderr).tap do |newlgr|
> >   newlgr.formatter = JsonLogFormatter.new
> > end
>
> I suspect that needs "logger()" around it, like so:
>
>     logger(Logger.new($stderr).tap do |newlgr|
>       newlgr.formatter = JsonLogFormatter.new
>     end)
>
> cf. https://urldefense.com/v3/__https://yhbt.net/unicorn/Unicorn/Configurator.html*method-i-logger__;Iw!!LBk0ZmAmG_H4m2o!9io6HA1SNuu8dkgdMRtwNuyjMJZwMCtZCUQsYqfcIvMvaFlkjfE17UHZSB15oiNN9YiW_Lm-hw$
>
> > For the most part it works and I get the stdout and stderr in json but
> > I also see some other non-json formatted messages, for example:
> > {"time":"2021-07-06 17:14:01
> > +1000","severity":"INFO","source":"","message":"Started GET \"/admin\"
> > for 127.0.0.1 at 2021-07-06 17:14:01 +1000"}
> > 127.0.0.1 - - [06/Jul/2021 17:14:01] "GET /admin HTTP/1.1" 301 102 0.4243
>
> I suspect one of those lines could be the result of
> Rack::CommonLogger from RACK_ENV=deployment or similar
> (which matched "rackup" defaults back in 2009).
>
> Personally, I always used something non-standard like "RACK_ENV=none"
> to disable all default Rack middleware (--no-default-middleware
> exists nowadays, too).
>
> > It seems that rails logs are working and then the unicorn process
> > itself is outputting its own logs because I can see duplicates of the
> > same log message one in json and the other in plain text.
> >
> > Just want to know if there is a way to get this working consistently?
>
> I've never used the "logger" directive much myself; maybe others
> here can chime in with experience using non-standard loggers.

-- 
The information contained in this e-mail message and any accompanying files 
is or may be confidential. If you are not the intended recipient, any use, 
dissemination, reliance, forwarding, printing or copying of this e-mail or 
any attached files is unauthorised. This e-mail is subject to copyright. No 
part of it should be reproduced, adapted or communicated without the 
written consent of the copyright owner. If you have received this e-mail in 
error please advise the sender immediately by return e-mail or telephone 
and delete all copies. Nine Group does not guarantee the accuracy or 
completeness of any information contained in this e-mail or attached files. 
Internet communications are not secure, therefore Nine Group does not 
accept legal responsibility for the contents of this message or attached 
files.

Re: Formatting unicorn logs in json format for $stderr

[Eric Wong]

Cenon Del Rosario <cdelrosario@publishing.nine.com.au> wrote:
> > I suspect that needs "logger()" around it, like so:
> >     logger(Logger.new($stderr).tap do |newlgr|
> >       newlgr.formatter = JsonLogFormatter.new
> >     end)
> 
> Sorry for incomplete code snippets but yes I do have this (I was doing
> it for either stdout or stderr) and it did not make a difference.

OK, did you see my other paragraph about Rack::CommonLogger?
(reposted below)

> > > For the most part it works and I get the stdout and stderr in json but
> > > I also see some other non-json formatted messages, for example:
> > > {"time":"2021-07-06 17:14:01
> > > +1000","severity":"INFO","source":"","message":"Started GET \"/admin\"
> > > for 127.0.0.1 at 2021-07-06 17:14:01 +1000"}
> > > 127.0.0.1 - - [06/Jul/2021 17:14:01] "GET /admin HTTP/1.1" 301 102 0.4243
> >
> > I suspect one of those lines could be the result of
> > Rack::CommonLogger from RACK_ENV=deployment or similar
> > (which matched "rackup" defaults back in 2009).
> >
> > Personally, I always used something non-standard like "RACK_ENV=none"
> > to disable all default Rack middleware (--no-default-middleware
> > exists nowadays, too).

Re: Formatting unicorn logs in json format for $stderr

[Cenon Del Rosario]

> > > I suspect one of those lines could be the result of
> > > Rack::CommonLogger from RACK_ENV=deployment or similar
> > > (which matched "rackup" defaults back in 2009).
> > >

Yes I just tried this and it fixed the issue (I used -N but
RACK_ENV=none also worked)

Just wondering what other things will be impacted by turning off rack
middleware?


On Wed, 7 Jul 2021 at 09:38, Eric Wong <e@80x24.org> wrote:
>
> Cenon Del Rosario <cdelrosario@publishing.nine.com.au> wrote:
> > > I suspect that needs "logger()" around it, like so:
> > >     logger(Logger.new($stderr).tap do |newlgr|
> > >       newlgr.formatter = JsonLogFormatter.new
> > >     end)
> >
> > Sorry for incomplete code snippets but yes I do have this (I was doing
> > it for either stdout or stderr) and it did not make a difference.
>
> OK, did you see my other paragraph about Rack::CommonLogger?
> (reposted below)
>
> > > > For the most part it works and I get the stdout and stderr in json but
> > > > I also see some other non-json formatted messages, for example:
> > > > {"time":"2021-07-06 17:14:01
> > > > +1000","severity":"INFO","source":"","message":"Started GET \"/admin\"
> > > > for 127.0.0.1 at 2021-07-06 17:14:01 +1000"}
> > > > 127.0.0.1 - - [06/Jul/2021 17:14:01] "GET /admin HTTP/1.1" 301 102 0.4243
> > >
> > > I suspect one of those lines could be the result of
> > > Rack::CommonLogger from RACK_ENV=deployment or similar
> > > (which matched "rackup" defaults back in 2009).
> > >
> > > Personally, I always used something non-standard like "RACK_ENV=none"
> > > to disable all default Rack middleware (--no-default-middleware
> > > exists nowadays, too).

-- 
The information contained in this e-mail message and any accompanying files 
is or may be confidential. If you are not the intended recipient, any use, 
dissemination, reliance, forwarding, printing or copying of this e-mail or 
any attached files is unauthorised. This e-mail is subject to copyright. No 
part of it should be reproduced, adapted or communicated without the 
written consent of the copyright owner. If you have received this e-mail in 
error please advise the sender immediately by return e-mail or telephone 
and delete all copies. Nine Group does not guarantee the accuracy or 
completeness of any information contained in this e-mail or attached files. 
Internet communications are not secure, therefore Nine Group does not 
accept legal responsibility for the contents of this message or attached 
files.

Re: Formatting unicorn logs in json format for $stderr

[Eric Wong]

Cenon Del Rosario <cdelrosario@publishing.nine.com.au> wrote:
> > > > I suspect one of those lines could be the result of
> > > > Rack::CommonLogger from RACK_ENV=deployment or similar
> > > > (which matched "rackup" defaults back in 2009).
> > > >
> 
> Yes I just tried this and it fixed the issue (I used -N but
> RACK_ENV=none also worked)

Cool, good to know.

> Just wondering what other things will be impacted by turning off rack
> middleware?

Rack::{ContentLength,Chunked,TempfileReaper} for prod:
https://yhbt.net/unicorn-public/d5991fea2df857480b728e27c927d69c3df2080f/s/?b=lib/unicorn.rb#n67

You can set them up yourself in config.ru, but maybe Rails
also does that for you.  I haven't used Rails in many years,
but I seem to recall Rails had its own middleware stack somewhere,
too, but you'll have to refer to Rails docs for that.

Re: Formatting unicorn logs in json format for $stderr

[Cenon Del Rosario]

I set them up for the most part in config.ru and it is all working great now.

Thank you for all the help,
Cenon.

On Wed, 7 Jul 2021 at 10:16, Eric Wong <e@80x24.org> wrote:
>
> Cenon Del Rosario <cdelrosario@publishing.nine.com.au> wrote:
> > > > > I suspect one of those lines could be the result of
> > > > > Rack::CommonLogger from RACK_ENV=deployment or similar
> > > > > (which matched "rackup" defaults back in 2009).
> > > > >
> >
> > Yes I just tried this and it fixed the issue (I used -N but
> > RACK_ENV=none also worked)
>
> Cool, good to know.
>
> > Just wondering what other things will be impacted by turning off rack
> > middleware?
>
> Rack::{ContentLength,Chunked,TempfileReaper} for prod:
> https://urldefense.com/v3/__https://yhbt.net/unicorn-public/d5991fea2df857480b728e27c927d69c3df2080f/s/?b=lib*unicorn.rb*n67__;LyM!!LBk0ZmAmG_H4m2o!5NcQzVZYpPImkKbKC_y1fau9dHkPueop1r1vsRmW3u7mXtdXoKBx0CutbksqshNguuoNhcbOCA$
>
> You can set them up yourself in config.ru, but maybe Rails
> also does that for you.  I haven't used Rails in many years,
> but I seem to recall Rails had its own middleware stack somewhere,
> too, but you'll have to refer to Rails docs for that.

-- 
The information contained in this e-mail message and any accompanying files 
is or may be confidential. If you are not the intended recipient, any use, 
dissemination, reliance, forwarding, printing or copying of this e-mail or 
any attached files is unauthorised. This e-mail is subject to copyright. No 
part of it should be reproduced, adapted or communicated without the 
written consent of the copyright owner. If you have received this e-mail in 
error please advise the sender immediately by return e-mail or telephone 
and delete all copies. Nine Group does not guarantee the accuracy or 
completeness of any information contained in this e-mail or attached files. 
Internet communications are not secure, therefore Nine Group does not 
accept legal responsibility for the contents of this message or attached 
files.