No logs in production from GenServer init function

I’m running a Phoenix app on Fly. I have a GenServer I’m starting as a child in my Application.start/2 function under my MyApp.Supervisor.

I had it crash within the GenServer.init/1 function when the app was starting for a deploy. In the logs there was:

{exit,terminating,[{application_controller,call,2,[{file,"application_controller.erl"},{line,511}]},{application,enqueue_or_start,6,[{file,"application.erl"},{line,380}]},{application,ensure_all_started,3,[{file,"application.erl"},{line,359}]},{elixir,start_cli,0,[{file,"src/elixir.erl"},{line,195}]},{init,start_it,1,[]},{init,start_em,1,[]},{init,do_boot,3,[]}]}
Runtime terminating during boot (terminating)

However, the cause of the crash was not in the logs. When I tested it more, if I try to log in GenServer.init/1 during a successful start with Logger.error("Test log") it also doesn’t end up in the production logs.

The crash and logs show up when I try all these scenarios in dev using either mix or a release.

I found How do I get Phoenix or Elixir to print more detailed logs on a crash? and added:

config :logger, 
   handle_otp_reports: true, 
   handle_sasl_reports: true,
   ...

That gave me more information about the supervisor starting its children, but I still didn’t get any logs from the GenServer init function in production.

My config/prod.exs is:

config :logger,
  level: :info,
  backends: [:console, {Appsignal.Logger.Backend, [group: "phoenix"]}],
  handle_otp_reports: true,
  handle_sasl_reports: true

my config/config.exs is:

config :logger, :console,
  format: "$time $metadata[$level] $message\n",
  metadata: [:request_id]

Any idea why I’m not getting these logs in production (either AppSignal or the console)?

1 Like

Don’t bother with handle_sasl_reports option, it will enable an additional error-level message, but the one you’re interested in is notice-level. This is what I see if I run your case in an empty application in a release locally:

{exit,terminating,[{application_controller,call,2,[{file,"application_controller.erl"},{line,511}]},{application,enqueue_or_start,6,[{file,"application.erl"},{line,380}]},{application,ensure_all_started,3,[{file,"application.erl"},{line,359}]},{elixir,start_cli,0,[{file,"src/elixir.erl"},{line,195}]},{init,start_it,1,[]},{init,start_em,1,[]},{init,do_boot,3,[]}]}

18:14:35.635 [notice] Application log_app exited: LogApp.Application.start(:normal, []) returned an error: shutdown: failed to start child: :foo
    ** (EXIT) an exception was raised:
        ** (RuntimeError) Oops
            (log_app 0.1.0) lib/log_app/application.ex:7: MyServer.init/1
            (stdlib 6.2.1) gen_server.erl:2229: :gen_server.init_it/2
            (stdlib 6.2.1) gen_server.erl:2184: :gen_server.init_it/6
            (stdlib 6.2.1) proc_lib.erl:329: :proc_lib.init_p_do_apply/3
Kernel pid terminated (application_controller) ("{application_start_failure,log_app,{{shutdown,{failed_to_start_child,foo,{#{message => <<\"Oops\">>,'__struct__' => 'Elixir.RuntimeError','__exception__' => true},[{'Elixir.MyServer',init,1,[{file,\"lib/log_app/application.ex\"},{line,7},{error_info,#{module => 'Elixir.Exception'}}]},{gen_server,init_it,2,[{file,\"gen_server.erl\"},{line,2229}]},{gen_server,init_it,6,[{file,\"gen_server.erl\"},{line,2184}]},{proc_lib,init_p_do_apply,3,[{file,\"proc_lib.erl\"},{line,329}]}]}}},{'Elixir.LogApp.Application',start,[normal,[]]}}}")

Which version of Elixir & OTP are you on?

I would try to run the app release locally and/or without appsignal backend as the next step.

There is also this No stack trace in production log - #20 by markmark206 that might be relevant.