<div dir="ltr">Merged a fix to maint for this problem: <a href="https://github.com/erlang/otp/pull/2884">https://github.com/erlang/otp/pull/2884</a></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Fri, Oct 9, 2020 at 1:43 PM Lukas Larsson <<a href="mailto:lukas@erlang.org">lukas@erlang.org</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div dir="ltr">Hello,<div><br></div><div>This seems to be the logger proxy, i.e. the process that logs messages sent by the emulator and other nodes. </div><div><br></div><div>It should not crash when receiving these late replies to gen_server:call/2. I will prepare a patch for it.</div><div><br></div><div>In OTP-24 there is a proposal for process aliases (<a href="https://github.com/erlang/otp/pull/2735" target="_blank">https://github.com/erlang/otp/pull/2735</a>) that should get rid of these types of bugs.</div><div><br></div><div>Lukas</div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Fri, Oct 9, 2020 at 11:47 AM Andreas Schultz <<a href="mailto:andreas.schultz@travelping.com" target="_blank">andreas.schultz@travelping.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div>Hi,</div><div><br></div><div>If got some really strange crashes of the logger and errors from supervisor on 22.1.7:</div><div><br></div><div><font face="monospace">2020-10-08T20:29:11.310911+00:00 error: Generic server <0.934.0> terminating. Reason: {function_clause,[{logger_proxy,handle_info,[{#Ref<0.3534272603.1552154625.127680>,ok},no_state],[{file,"logger_proxy.erl"},{line,136}]},{logger_olp,try_callback_call,4,[{file,"logger_olp.erl"},{line,598}]},{logger_olp,handle_info,2,[{file,"logger_olp.erl"},{line,270}]},{gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,680}]},{gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,756}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,226}]}]}. Last message: {#Ref<0.3534272603.1552154625.127680>,ok}. State: #{burst_limit_enable => false,burst_limit_max_count => 500,burst_limit_window_time => 1000,burst_msg_count => 0,burst_win_ts => -576460751230297,cb_state => no_state,drop_mode_qlen => 1000,flush_qlen => 5000,id => logger_proxy,idle => false,last_load_ts => -575306488755097,last_qlen => 1,mode => async,mode_ref => {logger_olp,logger_proxy},module => logger_proxy,overload_kill_enable => false,overload_kill_mem_size => 3000000,overload_kill_qlen => 20000,overload_kill_restart_after => 5000,sync_mode_qlen => 500}.<br>2020-10-08T20:29:12.179509+00:00 error: Supervisor received unexpected message: {#Ref<0.3534272603.1029701639.174367>,ok}<br>2020-10-08T20:29:13.992900+00:00 error: Supervisor received unexpected message: {#Ref<0.3534272603.1029701639.174370>,ok}<br>2020-10-08T20:29:12.797713+00:00 error: crasher: initial call: logger_olp:init/1, pid: <0.934.0>, registered_name: [], error: {function_clause,[{logger_proxy,handle_info,[{#Ref<0.3534272603.1552154625.127680>,ok},no_state],[{file,"logger_proxy.erl"},{line,136}]},{logger_olp,try_callback_call,4,[{file,"logger_olp.erl"},{line,598}]},{logger_olp,handle_info,2,[{file,"logger_olp.erl"},{line,270}]},{gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,680}]},{gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,756}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,226}]}]}, ancestors: [logger_sup,kernel_sup,<0.902.0>], message_queue_len: 1, messages: [{#Ref<0.3534272603.1552154625.128792>,ok}], links: [<0.932.0>], dictionary: [{olp_ref,{logger_proxy,<0.934.0>,{logger_olp,logger_proxy}}}], trap_exit: true, status: running, heap_size: 987, stack_size: 28, reductions: 84949; neighbours:<br>2020-10-08T20:29:15.492989+00:00 error: Supervisor received unexpected message: {#Ref<0.3534272603.1322254338.95824>,ok}<br>2020-10-08T20:29:21.399535+00:00 error: Supervisor received unexpected message: {#Ref<0.3534272603.1322254338.95915>,ok}<br>2020-10-08T20:29:22.982660+00:00 error: Supervisor: {local,logger_sup}. Context: child_terminated. Reason: {function_clause,[{logger_proxy,handle_info,[{#Ref<0.3534272603.1552154625.127680>,ok},no_state],[{file,"logger_proxy.erl"},{line,136}]},{logger_olp,try_callback_call,4,[{file,"logger_olp.erl"},{line,598}]},{logger_olp,handle_info,2,[{file,"logger_olp.erl"},{line,270}]},{gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,680}]},{gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,756}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,226}]}]}. Offende<br></font></div><div><br></div><div>It seems that somehow unhandled {Ref, ok} message got into the inbox of the servers. I'm pretty sure that my code is not sending those messages to random processes. Does anyone have an idea how this could happen?</div><div><br></div><div>One clue might be that the system was under heavy load, possibly overloaded as this log entry suggests:</div><div><br></div><div><font face="monospace">2020-10-08T20:28:15.676829+00:00 error: Error in process <0.4111.816> on node 'gtphub-c-node@ash-prd-tvp-gtphub-mvne-2' with exit value:, {{badmatch,{error,timeout}},[{cpu_sup,measurement_server_init,0,[{file,"cpu_sup.erl"},{line,502}]}]}</font><br></div><div><font face="arial, sans-serif"><br></font></div><div><font face="arial, sans-serif">The stray message could be left over from a timed out gen call. If that is the case and late replies from calls can happen, then clearly the logger process should handle them more gracefully.</font></div><div><br></div><div><font face="monospace"><br></font></div>-- <br><div dir="ltr"><p><span style="font-family:verdana,geneva,sans-serif;font-size:10pt">Andreas Schultz<br></span></p>
</div></div>
</blockquote></div></div>
</blockquote></div>