search

grafana / pyroscope-rs

Pyroscope Profiler for Rust. Profile your Rust applications.
Apache License 2.0
132 stars 22 forks source link

Panic initializing the logger from ruby gem #147

Open BrianHawley opened 3 months ago

BrianHawley commented 3 months ago

Describe the bug you encountered:

Trying to configure Pyroscope from Ruby, and I got a panic on the initialize_logger call.

thread '<unnamed>' panicked at 'called `Result::unwrap()` on an `Err` value: SetLoggerError(())', /Users/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/pretty_env_logger-0.4.0/src/lib.rs:74:22
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
fatal runtime error: failed to initiate panic, error 5

What did you expect to happen instead?

It should have initialized.

How did you install pyroscope-rs?

gem "pyroscope"

Then configured it with (just showing the code that ran before the crash):

require "bundler/setup"
require "pyroscope"

Pyroscope.configure do |config|
  config.application_name = "something"
end

Note that no other gems were loaded, aside from bundler itself, because I was wanting to profile startup times. I also tried loading it after all the other gems loaded, and got the same result.

pyroscope-rs version and environment

Ruby 3.1.2 macOS Ventura 13.6.5, Intel Core i9 pyroscope gem 0.5.10 (pyroscope-0.5.10-x86_64-darwin.gem)

BrianHawley commented 3 months ago

I also ran it with RUST_BACKTRACE=1 as suggested:

thread '<unnamed>' panicked at 'called `Result::unwrap()` on an `Err` value: SetLoggerError(())', /Users/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/pretty_env_logger-0.4.0/src/lib.rs:74:22
stack backtrace:
   0: _rust_begin_unwind
   1: core::panicking::panic_fmt
   2: core::result::unwrap_failed
   3: _initialize_logging
   4: <unknown>
   5: <unknown>
   6: rbffi_CallFunction
             at /Users/t442172/.rvm/gems/ruby-3.1.2@deluxe/gems/ffi-1.16.3/ext/ffi_c/Call.c:400:9
   7: custom_trampoline
             at /Users/t442172/.rvm/gems/ruby-3.1.2@deluxe/gems/ffi-1.16.3/ext/ffi_c/MethodHandle.c:222:34
   8: vm_call_cfunc_with_frame
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:3037:11
   9: vm_sendish
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:4751:15
  10: vm_exec_core
             at /Users/t442172/.rvm/src/ruby-3.1.2/insns.def:778:11
  11: rb_vm_exec
  12: load_iseq_eval
             at /Users/t442172/.rvm/src/ruby-3.1.2/load.c:656:5
  13: rb_load_internal
             at /Users/t442172/.rvm/src/ruby-3.1.2/load.c:717:9
  14: rb_f_load
             at /Users/t442172/.rvm/src/ruby-3.1.2/load.c:792:5
  15: vm_call_cfunc_with_frame
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:3037:11
  16: vm_sendish
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:4751:15
  17: vm_exec_core
             at /Users/t442172/.rvm/src/ruby-3.1.2/insns.def:778:11
  18: rb_vm_exec
  19: invoke_iseq_block_from_c
  20: invoke_block_from_c_bh
             at /Users/t442172/.rvm/src/ruby-3.1.2/vm.c:1390:13
  21: rb_yield
  22: rb_ary_each
             at /Users/t442172/.rvm/src/ruby-3.1.2/array.c:2522:2
  23: vm_call_cfunc_with_frame
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:3037:11
  24: vm_sendish
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:4751:15
  25: vm_exec_core
             at /Users/t442172/.rvm/src/ruby-3.1.2/insns.def:759:11
  26: rb_vm_exec
  27: invoke_iseq_block_from_c
  28: invoke_block_from_c_bh
             at /Users/t442172/.rvm/src/ruby-3.1.2/vm.c:1390:13
  29: vm_yield_with_cref
             at /Users/t442172/.rvm/src/ruby-3.1.2/vm.c:1427:12
  30: yield_under
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_eval.c:1969:12
  31: vm_call_cfunc_with_frame
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:3037:11
  32: vm_sendish
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:4751:15
  33: vm_exec_core
             at /Users/t442172/.rvm/src/ruby-3.1.2/insns.def:759:11
  34: rb_vm_exec
  35: invoke_iseq_block_from_c
  36: invoke_block_from_c_bh
             at /Users/t442172/.rvm/src/ruby-3.1.2/vm.c:1390:13
  37: rb_yield
  38: rb_ary_each
             at /Users/t442172/.rvm/src/ruby-3.1.2/array.c:2522:2
  39: vm_call_cfunc_with_frame
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:3037:11
  40: vm_sendish
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:4751:15
  41: vm_exec_core
             at /Users/t442172/.rvm/src/ruby-3.1.2/insns.def:759:11
  42: rb_vm_exec
  43: rb_vm_call0
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_eval.c:57:12
  44: rb_vm_call_kw
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_eval.c:302:12
  45: call_method_data
             at /Users/t442172/.rvm/src/ruby-3.1.2/proc.c:2422:12
  46: rb_method_call_with_block_kw
             at /Users/t442172/.rvm/src/ruby-3.1.2/proc.c:2436:12
  47: rb_method_call_pass_called_kw
             at /Users/t442172/.rvm/src/ruby-3.1.2/proc.c:2393:12
  48: vm_call_cfunc_with_frame
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:3037:11
  49: vm_sendish
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:4751:15
  50: vm_exec_core
             at /Users/t442172/.rvm/src/ruby-3.1.2/insns.def:759:11
  51: rb_vm_exec
  52: invoke_iseq_block_from_c
  53: invoke_block_from_c_bh
             at /Users/t442172/.rvm/src/ruby-3.1.2/vm.c:1390:13
  54: rb_yield
  55: rb_ary_each
             at /Users/t442172/.rvm/src/ruby-3.1.2/array.c:2522:2
  56: vm_call0_cfunc_with_frame
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_eval.c:149:15
  57: vm_call0_cfunc
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_eval.c:163:12
  58: vm_call0_body
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_eval.c:209:15
  59: rb_vm_call0
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_eval.c:57:12
  60: rb_vm_call_kw
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_eval.c:302:12
  61: call_method_data
             at /Users/t442172/.rvm/src/ruby-3.1.2/proc.c:2422:12
  62: rb_method_call_with_block_kw
             at /Users/t442172/.rvm/src/ruby-3.1.2/proc.c:2436:12
  63: rb_method_call_pass_called_kw
             at /Users/t442172/.rvm/src/ruby-3.1.2/proc.c:2393:12
  64: vm_call_cfunc_with_frame
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:3037:11
  65: vm_sendish
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:4751:15
  66: vm_exec_core
             at /Users/t442172/.rvm/src/ruby-3.1.2/insns.def:759:11
  67: rb_vm_exec
  68: load_iseq_eval
             at /Users/t442172/.rvm/src/ruby-3.1.2/load.c:656:5
  69: require_internal
             at /Users/t442172/.rvm/src/ruby-3.1.2/load.c:1132:21
  70: rb_require_string
             at /Users/t442172/.rvm/src/ruby-3.1.2/load.c:1223:18
  71: rb_f_require
             at /Users/t442172/.rvm/src/ruby-3.1.2/load.c:904:12
  72: vm_call_cfunc_with_frame
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:3037:11
  73: vm_call_method_each_type
  74: vm_sendish
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:4751:15
  75: vm_exec_core
             at /Users/t442172/.rvm/src/ruby-3.1.2/insns.def:778:11
  76: rb_vm_exec
  77: load_iseq_eval
             at /Users/t442172/.rvm/src/ruby-3.1.2/load.c:656:5
  78: require_internal
             at /Users/t442172/.rvm/src/ruby-3.1.2/load.c:1132:21
  79: rb_require_string
             at /Users/t442172/.rvm/src/ruby-3.1.2/load.c:1223:18
  80: rb_f_require
             at /Users/t442172/.rvm/src/ruby-3.1.2/load.c:904:12
  81: vm_call_cfunc_with_frame
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:3037:11
  82: vm_call_alias
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:3189:12
  83: vm_sendish
             at /Users/t442172/.rvm/src/ruby-3.1.2/./vm_insnhelper.c:4751:15
  84: vm_exec_core
             at /Users/t442172/.rvm/src/ruby-3.1.2/insns.def:778:11
  85: rb_vm_exec
  86: rb_ec_exec_node
             at /Users/t442172/.rvm/src/ruby-3.1.2/eval.c:280:2
  87: ruby_run_node
             at /Users/t442172/.rvm/src/ruby-3.1.2/eval.c:321:30
  88: main
             at /Users/t442172/.rvm/src/ruby-3.1.2/./main.c:47:9
  89: <unknown>
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
fatal runtime error: failed to initiate panic, error 5
BrianHawley commented 3 months ago

With RUST_BACKTRACE=full I get this:

thread '<unnamed>' panicked at 'called `Result::unwrap()` on an `Err` value: SetLoggerError(())', /Users/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/pretty_env_logger-0.4.0/src/lib.rs:74:22
stack backtrace:
   0:        0x10d4621ba - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hae51cb91d407e2ef
   1:        0x10d219f6b - core::fmt::write::h746bc0969202388b
   2:        0x10d43feec - std::io::Write::write_fmt::h4098c2c7437a0bd7
   3:        0x10d465eda - std::sys_common::backtrace::print::h8360bf0158e89b36
   4:        0x10d465b01 - std::panicking::default_hook::{{closure}}::hedf04c568eb6e0bc
   5:        0x10d466b36 - std::panicking::rust_panic_with_hook::h22edd02828aff274
   6:        0x10d466635 - std::panicking::begin_panic_handler::{{closure}}::h6895f44a9b7e2caa
   7:        0x10d466599 - std::sys_common::backtrace::__rust_end_short_backtrace::h013519e9b77978c5
   8:        0x10d466582 - _rust_begin_unwind
   9:        0x10d4a9dc3 - core::panicking::panic_fmt::h2a51b60c12d11322
  10:        0x10d4aa0c5 - core::result::unwrap_failed::h52a6a55d409027df
  11:        0x10d1f2efd - _initialize_logging
  12:     0x7ff825e4d8c2 - <unknown>
  13:     0x7ff825e4d214 - <unknown>
...

The rest is the same backtrace as before, but with addresses added.

BrianHawley commented 3 months ago

Looks like the code is calling:

pretty_env_logger::init_timed();

I checked the source of that, and internally it's calling the try_init_timed() function, which returns a Result<(), log::SetLoggerError>, then it's just calling unwrap() which panics unless the result was successful. Unfortunately, the call to try_init_timed() failed, and it threw away the failure result that said why it failed when it just called unwrap().

It might be better to call pretty_env_logger::try_init_timed() and then check for a successful or failed result, and report the failure somehow if the result failed.

You might also look into updating pretty_env_logger. The current version is 0.5.0.

BrianHawley commented 2 months ago

I checked the new version that came out on April 15, and it still has the same issue.