roidrage / lograge Goto Github PK
View Code? Open in Web Editor NEWAn attempt to tame Rails' default policy to log everything.
License: MIT License
An attempt to tame Rails' default policy to log everything.
License: MIT License
Is it somehow possible to include rograge to rocket_pants gem API controllers?
https://github.com/Sutto/rocket_pants
These controllers are not inheriting from ApplicationController.
This would make lograge usable as a drop-in replacement for many more apps.
If the remote IP isn't available elsewhere, it may entail redefining/monkeypatching ActionController::Instrumentation so the remote IP is provided to log subscribers. Something like:
ActionController::Instrumentation.send(:define_method, "process_action") do |arg|
raw_payload = {
# .. the existing keys ..
:ip => request.remote_ip
}
# define the ActiveSupport::Notifications events
end
If you would accept a patch to add this (or can suggest a better way to obtain the remote IP), let me know and I'll give it a whirl.
This isn't necessarily a lograge specific question/issue, but I haven't had much luck, elsewhere. I'm using Rails 3.2.14. I'm streaming a controller action response, as follows:
def my_controller_action
stream = StreamingClass.new(*args) #responds to each
response.sending_file= true
headers.merge!(
'Content-Disposition' => 'inline',
'Content-Transfer-Encoding' => 'binary',
'Cache-Control' => 'no-cache'
)
self.status = 200
self.content_type= 'application/json'
self.response_body = stream
end
The streaming works just fine, but the problem is that the controller action returns before the streaming is completed (i.e. before each is called on the 'stream' object). It basically returns immediately after assigning the 'stream' object to self.response_body.
I understand that lograge basically subscribes to the 'process_action.action_controller' notifications. It is logging the timings (i.e. duration, db_runtime, etc...) based on the actual controller return time, without tracking any time spent on the stream object code.
What I would really like is for the logged duration and db_runtime to reflect the time spent in the streaming code. Any ideas or suggestions on how I can achieve this? I've tried some nested notification subscriptions and custom instrumentation blocks around the streaming code, but it isn't a great solution and doesn't allow me to stick with lograge. I'd greatly appreciate some help with this.
Alex
I'd prefer to keep my configuration of whether Lograge is enabled inside chamber settings files and to use config/initializers/logger.rb
to enable any of my logging setup.
Unfortunately it appears that the initializer hook that Lograge hooks into in its railtie happens before any initializers are run. So if I put:
# config/initializers/logger.rb
MyApp::Application.configure do
config.lograge.enabled = Chamber.env.lograge.enabled?
end
as is suggested by the README, it doesn't work. And to be thorough it doesn't work even if I put true
rather than the Chamber
bit.
I'm running a puma server for my production setup. However I cannot integrate the lograge because of the following error.
I'm not doing anything special so I'm just including config.lograge.enabled = true in production.rb and thats it.
I wonder if someone else has encountered such a issue.
/usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/railties-4.2.0/lib/rails/railtie/configuration.rb:95:in `method_missing': undefined method `lograge' for #<Rails::Application::Configuration:0x007fb696924470> (NoMethodError)
from /home/deployer/apps/ren/releases/20150106184201/config/environments/production.rb:89:in `block in <top (required)>'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/railties-4.2.0/lib/rails/railtie.rb:210:in `instance_eval'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/railties-4.2.0/lib/rails/railtie.rb:210:in `configure'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/railties-4.2.0/lib/rails/railtie.rb:182:in `configure'
from /home/deployer/apps/ren/releases/20150106184201/config/environments/production.rb:1:in `<top (required)>'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activesupport-4.2.0/lib/active_support/dependencies.rb:274:in `require'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activesupport-4.2.0/lib/active_support/dependencies.rb:274:in `block in require'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activesupport-4.2.0/lib/active_support/dependencies.rb:240:in `load_dependency'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activesupport-4.2.0/lib/active_support/dependencies.rb:274:in `require'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/railties-4.2.0/lib/rails/engine.rb:598:in `block (2 levels) in <class:Engine>'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/railties-4.2.0/lib/rails/engine.rb:597:in `each'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/railties-4.2.0/lib/rails/engine.rb:597:in `block in <class:Engine>'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/railties-4.2.0/lib/rails/initializable.rb:30:in `instance_exec'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/railties-4.2.0/lib/rails/initializable.rb:30:in `run'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/railties-4.2.0/lib/rails/initializable.rb:55:in `block in run_initializers'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/2.1.0/tsort.rb:226:in `block in tsort_each'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/2.1.0/tsort.rb:348:in `block (2 levels) in each_strongly_connected_component'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/2.1.0/tsort.rb:418:in `block (2 levels) in each_strongly_connected_component_from'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/2.1.0/tsort.rb:427:in `each_strongly_connected_component_from'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/2.1.0/tsort.rb:417:in `block in each_strongly_connected_component_from'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/railties-4.2.0/lib/rails/initializable.rb:44:in `each'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/railties-4.2.0/lib/rails/initializable.rb:44:in `tsort_each_child'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/2.1.0/tsort.rb:411:in `call'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/2.1.0/tsort.rb:411:in `each_strongly_connected_component_from'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/2.1.0/tsort.rb:347:in `block in each_strongly_connected_component'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/2.1.0/tsort.rb:345:in `each'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/2.1.0/tsort.rb:345:in `call'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/2.1.0/tsort.rb:345:in `each_strongly_connected_component'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/2.1.0/tsort.rb:224:in `tsort_each'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/2.1.0/tsort.rb:205:in `tsort_each'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/railties-4.2.0/lib/rails/initializable.rb:54:in `run_initializers'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/railties-4.2.0/lib/rails/application.rb:352:in `initialize!'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/railties-4.2.0/lib/rails/railtie.rb:194:in `public_send'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/railties-4.2.0/lib/rails/railtie.rb:194:in `method_missing'
from /home/deployer/apps/ren/current/config/environment.rb:5:in `<top (required)>'
from /home/deployer/apps/ren/current/config.ru:3:in `require'
from /home/deployer/apps/ren/current/config.ru:3:in `block in <main>'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/rack-1.6.0/lib/rack/builder.rb:55:in `instance_eval'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/rack-1.6.0/lib/rack/builder.rb:55:in `initialize'
from /home/deployer/apps/ren/current/config.ru:in `new'
from /home/deployer/apps/ren/current/config.ru:in `<main>'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/rack-1.6.0/lib/rack/builder.rb:49:in `eval'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/rack-1.6.0/lib/rack/builder.rb:49:in `new_from_string'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/rack-1.6.0/lib/rack/builder.rb:40:in `parse_file'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/puma-2.10.2/lib/puma/configuration.rb:99:in `app'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/puma-2.10.2/lib/puma/runner.rb:123:in `app'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/puma-2.10.2/lib/puma/runner.rb:130:in `start_server'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/puma-2.10.2/lib/puma/cluster.rb:207:in `worker'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/puma-2.10.2/lib/puma/cluster.rb:106:in `block (2 levels) in spawn_workers'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/puma-2.10.2/lib/puma/cluster.rb:106:in `fork'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/puma-2.10.2/lib/puma/cluster.rb:106:in `block in spawn_workers'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/puma-2.10.2/lib/puma/cluster.rb:103:in `times'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/puma-2.10.2/lib/puma/cluster.rb:103:in `spawn_workers'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/puma-2.10.2/lib/puma/cluster.rb:154:in `check_workers'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/puma-2.10.2/lib/puma/cluster.rb:408:in `run'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/puma-2.10.2/lib/puma/cli.rb:507:in `run'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/puma-2.10.2/lib/puma/control_cli.rb:248:in `start'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/puma-2.10.2/lib/puma/control_cli.rb:216:in `run'
from /usr/local/rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/puma-2.10.2/bin/pumactl:8:in `<top (required)>'
from /usr/local/rbenv/versions/2.1.5/bin/pumactl:23:in `load'
from /usr/local/rbenv/versions/2.1.5/bin/pumactl:23:in `<main>'
I have an app, which maybe is doing something strange but it seems like 404 errors caused by missing routes and 500 errors get send to the log file as a stack trace not a single line entry. Am I missing something? In the code it certainly looks like it should be handling 500 errors but it doesn't seem to work.
In case of an an ActiveRecord::RecordNotFound
a status code 500
gets logged while actually a 404
response gets returned.
If noticed that this is an issue for quite some time - according to #27. However, this thread is 2 years old now and it also addresses a more complex issue.
What would be the best way to hook into this say from a Sinatra app?
Please excuse my ignorance if this has already been address, but so far I can only see HTTP request logging in JSON, not exception, or app initialization logs. Is this the correct behavior? Is there any way to make sure the entire production.log file is in JSON always? Similar to the yarder gem...?
Thank you
HI
How display with DB query on that logger
method=GET path=/article/24694 format=html controller=article action=show status=200 duration=7899.91 view=3193.04 db=1376.15
I want to display DB query, it's possible
It'd be really helpful if the project had a changelog. The README lists some changes, but it's not clear in which release they were added or when that release was made.
I'm getting log messages that resemble this:
method=GET path=/users format=html controller=controller action=action status=200 duration=677.10 view=585.45 db=17.37 uid=5 ip=127.0.0.1 params={"action"=>"index", "controller"=>"users"}
I added the uid, ip, and params as custom options, by overriding append_info_to_payload
as described at #23
I'm not sure why the actual controller and action are incorrect. If I use the debugger in append_info_to_payload
and call payload[:params]['controller']
it outputs the correct value ("users") - so it seems that value is being lost between here and when lograge handles it.
Rails 3.2.11
ruby 1.9.3p286 (2012-10-12 revision 37165) [x86_64-darwin12.0.0]
I'd love it if lograge would auto-support current_user
logging, something like:
config.lograge.custom_options = lambda do |event|
{ :uid => event.request.controller.current_user.id }
end
We find it vital for debugging and 'watching' how a user got into a particular state.
I've add a timestamp to my log with:
MyApp::Application.configure do
config.lograge.enabled = true
# add time to lograge
config.lograge.custom_options = lambda do |event|
{:time => event.time}
end
end
but it only added the date
, not the time
I've got a lograge extension as part of the elasticsearch-rails
gem, which sets up custom_options
in its Railtie (source).
Nevertheless, the configuration seems to be ignored, when the config.lograge.enabled
property is not being set. When I set in development.rb
, it is being ignored, probably due to the loading order.
I don't want to enable Lograge in the gem's Railtie, since people might want to enable it in certain environments only...
Any idea how can I make this work?
I don't want to either:
I am not sure i get this line "use a proper log formatter instead."
thanks!
I can easily add custom_options
but not removing default options, or changing the order.
Now you can choose among 3 formatters:
But you can't create your totally custom formatter. I'm missing the possibility to assign a block to the log_format
configuration option like:
config.lograge.log_format = lambda do |event, data| { "my custom log: #{data[:path]}" }
I've noticed that PATCH actions are logged with "method=POST"
Looks like lograge is using ActionDispatch::Request#method while the true method is returned by ActionDispatch::Request#request_method
[2] pry(#<UserSegmentsController>)> request.params
=> {"utf8"=>"✓",
"_method"=>"patch",
"authenticity_token"=>"oA0mKjw.......",
"user_segment"=>{"status"=>"Complete"},
"commit"=>"Submit Assignment",
"action"=>"update",
"controller"=>"......",
"id"=>"....."}
[3] pry(#<UserSegmentsController>)> request.method
=> "POST"
[4] pry(#<UserSegmentsController>)> request.request_method
=> "PATCH"
I have this config.lograge.enabled = true
in my development.rb
but log is still the Rails default.
This doesn't work within the engine:
initializer :initialize_logger do |app|
app.config.lograge.enabled = true
# add time to lograge
app.config.lograge.custom_options = lambda do |event|
{:time => event.time}
end
end
Is there a different initializer that I should use for lograge configuration? http://guides.rubyonrails.org/configuring.html#initializers
See log format here: https://github.com/ryandotsmith/l2met/wiki/Usage
I am using lograge with this configuration:
config.lograge.formatter = Lograge::Formatters::Json.new
config.lograge.enabled = true
config.lograge.custom_options = lambda do |event|
{
time: event.time,
user_agent: event.payload[:user_agent],
authorization: event.payload[:authorization],
params: event.payload[:params]
}
end
And it raised this error when there was photo uploading:
Could not log "process_action.action_controller" event. EncodingError: Invalid Unicode
["/data/ruby-2.0.0-p594/gems/lograge-0.3.0/lib/lograge/formatters/json.rb:6:in `dump'", "/data/ruby-2.0.0-p594/gems/lograge-0.3.0/lib/lograge/formatters/json.rb:6:in `call'", ...]
I think it is because it could not dump ActionDispatch::Http::UploadedFile
. Any thought?
We are having an issue where our Rails logs output for a few minutes after boot (on Heroku dynos) but then quit. The other Heroku logs continue (router, runtime metrics) so it seems to be a problem in Ruby-land.
If I remove lograge it seems to be working. I dropped our append_info_to_payload
and custom_options
code to confirm that just enabling lograge causes the problem:
gem "lograge"
config.log_level = :info
config.lograge.enabled = true
MRI 2.1, Rails 4.0.2, Puma 2.7.1 with 8 threads.
My guess is that this is actually an issue in Rails itself.
(I'm using rails 4.0.3, devise 3.2.3 and lograge 0.3.0.)
I'm not sure if this is really devise devise specific. When I make a request that fails authentication it returns a 401 Unauthorized
. lograge does log this with status=0
though. When I look at payload
in https://github.com/roidrage/lograge/blob/master/lib/lograge/log_subscriber.rb#L56-L65, I get
{:controller=>"TestsController", :action=>"index", :params=>{"action"=>"index", "controller"=>"tests"}, :format=>"*/*", :method=>"GET", :path=>"/tests"}
which is obviously the reason why status=0
gets logged.
With lograge disabled I get this log entry by rails:
Started GET "/tests" for 127.0.0.1 at 2014-03-14 10:45:49 +0100
Processing by TestsController#index as */*
Completed 401 Unauthorized in 8ms
I'm wondering if I am overlooking something here and if this can be somehow fixed. Anyone else seeing this issue?
At the moment:
@roidrage Would you mind if I submit a PR to move the logging from the LogSubscriber to middleware?
I'm receiving request logs correctly, but when Rails throws any error, the log goes to Kibana in 3 or more parts without a clean format.
While following the setup steps here I found that the version I installed does not have formatters. I compared the ruby files and found the installed version 0.2.0 is different from what we have here. Is there any plan to release a new version?
I think starting in rails 4, rack-cache can be configured with a simple boolean like so:
config.action_dispatch.rack_cache = true
And rails will use defaults: https://github.com/rails/rails/blob/master/railties/lib/rails/application/default_middleware_stack.rb#L83-L91
lograge doesn't accommodate this scenario, and ends up trying to access []=
on true
https://github.com/roidrage/lograge/blob/master/lib/lograge.rb#L103
since the default verbosity is false
anyway, this scenario can be accommodated by simply doing nothing if app.config.action_dispatch.rack_cache == true
let me know what you think and i can put together a pull request
Before more formatters might be added I would propose that we extract the existing ones into single gems or a pack of formatters.
This helps in keeping the dependencies for lograge small, and the formatters could have what they need as dependencies.
Also people would be able to create their own specialised formatters.
with 2.3.9rc3 and 0.0.6 we see this error:
ArgumentError: wrong number of arguments (2 for 1)
lograge-0.0.6/lib/lograge/rails_ext/rack/logger.rb:12→ call_app
railties-3.2.9.rc3/lib/rails/rack/logger.rb:16→ block in call
activesupport-3.2.9.rc3/lib/active_support/tagged_logging.rb:22→ tagged
railties-3.2.9.rc3/lib/rails/rack/logger.rb:16→ call
it doesn't happen with 2.3.8
it originates from a custom rack middleware in our app. i can provide more details if you are interested.
does this look familiar?
/cc @sidonath
I'm using lograge to build summarize log from rails app, but when I follow Readme indication of version [v0.3.1][1] the result it's: full rails log + summarize log.
For example:
Connecting to database specified by database.yml
Connecting to database specified by database.yml
{"@source":"unknown","@tags":[],"@fields":{},"method":"GET","path":"/","format":"html","controller":"home/summaries","action":"index","status":0,"duration":6.85,"product":"beesor-log","@timestamp":"2015-02-02T18:05:19.514583+00:00","@message":"[0] GET / (home/summaries#index)"}
{"@source":"unknown","@tags":[],"@fields":{},"method":"GET","path":"/login","format":"html","controller":"devise/sessions","action":"new","status":200,"duration":155.42,"view":87.71,"db":8.29,"product":"beesor-log","@timestamp":"2015-02-02T18:05:19.850720+00:00","@message":"[200] GET /login (devise/sessions#new)"}
Served asset /final_calls-b2b9d4899d488cafd9cbf55362f51edd.js - 200 OK (0ms) Served asset /i18n-a014c1078d4f5a62e1459afd80ef048b.js - 200 OK (0ms) Served asset /login-6e9b4528e684cf7f6bc276da58753af0.css - 200 OK (0ms) Served asset /devise/sessions - 200 OK (0ms) [1m[36mUser Load (2.2ms)[0m [1mSELECT "users".* FROM "users" WHERE "users"."username" = 'tenant_admin' AND "users"."status" = 'enabled' LIMIT 1[0m [1m[35m (1.0ms)[0m BEGIN [1m[36m (1.4ms)[0m [1mUPDATE "users" SET "last_sign_in_at" = '2015-02-02 17:03:35.791483', "current_sign_in_at" = '2015-02-02 18:05:25.525736', "sign_in_count" = 8, "updated_at" = '2015-02-02 18:05:25.528094' WHERE "users"."id" = 1[0m [1m[35m (13.9ms)[0m COMMIT [1m[36m (0.8ms)[0m [1mBEGIN[0m [1m[35m (1.2ms)[0m UPDATE "users" SET "unique_session_id" = 'jyzQTvsZKJiTye1a5RFQ', "updated_at" = '2015-02-02 18:05:25.546695' WHERE "users"."id" = 1 [1m[36m (4.4ms)[0m [1mCOMMIT[0m {"@source":"unknown","@tags":[],"@fields":{},"method":"POST","path":"/login","format":"html","controller":"devise/sessions","action":"create","status":302,"duration":141.81,"view":0.0,"db":0.0,"location":"http://localhost:3000/","product":"beesor-log","@timestamp":"2015-02-02T18:05:25.567320+00:00","@message":"[302] POST /login (devise/sessions#create)"}
This behavior is normal? I'm been understand that with this gems the rails log result will be: summarized log like:
{"@source":"unknown","@tags":[],"@fields":{},"method":"GET","path":"/","format":"html","controller":"home/summaries","action":"index","status":0,"duration":6.85,"product":"beesor-log","@timestamp":"2015-02-02T18:05:19.514583+00:00","@message":"[0] GET / (home/summaries#index)"}
{"@source":"unknown","@tags":[],"@fields":{},"method":"GET","path":"/login","format":"html","controller":"devise/sessions","action":"new","status":200,"duration":155.42,"view":87.71,"db":8.29,"product":"beesor-log","@timestamp":"2015-02-02T18:05:19.850720+00:00","@message":"[200] GET /login (devise/sessions#new)"}
{"@source":"unknown","@tags":[],"@fields":{},"method":"POST","path":"/login","format":"html","controller":"devise/sessions","action":"create","status":302,"duration":141.81,"view":0.0,"db":0.0,"location":"http://localhost:3000/","product":"beesor-log","@timestamp":"2015-02-02T18:05:25.567320+00:00","@message":"[302] POST /login (devise/sessions#create)"}
Looks like it's not happy with:
app.config.action_dispatch.rack_cache[:verbose] = false
Maybe need to move that to after initialize? Here's the whole error:
NoMethodError: undefined method `[]=' for false:FalseClass
~/.rbenv/versions/1.9.3-p125/lib/ruby/gems/1.9.1/gems/lograge-0.0.3/lib/lograge.rb:30:in `setup'
~/.rbenv/versions/1.9.3-p125/lib/ruby/gems/1.9.1/gems/lograge-0.0.3/lib/lograge/railtie.rb:11:in `block in <class:Railtie>'
~/.rbenv/versions/1.9.3-p125/lib/ruby/gems/1.9.1/bundler/gems/rails-a01f0ab83981/railties/lib/rails/initializable.rb:30:in `instance_exec'
~/.rbenv/versions/1.9.3-p125/lib/ruby/gems/1.9.1/bundler/gems/rails-a01f0ab83981/railties/lib/rails/initializable.rb:30:in `run'
~/.rbenv/versions/1.9.3-p125/lib/ruby/gems/1.9.1/bundler/gems/rails-a01f0ab83981/railties/lib/rails/initializable.rb:55:in `block in run_initializers'
~/.rbenv/versions/1.9.3-p125/lib/ruby/gems/1.9.1/bundler/gems/rails-a01f0ab83981/railties/lib/rails/initializable.rb:54:in `each'
~/.rbenv/versions/1.9.3-p125/lib/ruby/gems/1.9.1/bundler/gems/rails-a01f0ab83981/railties/lib/rails/initializable.rb:54:in `run_initializers'
~/.rbenv/versions/1.9.3-p125/lib/ruby/gems/1.9.1/bundler/gems/rails-a01f0ab83981/railties/lib/rails/application.rb:136:in `initialize!'
~/.rbenv/versions/1.9.3-p125/lib/ruby/gems/1.9.1/bundler/gems/rails-a01f0ab83981/railties/lib/rails/railtie/configurable.rb:30:in `method_missing'
Lograge was working fine with the logstash format, but now all of a sudden each log line is prefixed with a timestamp and INFO --
, like this:
I, [2014-09-19T00:44:13.799675 #18431] INFO -- [JSON]
Before, each line was just a JSON logstash-event hash.
This problem occurs in our rails 4.1.5 app, but not in our rails 3.1.12 app.
This problem occurs in production, but not in development.
The rails 4 app is using lograge 0.3.0 and logstash-event 1.2.02.
Any ideas how this could have happened or how we can solve this?
We are in the process of setting up logstash with lograge and it seems that in Logstash 1.2 @fields
tag is not needed and fields can be passed directly to the Logstash::Event.new
.
Current setup make is harder to parse events. With new format no additional parsing would be needed.
Not sure if this is the right place to open this, but it would be nice to have a grok pattern (http://logstash.net/docs/1.1.0/filters/grok) available for use with logstash. Has anybody who's using this written one?
I want JSON format log in seperate file, so In config application.rb
config.lograge.logger = ActiveSupport::BufferedLogger.new "#{Rails.root}/log/lograge_#{Rails.env}.log"
But still JSON format log is coming in production.log only.
Could you please correct me
Thanks for any help
I believe that this is not a lograge issue but I'm not certain so I thought I'd raise it.
When an exception occurs, and a 500 is logged, custom options are missing from the log line.
For example:
If I have the following in /config/environments/production.rb
config.lograge.custom_options = lambda do |event|
{
remote_ip: event.payload[:remote_ip],
request_id: event.payload[:request_id]
}
end
I'm then appending to the payload in my application_controller.rb
def append_info_to_payload(payload)
super
payload[:remote_ip] = request.remote_ip
payload[:request_id] = request.env['HTTP_HEROKU_REQUEST_ID']
end
I get the following for an exception log line.
method=POST path=/users.json format=json controller=users action=create status=500 error='NoMethodError:undefined method `id' for nil:NilClass' duration=447.09 remote_ip= request_id=
Both remote_ip
and request_id
are blank.
Log lines for successful transactions are receiving the remote_ip
and request_id
correctly so I suspect the issue is that Rails is not passing the additional payload items when there is an exception.
Any ideas on how this info could be made to flow through?
I wonder if you would accept a PR for another subscriber, generating the following format:
{
"debug_info": {},
"response": {
"db": 0,
"view": 0.19,
"duration": 3.92,
"status": 200
},
"request": {
"path": "/api/ping",
"params": {
"x": "1"
},
"action": "ping",
"controller": "ApiStateController",
"format": "*/*",
"headers": {
"HTTP_ORIGIN": null,
"HTTP_VERSION": "HTTP/1.1",
"HTTP_ACCEPT": "*/*",
"HTTP_HOST": "localhost:3000",
"HTTP_USER_AGENT": "curl/7.30.0"
},
"ip": "127.0.0.1",
"method": "GET"
}
}
I have the following log entry created by lograge
{"method":"GET","path":"/warenkorb","format":"json","controller":"carts","action":"show","status":200,"duration":4.69,"view":0.3,"db":0.0,"name":"development","session":"a93fa3308f8873b179c091ad287534c8","host":"localhost","@timestamp":"2014/11/28 12:56:09 +0000","@version":"1","message":"[200] GET /warenkorb (carts#show)"}
The timestamp bit looks like this:
"@timestamp":"2014/11/28 12:56:09 +0000"
Unfortunately, logstash is responding with this error:
A plugin had an unrecoverable error. Will restart this plugin.
Plugin: <LogStash::Inputs::Stdin >
Error: Invalid format: "2014/11/25 13:14:30 +0000" is malformed at "/11/25 13:14:30 +0000"
{:level=>:error}
When changing the format by hand for test purposes to:
2014-11-27T14:45:02.928Z
it is working. I am not sure where the error is. Is this a lograge, logstash or Rails config error?
Thanks for any help
When using standard Rails logging, fields named password are filtered out before being logged. So they show up as :password=>\"[FILTERED]\"
When using lograge, this filtering doesn't happen - the param shows up as "password"=>"hunter2"
in the logs.
Note: this doesn't happen by default, it only happens if you are passing parameters through using append_info_to_payload
.
I know how I can ADD custom options to the log but how can I change default option? For example I don't want to log format=html
because all requests respond with html. Have I been missing something stupid?
At the moment, I see that the implementation attaches a logger to :action_controller. If I have routes that look similar to this:
root to: proc { [200, { 'Content-Type' => 'application/json' }, ['']]}
Would it be possible to log those requests? If so how?
In bug fix of the issue #110 , you had modified following this.
https://github.com/roidrage/lograge/pull/112/files#diff-d3a7c7717409a1c1353805f9579b980bR64
But, in get_error_status_code
method, there is exception_object = exception.constantize.new
.
https://github.com/roidrage/lograge/pull/112/files#diff-d3a7c7717409a1c1353805f9579b980bR71
If the exception requires arguments (for example, as of ActiveRecord::RecordInvalid
), exception_object = exception.constantize.new
throw ArgumentError: wrong number of arguments
.
Such errors cause Could not log "process_action.action_controller" event. ArgumentError: wrong number of arguments (0 for 1)
in 85 line of activesupport-4.2.0/lib/active_support/log_subscriber.rb
.
0.3.2
4.2.0
2.2.2p95 (2015-04-13 revision 50295)
It clearly would involve a lot of monkey-patching, but having a common logger that quieted things down in 2.3 and 3 would be pretty great.
I completely realise it is not the objective of this gem, but what would it take to get DelayedJob write proper logs as well? For example, right now I'm getting lines like:
{"message":"2015-02-16T20:47:21-0500: [Worker(delayed_job.0 host:worker0 pid:31027)] Job JobRunner#process_events (id=127673023) COMPLETED after 0.3080","@timestamp":"2015-02-17T01:47:21.217Z","@version":"1","severity":"INFO","host":"worker0"}
It would be cool if this could be split up in fields. Especially the type of job and the duration would be very useful information.
I just started using lograge. Everything seems to work fine on production. However I see now there are quite a few messages like the following:
Could not log "process_action.action_controller" event. Encoding::CompatibilityError: incompatible character encodings: ASCII-8BIT and UTF-8
At this stage the view has already begun rendering.
I sampled a few pages of that controller/action and those renders okay. This happens in a few actions.
I also want to ask that, if this error logging can cause the actual request to fail?
Something about the way I have to append additional info to the payload (i.e. overriding append_info_to_payload
inside of my ApplicationController
) feels messy. It requires defining the same custom options in 2 different locations, very far apart. This is something I'd much prefer to do right next to where I configure lograge, or at least in an initializer, so that when I (or a team member) come back to this in 6 months it isn't totally confusing.
For now, I have an initializer (lograge.rb
) set up that looks like this (>= ruby 2.0):
module LogrageControllerOverride
def append_info_to_payload(payload)
super
payload[:host] = request.host
payload[:fwd] = request.remote_ip
payload[:user_id] = current_user.try(:id)
end
end
# should probably do this only if Rails.env is production
ActionController::Base.send :prepend, LogrageControllerOverride
And then in config/environments/production.rb
I have this:
config.lograge.enabled = true
config.lograge.custom_options = lambda do |event|
{
time: event.time.to_i,
host: event.payload[:host], # see: config/initializers/lograge.rb
fwd: event.payload[:fwd].try(:inspect),
user_id: event.payload[:user_id]
}
end
But I'd still prefer to be able to do all of this from config/environments/production.rb
along with the above config code. As in, specify a proc which will be called in the context of the controller, so I'd have direct access to the usual things like request
and current_user
. Does that make sense?
in development.rb I have added:
config.lograge.enabled = true
config.lograge.formatter = Lograge::Formatters::Json.new
and when I start the server I get:
config/environments/development.rb:37:in `block in <top (required)>': uninitialized constant Lograge::Formatters (NameError)
Any idea?
I do have the gem 'lograge' in the Gemfile and if I remove the config.lograge.formatter = Lograge::Formatters::Json.new everything works just fine.
Hey, I want to log the logger.debug, logger.info, etc. call in controller information, sunch as callee , FILE, LINE , so I can trace the souce code information in log file.
How can i do that? Please
Hi,
So I've include the gem and added config.lograge.enabled = true
to my config and everything works locally (rails 4.0.1). When I push to heroku I get this error:
A declarative, efficient, and flexible JavaScript library for building user interfaces.
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
An Open Source Machine Learning Framework for Everyone
The Web framework for perfectionists with deadlines.
A PHP framework for web artisans
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
Some thing interesting about web. New door for the world.
A server is a program made to process requests and deliver data to clients.
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
Some thing interesting about visualization, use data art
Some thing interesting about game, make everyone happy.
We are working to build community through open source technology. NB: members must have two-factor auth.
Open source projects and samples from Microsoft.
Google ❤️ Open Source for everyone.
Alibaba Open Source for everyone
Data-Driven Documents codes.
China tencent open source team.