<html><head><meta http-equiv="Content-Type" content="text/html; charset=utf-8"></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; line-break: after-white-space;" class="">Hi Raimo,<div class=""><br class=""></div><div class="">I’ve tried your patch and it hasn’t caused any errors. We are still having problems reproducing the issue, but it at least doesn’t look to have caused any side effects.</div><div class=""><br class=""></div><div class="">Regards,</div><div class="">Peter.<br class=""><div><br class=""><blockquote type="cite" class=""><div class="">On 25 Apr 2019, at 08:28, Raimo Niskanen <<a href="mailto:raimo+erlang-questions@erlang.org" class="">raimo+erlang-questions@erlang.org</a>> wrote:</div><br class="Apple-interchange-newline"><div class=""><span style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none; float: none; display: inline !important;" class="">On Wed, Apr 24, 2019 at 06:46:27PM +0100, Peter Morgan wrote:</span><br style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none;" class=""><blockquote type="cite" style="font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: auto; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; widows: auto; word-spacing: 0px; -webkit-text-size-adjust: auto; -webkit-text-stroke-width: 0px; text-decoration: none;" class="">Hi Raimo,<br class=""><br class="">I am having great difficultly reproducing in a simple test case. Despite best efforts of hundreds of thousands of processes creating timers and retry_state I’ve not managed to reproduce our production issue - with a vanilla OTP21 without your patch. Will let you know if I do.<br class=""><br class=""></blockquote><br style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none;" class=""><span style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none; float: none; display: inline !important;" class="">Can you try my patch on OTP-21 - pull/2211 to see if it works without</span><br style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none;" class=""><span style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none; float: none; display: inline !important;" class="">errors in your original setup?</span><br style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none;" class=""><br style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none;" class=""><span style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none; float: none; display: inline !important;" class="">/ Raimo</span><br style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none;" class=""><br style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none;" class=""><br style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none;" class=""><br style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none;" class=""><blockquote type="cite" style="font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: auto; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; widows: auto; word-spacing: 0px; -webkit-text-size-adjust: auto; -webkit-text-stroke-width: 0px; text-decoration: none;" class="">Thanks again for your help on this issue.<br class=""><br class="">Regards,<br class="">Peter.<br class=""><br class=""><blockquote type="cite" class="">On 17 Apr 2019, at 15:36, Raimo Niskanen <<a href="mailto:raimo+erlang-questions@erlang.org" class="">raimo+erlang-questions@erlang.org</a>> wrote:<br class=""><br class="">On Wed, Apr 17, 2019 at 11:54:42AM +0200, Raimo Niskanen wrote:<br class=""><blockquote type="cite" class="">After some discussions with the VM guys this seems to be a bug in<br class="">gen_statem coming from a misunderstanding of which guarantees that<br class="">asynchronous timer cancels gives and does not give.<br class=""><br class="">The {timeout, Ref, Msg} message may actually come _after_ the<br class="">{cancel_timer, Ref, false} message. Heavy load seems to increase the<br class="">probability from almost zero to very small.<br class=""><br class="">So the handling of these messages is broken for gen_statem on OTP-21, but<br class="">this should be fixed on master (soon to be OTP-22) since gen_statem there<br class="">does not use asynchronous timer cancels.<br class=""><br class="">I will look into how big a diff it will be to rewrite gen_statem in OTP-21.latest<br class="">to use synchronous timer cancel...<br class=""></blockquote><br class="">The diff became a fat one, so I created a pull request:<br class=""><br class=""> <a href="https://github.com/erlang/otp/pull/2211" class="">https://github.com/erlang/otp/pull/2211</a><span class="Apple-converted-space"> </span><<a href="https://github.com/erlang/otp/pull/2211" class="">https://github.com/erlang/otp/pull/2211</a>><br class=""><br class="">If you can try it out, that would be awsome!<br class=""><br class="">Best Regards<br class="">/ Raimo<br class=""><br class=""><br class=""><br class=""><blockquote type="cite" class=""><br class="">Thank you for finding a tricky bug!<br class="">/ Raimo<br class=""><br class=""><br class=""><br class="">On Fri, Apr 12, 2019 at 04:13:27PM +0100, Peter Morgan wrote:<br class=""><blockquote type="cite" class="">Hi Raimo,<br class=""><br class="">Thanks for looking at this, and the background on the implementation which is very useful. I am in the process of putting together a simple test case, but having trouble reproducing it. It appears to happen very infrequently - possibly something that is load related? The original output was from the Crash Report which I’ve attached - where you can see the info timeout was received by our gen_statem behaviour callback. Our OTP is 21.2 (without any 21.2.X patches):<br class=""><br class="">{stdlib,"ERTS CXC 138 10","3.7”}<br class="">{kernel,"ERTS CXC 138 10","6.2”}<br class=""><br class=""><br class="">Your question - “why so many?” - it could be a failure of a downstream service that is ultimately causing this, and we’re not backing off in this case - something that I’m checking too. However, I still thought it was interesting that the info timeout reaches the behaviour module.<br class=""><br class=""></blockquote><br class=""><blockquote type="cite" class="">=CRASH REPORT==== 8-Apr-2019::23:37:19.038905 === <0.969.0> proc_lib:crash_report/4:508<br class="">crasher:<br class=""> initial call: kafire_fetcher:init/1<br class=""> pid: <0.969.0><br class=""> registered_name: []<br class=""> exception error: no function clause matching<span class="Apple-converted-space"> </span><br class=""> kafire_fetcher:handle_event(info,<br class=""> {timeout,<br class=""> #Ref<0.2399112782.889192450.118024>,<br class=""> fetch},<br class=""> subsequent_fetches,<br class=""> our_state) (src/kafire_fetcher.erl, line 445)<br class=""> in function gen_statem:call_state_function/5 (gen_statem.erl, line 1662)<br class=""> in call from gen_statem:loop_event_state_function/6 (gen_statem.erl, line 1023)<br class=""> ancestors: [<0.931.0>,<0.332.0>,kafire_cluster_sup,kafire_sup,<0.227.0>]<br class=""> message_queue_len: 279<br class=""> messages: [{timeout,#Ref<0.2399112782.903610369.70160>,fetch},<br class=""> {cancel_timer,#Ref<0.2399112782.903610369.70160>,false},<br class=""> {cancel_timer,#Ref<0.2399112782.903610369.70168>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118038>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118039>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118043>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118044>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118045>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118049>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118050>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118051>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118052>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118053>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118054>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118055>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118056>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118060>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118061>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118062>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118063>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118064>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118068>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118069>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118070>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118071>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118074>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118079>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118081>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118083>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118087>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118088>,0},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118089>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118093>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118094>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118095>,3},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118096>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118097>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118098>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118099>,3},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118103>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118104>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118105>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118106>,3},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118107>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118108>,1},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118109>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118113>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118114>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118115>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118116>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118117>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118118>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118119>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118120>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118121>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118122>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118123>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118124>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118125>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118126>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118127>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118128>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118129>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118130>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118131>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118132>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118133>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118134>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118135>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118136>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118137>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118138>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118139>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118140>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118141>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118145>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118146>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118147>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118148>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118149>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118150>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118151>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118152>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118153>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118154>,5},<br class=""> {timeout,#Ref<0.2399112782.889192450.118159>,fetch},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118159>,false},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118165>,0},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118169>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118170>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118173>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118174>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118175>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118176>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118177>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118178>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118179>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118180>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118181>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118182>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118183>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118184>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118185>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118189>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118190>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118191>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118192>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118196>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118197>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118198>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118199>,5},<br class=""> {timeout,#Ref<0.2399112782.889192450.118203>,fetch},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118203>,false},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118206>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118207>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118208>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118212>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118213>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118214>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118215>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118221>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118225>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118226>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118227>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118231>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118235>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118236>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118237>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118238>,2},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118242>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118243>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118244>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118248>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118249>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118250>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118254>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118255>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118256>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118260>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118264>,0},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118265>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118266>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118270>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118271>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118272>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118273>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118274>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118278>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118279>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118280>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118281>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118282>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118283>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118287>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118288>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118289>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118290>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118291>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118295>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118296>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118297>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118298>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118299>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118303>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118304>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118305>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118306>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118307>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118308>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118309>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118313>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118314>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118315>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118316>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118317>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118318>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118319>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118323>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118324>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118325>,5},<br class=""> {timeout,#Ref<0.2399112782.889192450.118326>,fetch},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118326>,false},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118327>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118328>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118329>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118330>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118331>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118332>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118333>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118337>,3},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118338>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118339>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118340>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118344>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118345>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118346>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118347>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118351>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118352>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118353>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118357>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118358>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118359>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118360>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118364>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118365>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118366>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118367>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118371>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118372>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118373>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118377>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118378>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118379>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118383>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118384>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118385>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118389>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118390>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118391>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118392>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118393>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118394>,0},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118395>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118399>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118400>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118401>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118402>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118403>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118404>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118405>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118409>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118410>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118411>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118412>,1},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118413>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118414>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118415>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118419>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118420>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118421>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118422>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118423>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118424>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118425>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118429>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118430>,0},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118431>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118432>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118433>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118434>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118435>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118439>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118440>,1},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118441>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118442>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118443>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118444>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118445>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118449>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118450>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118451>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118452>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118453>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118454>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118455>,5},<br class=""> {timeout,#Ref<0.2399112782.889192450.118456>,fetch},<br class=""> {'EXIT',<0.10080.8>,normal},<br class=""> {'EXIT',<0.10079.8>,normal},<br class=""> {'EXIT',<0.10081.8>,normal},<br class=""> {'EXIT',<0.10082.8>,normal},<br class=""> {'EXIT',<0.10083.8>,normal},<br class=""> {'EXIT',<0.10084.8>,normal},<br class=""> {'EXIT',<0.10085.8>,normal},<br class=""> {'EXIT',<0.10086.8>,normal},<br class=""> {'EXIT',<0.10087.8>,normal},<br class=""> {'EXIT',<0.10088.8>,normal},<br class=""> {'EXIT',<0.10089.8>,normal},<br class=""> {'EXIT',<0.10071.8>,normal}]<br class=""> links: [<0.931.0>]<br class=""> dictionary: []<br class=""> trap_exit: true<br class=""> status: running<br class=""> heap_size: 17731<br class=""> stack_size: 27<br class=""> reductions: 28849413204<br class="">neighbours:<br class=""></blockquote><br class=""><blockquote type="cite" class=""><br class=""><br class="">I’ll try and get a simple test case for you.<br class="">Regards,<br class="">Peter.<br class=""><br class=""><br class=""><br class=""><blockquote type="cite" class="">On 12 Apr 2019, at 13:38, Raimo Niskanen <<a href="mailto:raimo+erlang-questions@erlang.org" class="">raimo+erlang-questions@erlang.org</a>> wrote:<br class=""><br class="">On Fri, Apr 12, 2019 at 10:38:42AM +0200, Raimo Niskanen wrote:<br class=""><blockquote type="cite" class="">On Wed, Apr 10, 2019 at 01:41:06PM +0100, Peter Morgan wrote:<br class=""><blockquote type="cite" class="">Hello -<br class=""><br class="">We are _sometimes_ seeing cases where a state_timeout in a gen_statem results in the timeout reaching the callback module as info {timeout, Ref, Name} with OTP 21.2.<br class=""><br class="">The crash looks like:<br class=""><br class="">=ERROR REPORT==== 8-Apr-2019::23:37:19.035346 === <0.969.0> gen_statem:error_info/5:1895<br class="">** State machine {kafire_fetcher,<<“abc">>,<<“def">>,0} terminating<br class="">** Last event = {info,{timeout,#Ref<0.2399112782.889192450.118024>,fetch}}<br class=""><br class="">We crash because we are not expecting info messages - interestingly the following messages are in the queue for the crashed process:<br class=""><br class=""><br class=""> message_queue_len: 279<br class=""> messages: [{timeout,#Ref<0.2399112782.903610369.70160>,fetch},<br class=""> {cancel_timer,#Ref<0.2399112782.903610369.70160>,false},<br class=""> {cancel_timer,#Ref<0.2399112782.903610369.70168>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118038>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118039>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118043>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118044>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118045>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118049>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118050>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118051>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118052>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118053>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118054>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118055>,4},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118056>,5},<br class=""> {cancel_timer,#Ref<0.2399112782.889192450.118060>,5},<br class=""></blockquote><br class="">Is that from a process_info() call?<br class=""><br class=""><blockquote type="cite" class=""><br class="">Followed by lots more cancel_timer messages (200ish!). Our gen_statem does use {state_timeout, 500, fetch} so we are expecting a “fetch” timeout to happen, and we use repeat_state_and_data to requeue the state timeout (and also transition to other states). Is it possible that timeouts in gen_statem can be delivered as an info message?<br class=""></blockquote><br class="">It is not supposed to happen. This must be a bug.<br class=""><br class="">The gen_statem engine keeps track of the running state_timeout timer<br class="">and should never present it as an info event.<br class=""><br class="">When a timer is stopped (or restarted) it is done with an asynchronous<br class="">cancel (in OTP 21) so the cancel_timer messages comes from that.<br class="">They should be matched against map entries in the internal gen_statem<br class="">engine state when they arrive so them being in the inbox may be ok.<br class=""><br class="">However, how come you have so many? Are you restarting the state_timeout<br class="">in a very tight loop of repeat_state:s? Can you show the essential parts<br class="">of the code that causes state_timeout:s?<br class=""><br class="">Also - OTP-21.2; is that your exact OTP version? What is your stdlib version?<br class=""><br class="">I will look at the relevant parts of the code with the new knowledge that<br class="">a state_timeout timer can be lost, probably in combination with<br class="">repeat_state and state_timeout restart!<br class=""></blockquote><br class=""><br class="">Sorry, the knowledge did not help; I did not find anything suspicous.<br class=""><br class="">More information will be needed...<br class=""><br class=""><blockquote type="cite" class=""><br class="">On master since Jan 21 so in OTP-22.0-rc1 among other changes the timer handling<br class="">has been rewritten to use a synchronous cancel, which simplified the code<br class="">significantly. I do not know if that would be worth trying?<br class=""><br class="">/ Raimo Niskanen<br class=""><br class=""><br class=""><blockquote type="cite" class=""><br class="">Thanks<br class="">Peter.<br class=""><br class=""></blockquote></blockquote><br class="">--<span class="Apple-converted-space"> </span><br class=""><br class="">/ Raimo Niskanen, Erlang/OTP, Ericsson AB<br class="">_______________________________________________<br class="">erlang-questions mailing list<br class=""><a href="mailto:erlang-questions@erlang.org" class="">erlang-questions@erlang.org</a><br class="">http://erlang.org/mailman/listinfo/erlang-questions<br class=""></blockquote><br class=""></blockquote><br class=""><br class="">--<span class="Apple-converted-space"> </span><br class=""><br class="">/ Raimo Niskanen, Erlang/OTP, Ericsson AB<br class="">_______________________________________________<br class="">erlang-questions mailing list<br class=""><a href="mailto:erlang-questions@erlang.org" class="">erlang-questions@erlang.org</a><br class="">http://erlang.org/mailman/listinfo/erlang-questions<br class=""></blockquote><br class="">--<span class="Apple-converted-space"> </span><br class=""><br class="">/ Raimo Niskanen, Erlang/OTP, Ericsson AB<br class="">_______________________________________________<br class="">erlang-questions mailing list<br class=""><a href="mailto:erlang-questions@erlang.org" class="">erlang-questions@erlang.org</a><span class="Apple-converted-space"> </span><<a href="mailto:erlang-questions@erlang.org" class="">mailto:erlang-questions@erlang.org</a>><br class=""><a href="http://erlang.org/mailman/listinfo/erlang-questions" class="">http://erlang.org/mailman/listinfo/erlang-questions</a><span class="Apple-converted-space"> </span><<a href="http://erlang.org/mailman/listinfo/erlang-questions" class="">http://erlang.org/mailman/listinfo/erlang-questions</a>><br class=""></blockquote></blockquote><br style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none;" class=""><span style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none; float: none; display: inline !important;" class="">--<span class="Apple-converted-space"> </span></span><br style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none;" class=""><br style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none;" class=""><span style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none; float: none; display: inline !important;" class="">/ Raimo Niskanen, Erlang/OTP, Ericsson AB</span><br style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none;" class=""><span style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none; float: none; display: inline !important;" class="">_______________________________________________</span><br style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none;" class=""><span style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none; float: none; display: inline !important;" class="">erlang-questions mailing list</span><br style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none;" class=""><a href="mailto:erlang-questions@erlang.org" style="font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: auto; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; widows: auto; word-spacing: 0px; -webkit-text-size-adjust: auto; -webkit-text-stroke-width: 0px;" class="">erlang-questions@erlang.org</a><br style="caret-color: rgb(0, 0, 0); font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; word-spacing: 0px; -webkit-text-stroke-width: 0px; text-decoration: none;" class=""><a href="http://erlang.org/mailman/listinfo/erlang-questions" style="font-family: Helvetica; font-size: 12px; font-style: normal; font-variant-caps: normal; font-weight: normal; letter-spacing: normal; orphans: auto; text-align: start; text-indent: 0px; text-transform: none; white-space: normal; widows: auto; word-spacing: 0px; -webkit-text-size-adjust: auto; -webkit-text-stroke-width: 0px;" class="">http://erlang.org/mailman/listinfo/erlang-questions</a></div></blockquote></div><br class=""></div></body></html>