Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logging not working, or not well documented #91

Closed
dmlond opened this issue Jan 18, 2020 · 12 comments
Closed

Logging not working, or not well documented #91

dmlond opened this issue Jan 18, 2020 · 12 comments

Comments

@dmlond
Copy link

dmlond commented Jan 18, 2020

Please describe the issue

I am trying to log information to the log the way I can in a normal rails application

A clear and concise description of what the bug is.
I am trying to add a GRPC service to an existing rails 6 api service. It may be that gruf isnt ready for rails 6.

I have the following in config/initializers/gruf.rb

   Gruf.configure do |c|
        c.server_binding_url = "0.0.0.0:#{grpc_port}"
        c.backtrace_on_error = !Rails.env.production?
        c.use_exception_message = !Rails.env.production?
        c.hooks.use(Gruf::Prometheus::Hook)
        c.rpc_server_options = {
            pool_size: grpc_pool_size,
            pool_keep_alive: grpc_pool_keepalive,
            poll_period: grpc_poll_period
        }
        c.interceptors.use(
            Gruf::Interceptors::Instrumentation::RequestLogging::Interceptor,
            formatter: :logstash
        )
    end

I have tried putting the following in my Controller (which inherits from Gruf::Controllers::Base)

logger.error { "are we there?" }

I also add the following line after the logger.error line to immediately fail the request, which should also log

fail!(:invalid_argument, :jwt_error, "dont get no request with jwt")

This results is a fail response in my client, and nothing is logged

<GRPC::Internal: 13:undefined local variable or method `logger' for #<Authentication::V1::UserInfoServiceController:0x0000563e1bd2e2b8>>

When I ctrl-c the server, the following logs before shutdown:

log writing failed. can't be called from trap context
deadline is 1969-12-31 23:59:59 +0000; (now=2020-01-18 21:31:01 +0000)
schedule another job
Intercepting request with interceptor: Gruf::Interceptors::Instrumentation::RequestLogging::Interceptor
Intercepting request with interceptor: Gruf::Interceptors::Instrumentation::OutputMetadataTimer
Intercepting request with interceptor: Gruf::Interceptors::ActiveRecord::ConnectionReset
app err:#<GRPC::ActiveCall:0x000056369d818e48>, status:13:undefined local variable or method `logger' for #<Authentication::V1::UserInfoServiceController:0x000056369d8185d8>
Sending status  13:undefined local variable or method `logger' for #<Authentication::V1::UserInfoServiceController:0x000056369d8185d8>
[bigcommerce-prometheus][unknown] Prometheus exporter cleanly shut down
Shutting down...
stopping, will wait for all the workers to exit
stopped: #<GRPC::RpcServer:0x000056369c92ce48>
stopped, all workers are shutdown
Goodbye!

I have tried adding the following line to my Controller with the logger.error and fail lines

include Gruf::Loggable

I get the fail response exception in my client

<GRPC::InvalidArgument: 3:dont get no request with jwt>

I do not see anything output in the log until I ctrl-C the server, then I get the following in my log output:

log writing failed. can't be called from trap context
deadline is 1969-12-31 23:59:59 +0000; (now=2020-01-18 21:33:38 +0000)
schedule another job
Intercepting request with interceptor: Gruf::Interceptors::Instrumentation::RequestLogging::Interceptor
Intercepting request with interceptor: Gruf::Interceptors::Instrumentation::OutputMetadataTimer
Intercepting request with interceptor: Gruf::Interceptors::ActiveRecord::ConnectionReset
are we there?
{"message":"[GRPC::InvalidArgument] (authentication.v1.user_info_service.get_user_info) 3:dont get no request with jwt","status":3,"service":"authentication.v1.user_info_service","method":"get_user_info","action":"get_user_info","grpc_status":"GRPC::InvalidArgument","duration":0.48,"thread_id":47097108531520,"time":"2020-01-18 21:33:38 +0000","host":"905332c24f39","format":"json"}
app err:#<GRPC::ActiveCall:0x000055ab4dc6e5c8>, status:3:dont get no request with jwt
Sending status  3:dont get no request with jwt
[bigcommerce-prometheus] Pushing gruf_prometheus_ metrics to type collector: {:type=>"grpc", :pool_jobs_waiting_total=>0, :pool_ready_workers_total=>1, :pool_workers_total=>1, :pool_initial_size=>1, :poll_period=>1}
[bigcommerce-prometheus][unknown] Prometheus exporter cleanly shut down
Shutting down...
stopping, will wait for all the workers to exit
stopped: #<GRPC::RpcServer:0x000055ab4cd93968>
stopped, all workers are shutdown
Goodbye!
Stopping ...
[bigcommerce-prometheus][unknown] Prometheus exporter cleanly shut down

How to Reproduce

Steps to reproduce the behavior:

  1. create the demo application in a rails 6 server
  2. add logging to the demo server code
  3. run the demo client
  4. See error

What should happen?

it should log to the logger output (STDOUT)

Describe what expected behavior should be.

Anything else we should know?

  • gRPC version: libprotoc 3.8.0
  • Ruby version: ruby 2.6.5p114 (2019-10-01 revision 67812) [x86_64-linux]
  • OS: fedora 31
  • Does it occur at certain traffic volumes, payload size, etc
    no all the time
@splittingred
Copy link
Member

Hi @dmlond! Yep, the likelihood is gruf may not have its railtie configured properly for Rails 6. I have tested it with Rails 5 and know it's compat there, but YMMV on how you've got logging initialized with 6.

@dmlond
Copy link
Author

dmlond commented Jan 21, 2020

ok. thanks for letting me know.

@splittingred
Copy link
Member

@dmlond I'll see about getting some time this week to test Rails 6 and see what changes may have affected logging. Thanks for raising this!

@dmlond
Copy link
Author

dmlond commented Jan 22, 2020

great! thanks for building this. I am writing a rails 5 version of my rails 6 grpc service for now.

@dmlond
Copy link
Author

dmlond commented Jan 22, 2020

I am still seeing the same behavior in a rails 5.2.4.1 server. I am running the gruf command. It is loading the gruf.rb initializer, it logs the hostname, then starts the GRPC server, then nothing gets logged again to STDOUT until after I stop the service. I am not sure what I am doing wrong.

@splittingred
Copy link
Member

splittingred commented Jan 22, 2020

Oh, okay. So the RequestLogging interceptor logs at various levels depending on the status code:

LOG_LEVEL_MAP = {
  'GRPC::Ok' => :debug,
  'GRPC::InvalidArgument' => :debug,
  'GRPC::NotFound' => :debug,
  'GRPC::AlreadyExists' => :debug,
  'GRPC::OutOfRange' => :debug,
  'GRPC::Unauthenticated' => :warn,
  'GRPC::PermissionDenied' => :warn,
  'GRPC::Unknown' => :error,
  'GRPC::Internal' => :error,
  'GRPC::DataLoss' => :error,
  'GRPC::FailedPrecondition' => :error,
  'GRPC::Unavailable' => :error,
  'GRPC::DeadlineExceeded' => :error,
  'GRPC::Cancelled' => :error
}.freeze

So unless you have LOG_LEVEL env at debug, you shouldn't see any errors in logs for invalid arguments. (Invalid arguments are validation errors caused by invalid user input, and are not generally considered application-level errors that deserve error severity. This is to prevent log flooding as an attack vector).

You can override this map via the log_levels option on the RequestLogging interceptor, which will just merge over the defaults provided above. So, if you want them to log at info, you could just do:

c.interceptors.use(
  Gruf::Interceptors::Instrumentation::RequestLogging::Interceptor,
  formatter: :logstash,
  log_levels: {
    'GRPC::InvalidArgument' => :info,
  }
)

@dmlond
Copy link
Author

dmlond commented Jan 22, 2020

in https://github.com/bigcommerce/gruf/blob/master/lib/gruf/server.rb at line 88, the start! method creates a thread, logs logger.info { "Starting gruf server at #{@hostname}..." }, then runs server.run. In my logs for the running server, I see the following at startup:

Attaching to user-information-service_grpc_1
grpc_1      | [bigcommerce-prometheus][unknown] Failed to start web instrumentation - undefined method `before_fork_callbacks' for #<Rails::Application::Configuration:0x000055a0d5f74f38>
grpc_1      | Did you mean?  before_eager_load - /usr/local/lib/ruby/gems/2.6.0/gems/railties-5.2.4.1/lib/rails/railtie/configuration.rb:97:in `method_missing'
grpc_1      | /usr/local/lib/ruby/gems/2.6.0/gems/bc-prometheus-ruby-0.2.1/lib/bigcommerce/prometheus/instrumentors/web.rb:65:in `setup_before_fork'
grpc_1      | /usr/local/lib/ruby/gems/2.6.0/gems/bc-prometheus-ruby-0.2.1/lib/bigcommerce/prometheus/instrumentors/web.rb:47:in `start'
grpc_1      | /usr/local/lib/ruby/gems/2.6.0/gems/bc-prometheus-ruby-0.2.1/lib/bigcommerce/prometheus/integrations/railtie.rb:26:in `block in <class:Railtie>'
grpc_1      | /usr/local/lib/ruby/gems/2.6.0/gems/activesupport-5.2.4.1/lib/active_support/lazy_load_hooks.rb:69:in `block in execute_hook'
grpc_1      | - Loading gRPC service file: /opt/app-root/src/app/rpc/authentication/v1/user_info_service_controller.rb
grpc_1      | [gruf-prometheus][authentication_user_info_rpc] Starting Gruf::Server
grpc_1      | [bigcommerce-prometheus][unknown] Registering collector grpc
grpc_1      | [bigcommerce-prometheus][unknown] Registering collector active_record
grpc_1      | [bigcommerce-prometheus][unknown] Starting prometheus exporter on port 0.0.0.0:9004
grpc_1      | [bigcommerce-prometheus][unknown] Prometheus exporter started on 0.0.0.0:9004
grpc_1      | Thin web server (v1.7.2 codename Bachmanity)
grpc_1      | Debugging ON
grpc_1      | Maximum connections set to 1024
grpc_1      | Listening on 0.0.0.0:9004, CTRL+C to stop
grpc_1      | handling /authentication.v1.UserInfoService/GetUserInfo with #<Method: Authentication::V1::UserInfoService::Service#get_user_info>
grpc_1      | [bigcommerce-prometheus] Pushing gruf_prometheus_ metrics to type collector: {:type=>"grpc", :pool_jobs_waiting_total=>0, :pool_ready_workers_total=>0, :pool_workers_total=>0, :pool_initial_size=>30, :poll_period=>1}
grpc_1      | Starting gruf server at 0.0.0.0:9003...
grpc_1      | /usr/local/bin/gruf: No such file or directory - hostname
grpc_1      | Unable to lookup hostname undefined method `strip' for nil:NilClass

I make a request to the grpc service, and get a response, but I do not see anything new in the log. I then stop the grpc server, and the following prints to the log:

grpc_1      | log writing failed. can't be called from trap context
grpc_1      | [bigcommerce-prometheus] Pushing gruf_prometheus_ metrics to type collector: {:type=>"grpc", :pool_jobs_waiting_total=>0, :pool_ready_workers_total=>30, :pool_workers_total=>30, :pool_initial_size=>30, :poll_period=>1}
grpc_1      | deadline is 1969-12-31 23:59:59 +0000; (now=2020-01-22 16:09:38 +0000)
grpc_1      | schedule another job
grpc_1      | Intercepting request with interceptor: Gruf::Interceptors::Instrumentation::RequestLogging::Interceptor
grpc_1      | Intercepting request with interceptor: Gruf::Interceptors::Instrumentation::OutputMetadataTimer
grpc_1      | Intercepting request with interceptor: Gruf::Interceptors::ActiveRecord::ConnectionReset
grpc_1      | get_user_info starting
grpc_1      | {"message":"[GRPC::Ok] (authentication.v1.user_info_service.get_user_info)","status":0,"service":"authentication.v1.user_info_service","method":"get_user_info","action":"get_user_info","grpc_status":"GRPC::Ok","duration":37.0,"thread_id":47074637091540,"time":"2020-01-22 16:09:38 +0000","host":"e9f010684e2b","format":"json"}
grpc_1      | [bigcommerce-prometheus] Pushing gruf_prometheus_ metrics to type collector: {:type=>"grpc", :pool_jobs_waiting_total=>0, :pool_ready_workers_total=>30, :pool_workers_total=>30, :pool_initial_size=>30, :poll_period=>1}
grpc_1      | [bigcommerce-prometheus][unknown] Prometheus exporter cleanly shut down
grpc_1      | Shutting down...
grpc_1      | stopping, will wait for all the workers to exit
grpc_1      | stopped: #<GRPC::RpcServer:0x000055a0d60b3c28>
grpc_1      | stopped, all workers are shutdown
grpc_1      | Goodbye!
grpc_1      | Stopping ...
grpc_1      | [bigcommerce-prometheus][unknown] Prometheus exporter cleanly shut down

I could make lots of requests to the service, but nothing is logged until I stop the server. The key for me is the line that says 'log writing failed. can't be called from trap context'. There is something about running the server in a Thread that is preventing log output until the server shuts down

@zinosama
Copy link

zinosama commented Feb 4, 2020

that may be an issue with rails logger. i think by default gruf sets self.logger = Rails.logger. Maybe try setting logger to ::Logger.new(STDOUT)

@ankitkalia1195
Copy link

ankitkalia1195 commented Jun 26, 2020

I had a similar issue where the gruf logs were not synced immediately, but synced after some number of grpc requests. Setting STDOUT.sync = true solved it for me.

@ld100
Copy link

ld100 commented Sep 9, 2020

Got the same issue, already killed about 6-8 hours on it, and still no luck, none of the solutions above helped.

Any other ideas on how to get Gruf logs to the STDOUT instantly and not just on shutting down the app?

@splittingred
Copy link
Member

$stdout.sync = true is preferred. Gruf is not opinionated here and delegates that control to the upstream service to determine how to control its logging/stream output. If you're logging to $stdout, then it's best to set sync true if you want immediate logs.

@splittingred
Copy link
Member

Closing this - feel free to open another, specific issue if you'd like more clarity in the docs, or find a bug/issue related to this again. Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Development

No branches or pull requests

5 participants