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.

Sign up for GitHub

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

Jump to bottom

Panic initializing the logger from ruby gem #147

Open
BrianHawley opened this issue Mar 13, 2024 · 4 comments
Open

Panic initializing the logger from ruby gem #147

BrianHawley opened this issue Mar 13, 2024 · 4 comments
Labels
bug Something isn't working

Comments

@BrianHawley
Copy link

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 BrianHawley added the bug Something isn't working label Mar 13, 2024
@BrianHawley
Copy link
Author

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
Copy link
Author

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
Copy link
Author

BrianHawley commented Mar 13, 2024 •
edited
Loading

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
Copy link
Author

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@BrianHawley