Logging not working, or not well documented

[dmlond]

Logging not working, or not well documented

[zinosama]

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)

[splittingred]

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

gruf/lib/gruf/interceptors/instrumentation/request_logging/interceptor.rb

Line 42 in 7038ae6

LOG_LEVEL_MAP = {

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,
  }
)

[splittingred]

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]

ok. thanks for letting me know.

[splittingred]

@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]

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

[dmlond]

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.

[dmlond]

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

[ankitkalia1195]

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]

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]

$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]

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!