Erlang server crashing after timeout from timer module

Question

I have a Table module. When it starts as a gen_server, it creates 2 servers from the Clock module - one for the X player and one for the O player.

After 10 seconds the Clock will time out and this code is called:

updateTick(Delta, {{Time, ticking, _}, Host}) ->
  Now = Time - Delta,
  case Now of
    Now when Now > 0 ->
      {{Now, ticking, intervalRef()}, Host};
    _ ->
      gen_server:call(Host, timeout),
      {{0, out, none}, Host}
  end;

I expect the latter clause to fire.

Here's the crash I get:

Eshell V8.2  (abort with ^G) ([email protected])1> Clock.{{1000,paused,none},<0.532.0>} Clock.{{20.823899999999803,ticking,#Ref<0.0.1.603>},<0.532.0>}

=ERROR REPORT==== 4-Sep-2017::20:10:19 ===
** Generic server <0.536.0> terminating
** Last message in was {tick,25.099}
** When Server state == {{20.823899999999803,ticking,#Ref<0.0.1.603>},
                         <0.532.0>}
** Reason for termination ==
** {{timeout,{gen_server,call,[<0.532.0>,timeout]}},
    [{gen_server,call,2,[{file,"gen_server.erl"},{line,204}]},
     {clock,updateTick,2,[{file,"src/clock.erl"},{line,27}]},
     {clock,handle_call,3,[{file,"src/clock.erl"},{line,35}]},
     {gen_server,try_handle_call,4,[{file,"gen_server.erl"},{line,615}]},
     {gen_server,handle_msg,5,[{file,"gen_server.erl"},{line,647}]},
     {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,247}]}]}

The gen_server being called with timeout is a Table server. The Clocks keep a reference to the Table to send the timeout message to them when a clock times out, so the Table can cancel the others and do other logic.

Here is my full clock.erl:

-module(clock).
-compile(export_all).

-define(STARTING, 1000).
-define(INTERVAL, 250).

init([Host]) -> 
  {ok, defaultState(Host)}.

defaultState(Host) ->
  {{?STARTING, paused, none}, Host}.

tickPid(Pid, Then) ->
  Delta = timer:now_diff(erlang:timestamp(), Then) / 10000,
  s:s(Pid, {tick, Delta}).

intervalRef() ->
 {ok, {_, Tref}} = timer:apply_after(?INTERVAL, ?MODULE, tickPid, [self(), erlang:timestamp()]),
 Tref.

updateTick(Delta, {{Time, ticking, _}, Host}) ->
  Now = Time - Delta,
  case Now of
    Now when Now > 0 ->
      {{Now, ticking, intervalRef()}, Host};
    _ ->
      s:s(Host, timeout),
      {{0, out, none}, Host}
  end;

updateTick(_, State) ->
  State.

handle_call({tick, Delta}, _, State) ->
  State2 = updateTick(Delta, State),
  {reply, State2, State2};
handle_call(info, _, State) ->
  {reply, State, State};
handle_call(pause, _, {{Time, ticking, Tref}, Host}) ->
  timer:cancel(Tref),
  State2 = {{Time, paused, none}, Host},
  {reply, State2, State2};
handle_call(start, _, {{Time, paused, _}, Host}) ->
  {ok, Tref} = timer:apply_after(?INTERVAL, ?MODULE, tickPid, [self(), erlang:timestamp()]),
  State2 = {{Time, ticking, Tref}, Host},
  {reply, State2, State2};
handle_call(stop, _From, State) ->
  {stop, normal, shutdown_ok, State};
handle_call(_, _, State) ->
  {reply, State, State}.

terminate(_, State = {{_,_, none}, _}) ->
    io:format("Clock.~p~n", [State]),
    ok;
terminate(_, State = {{_,_,Tref}, _}) ->
    timer:cancel(Tref),
    io:format("Clock.~p~n", [State]),
    ok.
code_change(_OldVsn, State, _Extra) ->
    {ok, State}. 
handle_cast(_, State) ->
    {noreply, State}.
handle_info(Msg, State) ->
  io:format("Unexpected message: ~p~n",[Msg]),
  {noreply, State }.

go(Host) ->
  gen_server:start_link(?MODULE, [Host], []).

and full table.erl:

-module(table).
-compile(export_all).
-behavior(gen_server).

-define(POSTGAME_TIMEOUT, 6000).

otherPlayer(x) -> o;
otherPlayer(o) -> x.

processRecentTaken(true) -> 1;
processRecentTaken(false) -> 0.

processResult({error, Error, _Board}, State) ->
  {{error, Error}, State};
processResult({playing, NewBoard, Slices, RecentTaken},   {Board, Status, Players}) ->
  % update recent taken
  CurrentPlayer = maps:get(current_player, Status),
  OtherPlayer = otherPlayer(CurrentPlayer),
  {OClock, OActions} = maps:get(OtherPlayer, Players),
  s:s(OActions, {recent_bonus, processRecentTaken(RecentTaken)}),
  % update slice bonus
  {CClock, CActions} = maps:get(CurrentPlayer, Players),
  Made = s:s(CActions, {made, Slices}),
  Status2 = case Made of
    {over, _} ->
      s:s(Board, {cycle, OtherPlayer}),
      s:s(CClock, pause),
      s:s(OClock, start),
      maps:put(current_player, OtherPlayer, Status);
    _ -> Status
  end,
  {{ok, NewBoard}, {Board, Status2, Players}};
processResult({Win, NewBoard, _Slices, _RecentTaken}, State) ->
  {{ok, NewBoard}, winGame(Win, State)}.

markAsFinished(Pid, _Timestamp) ->
  s:s(Pid, finished).

winGame(x, State) ->
  winGame(xWin, State);
winGame(o, State) ->
  winGame(oWin, State);
winGame(Win, {Board, Status, Players}) ->
  CurrentPlayer = maps:get(current_player, Status),
  OtherPlayer = otherPlayer(CurrentPlayer),
  {OClock, _} = maps:get(OtherPlayer, Players),
  CurrentPlayer = maps:get(current_player, Status),
  {CClock, _} = maps:get(CurrentPlayer, Players),
  s:s(OClock, pause),
  s:s(CClock, pause),
  Status2 = maps:put(result, Win, Status),
  {ok, _Tref} = timer:apply_after(?POSTGAME_TIMEOUT, ?MODULE, markAsFinished, [self(), erlang:timestamp()]),
  {Board, Status2, Players}.

handle_call({place, Action, Player, Position}, _, State = {Board, Status, _Players}) ->
% TODO: check for is playing
  CurrentPlayer = maps:get(current_player, Status),
  Result = s:s(Board, {place, CurrentPlayer, {Action, Player, Position}}),
  {Response, State2} = processResult(Result, State),
  {reply, Response, State2};
handle_call(timeout, TimeoutPid, State = {_Board, _Status, Players}) ->
  TimeoutPlayer = getPlayerForClockPid(TimeoutPid, Players),
  WinningPlayer = otherPlayer(TimeoutPlayer),
  {Res, State2} = winGame(WinningPlayer, State),
  {reply, Res, State2};
handle_call(finished, _, {Board, Status, Players}) ->
  Status2 = maps:put(result, finished, Status),
  State2 = {Board, Status2, Players},
  {reply, State2, State2};
handle_call(assign_players, _, {Board, Status}) ->
  Players = createPlayers(self()),
  State2 = {Board, Status, Players},
  {reply, State2, State2};
handle_call(info, _, State = {Board, Status, #{x := X, o := O}}) ->
  BoardInfo = s:s(Board, info),
  RX = playerInfo(X),
  RO = playerInfo(O),
  Res = #{board => BoardInfo,
          status => Status, 
          players => #{x => RX, o => RO}},
  {reply, Res, State};
handle_call(_, _, State) ->
  {reply, State, State}.

playerInfo({Clock, Actions}) ->
  {Next, Current} = s:s(Actions, info),
  {{Time, _ ,_}, _} = s:s(Clock, info),
  #{clock => Time, actions => #{next => Next, current => Current}}.

getPlayerForClockPid(ClockPid, Players) ->
  getPlayerForClockPid(ClockPid, Players, maps:keys(Players)).
getPlayerForClockPid(ClockPid, Players, [H | T]) ->
  case maps:get(H, Players) of
    {ClockPid, _} -> H,
    getPlayerForClockPid(ClockPid, Players, T)
  end.

actionProcess(x) -> actions:go(1);
actionProcess(o) -> actions:go(2).

playerProcesses(Pid, Player) ->
  {ok, Clock} = clock:go(Pid),
  {ok, Actions} = actionProcess(Player),
  {Clock, Actions}.

playerNames() ->
  [x, o].

createPlayers(Self) ->
  createPlayers(Self, playerNames(), #{}).
createPlayers(_Self, [], Players) ->
  Players;
createPlayers(Self, [H | T], Players) ->
  createPlayers(Self, T, maps:put(H, playerProcesses(Self, H), Players)).

defaultStatus() ->
  #{current_player => x,
    result => playing}.

init([]) -> 
  {ok, Board} = board:go(),
  Status = defaultStatus(),
  {ok, {Board, Status}}.

go() ->
  {ok, Pid} = gen_server:start_link(?MODULE, [], []),
  s:s(Pid, assign_players),
  {ok, Pid}.

terminate(_, State = {_Board, Status, Players}) ->
  % gen_server:stop(Board),
  CurrentPlayer = maps:get(current_player, Status),
  OtherPlayer = otherPlayer(CurrentPlayer),
  {OClock, OActions} = maps:get(OtherPlayer, Players),
  CurrentPlayer = maps:get(current_player, Status),
  {CClock, CActions} = maps:get(CurrentPlayer, Players),
  gen_server:stop(OClock),
  gen_server:stop(CClock),
  gen_server:stop(OActions),
  gen_server:stop(CActions),
  io:format("Table Terminating.~p~n", [State]),
  ok.

code_change(_OldVsn, State, _Extra) ->
    {ok, State}. 

handle_cast(_, State) ->
    {noreply, State}.

handle_info(Msg, State) ->
  io:format("Unexpected message: ~p~n",[Msg]),
  {noreply, State}.

What I'm confused about is it seems to be crashing from calling the Table (the Host variable) with timeout but I don't see a stacktrace with anything about the Table code.

s:s(Pid, Msg) is a convenience for gen_server:call(Pid, Msg).

How can I debug what's causing the crash?

EDIT:

Changed the timeout atom to clockdone since timeout has special case in Erlang.

Now getting this crash:

=ERROR REPORT==== 5-Sep-2017::11:37:07 ===
** Generic server <0.570.0> terminating
** Last message in was {tick,25.1116}
** When Server state == {{20.927900000000147,ticking,#Ref<0.0.5.642>},
                         <0.566.0>}
** Reason for termination ==
** {{timeout,{gen_server,call,[<0.566.0>,clockdone]}},
    [{gen_server,call,2,[{file,"gen_server.erl"},{line,204}]},
     {clock,updateTick,2,[{file,"src/clock.erl"},{line,27}]},
     {clock,handle_call,3,[{file,"src/clock.erl"},{line,35}]},
     {gen_server,try_handle_call,4,[{file,"gen_server.erl"},{line,615}]},
     {gen_server,handle_msg,5,[{file,"gen_server.erl"},{line,647}]},
     {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,247}]}]}

which if I understand right, means the server <0.566.0> died.

Answer 1

You should start with 6.1 Simple Debugging from OTP Design Principles User's Guide.

If it doesn't help try use dbg module from Runtime_Tools. Look at gen_server:call/2. It seems that exception is generated at https://github.com/erlang/otp/blob/master/lib/stdlib/src/gen_server.erl#L206 which indicates that catch gen:call(Host, '$gen_call', timeout) returns {'EXIT',{timeout,{gen_server,call,[<0.532.0>,timeout]}}} for some reason. You could go deeper and see why it happen. I vaguely remember there was some trick or catch which could cause gen:call/3 could return {'EXIT',Reason} instead of throwing an exception but I don't recall details and don't know it is the cause of your trouble.

You could also try observer if you do like GUI.

Anyway creating Minimal, Complete, and Verifiable example would help a lot to obtain a better answer to your question.