larskrantz / logger_papertrail_backend

A Papertrail backend for Elixir Logger
MIT License
53 stars 13 forks source link

Application crash due to "{:error, :emfile}" #6

Closed hamann closed 7 years ago

hamann commented 8 years ago

Today we had more traffic as usual on our website and after a while the application crashed

otp: 19.1.3 logger_papertrail_backend: 0.1

Last lines from error log at that time:

2016-10-25 21:08:01.950 [error] Child LoggerPapertrailBackend.Sender of Supervisor LoggerPapertrailBackend.Supervisor terminated
** (exit) an exception was raised:
    ** (MatchError) no match of right hand side value: {:error, :emfile}
        (logger_papertrail_backend) lib/logger_papertrail_backend/sender.ex:17: LoggerPapertrailBackend.Sender.handle_cast/2
        (stdlib) gen_server.erl:601: :gen_server.try_dispatch/4
        (stdlib) gen_server.erl:667: :gen_server.handle_msg/5
        (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
Pid: #PID<0.21007.866>
Start Call: LoggerPapertrailBackend.Sender.start_link()
2016-10-25 21:08:01.951 [error] GenServer LoggerPapertrailBackend.Sender terminating
** (MatchError) no match of right hand side value: {:error, :emfile}
    (logger_papertrail_backend) lib/logger_papertrail_backend/sender.ex:17: LoggerPapertrailBackend.Sender.handle_cast/2
    (stdlib) gen_server.erl:601: :gen_server.try_dispatch/4
    (stdlib) gen_server.erl:667: :gen_server.handle_msg/5
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
2016-10-25 21:08:01.952 [error] Process LoggerPapertrailBackend.Sender (#PID<0.20891.866>) terminating
** (exit) an exception was raised:
    ** (MatchError) no match of right hand side value: {:error, :emfile}
        (logger_papertrail_backend) lib/logger_papertrail_backend/sender.ex:17: LoggerPapertrailBackend.Sender.handle_cast/2
        (stdlib) gen_server.erl:601: :gen_server.try_dispatch/4
        (stdlib) gen_server.erl:667: :gen_server.handle_msg/5
        (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
    (stdlib) gen_server.erl:812: :gen_server.terminate/7
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
Initial Call: LoggerPapertrailBackend.Sender.init/1
Ancestors: [LoggerPapertrailBackend.Supervisor, #PID<0.2330.0>]
2016-10-25 21:08:01.954 [error] Child LoggerPapertrailBackend.Sender of Supervisor LoggerPapertrailBackend.Supervisor terminated
** (exit) an exception was raised:
    ** (MatchError) no match of right hand side value: {:error, :emfile}
        (logger_papertrail_backend) lib/logger_papertrail_backend/sender.ex:17: LoggerPapertrailBackend.Sender.handle_cast/2
        (stdlib) gen_server.erl:601: :gen_server.try_dispatch/4
        (stdlib) gen_server.erl:667: :gen_server.handle_msg/5
        (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
Pid: #PID<0.20891.866>
Start Call: LoggerPapertrailBackend.Sender.start_link()
2016-10-25 21:08:01.955 [error] Child LoggerPapertrailBackend.Sender of Supervisor LoggerPapertrailBackend.Supervisor caused shutdown
** (exit) :reached_max_restart_intensity

Extract from crash dump

=erl_crash_dump:0.3
Tue Oct 25 21:08:09 2016
Slogan: Kernel pid terminated (application_controller) ({application_terminated,logger_papertrail_backend,shutdown})
System version: Erlang/OTP 19 [erts-8.1] [source-4cc2ce3] [64-bit] [smp:4:4] [async-threads:10] [hipe] [kernel-poll:false]
Compiled: Wed Oct 12 12:53:26 2016
larskrantz commented 8 years ago

Ok,as far as I understand, the :emfile-error means that all system file descriptors are out, and that there's no room for the single socket that logger needs for sending. Since it's a single process gen_server that closes it's socket, I doubt it's papertrail-logger that's the underlying problem. A viable solution should be rewriting sender to cache up messages. A future version should probably use GenStage.

hamann commented 8 years ago

@larskrantz yeah, probably we ran out of file descriptors due to some OS limits. just wanted to let you know that such problem could occur

larskrantz commented 8 years ago

Thanks, will have it mind!

hamann commented 8 years ago

@larskrantz what do you think about sharing the socket instead of opening/closing a socket each time a log message is generated?

    {:ok, socket} = :gen_udp.open(0)
    :gen_udp.send(socket, ip, port, message)
    :gen_udp.close(socket)

That should solve the problem above, and on busy and chatty systems it should be less expensive

larskrantz commented 8 years ago

Yes, I'll try a version opening the socket at init, since its a 0-udp-socket I guess it's ok to have it open all the time and store it in state (and close it at termination).