[erlang] Почему при краше процесса не видно стектрейс?
От: Васильич  
Дата: 09.09.09 19:30
Оценка:
Здравствуйте.

Вот столкнулся с новой проблемой. Итак, есть несколько процессов, при запуске которых используются функции из модулей proc_lib и sys. Что-то вроде:


start_link(Args) ->
    proc_lib:start_link(?MODULE, init,
                        [self(), Args]).


init(Parent, Args) ->
    % Тут проводим инициализацию процесса
    % ...

    Debug = sys:debug_options([]),
    State = #state{...},

    proc_lib:init_ack(Parent, {ok, self()}),

    loop(State, Parent, Debug).


loop(State, Parent, Debug) ->
    receive
        % Тут обрабатываем свои сообщения
        % ...
        {system, From, Request} ->
            sys:handle_system_msg(
                Request, From, Parent, ?MODULE, Debug, State)
    end.


В общем, все как рекомендуется в доке. Теперь, как только в любом из этих процессов возникает рантаймовая ошибка, например function_clause, то процесс падает с причиной ошибки просто function_clause, без стектрейса:

=INFO REPORT==== 9-Sep-2009::23:20:16 ===
    application: stp
    exited: function_clause
    type: temporary

=ERROR REPORT==== 9-Sep-2009::23:20:16 ===
** Generic server <0.53.0> terminating 
** Last message in was {'DOWN',#Ref<0.0.0.58>,process,<0.48.0>,
                               function_clause}
** When Server state == {state,#Port<0.738>,undefined,<0.48.0>,undefined,on,
                               false,false,on,connected,undefined,0,
                               [#Port<0.736>,#Port<0.737>],
                               #Port<0.739>,#Port<0.740>}
** Reason for termination == 
** {stopped,{'EXIT',<0.48.0>,function_clause}}


При этом, процессы из этого же приложения, которые запускались через обычный spawn_link() или которые реализованы через стандартные бехавиоры — падают нормально, со стектрейсом:

** Generic server <0.53.0> terminating 
** Last message in was {'DOWN',#Ref<0.0.0.58>,process,<0.48.0>,
                           {function_clause,
                               [{consumer,crash,[do_it]},
                                {consumer,handle_info,2},
                                {gen_server,handle_msg,5},
                                {proc_lib,init_p_do_apply,3}]}}
** When Server state == {state,#Port<0.738>,undefined,<0.48.0>,undefined,on,
                               false,false,on,connected,undefined,0,
                               [#Port<0.736>,#Port<0.737>],
                               #Port<0.739>,#Port<0.740>}
** Reason for termination == 
** {stopped,{'EXIT',<0.48.0>,
                    {function_clause,[{consumer,crash,[do_it]},
                                      {consumer,handle_info,2},
                                      {gen_server,handle_msg,5},
                                      {proc_lib,init_p_do_apply,3}]}}}


Почему так, куда пропадает стек в первом случае? Я уже и гуглил, и изучал исходники proc_lib, gen_*, sys — ну нет там чего-то такого, что могло бы приводить к такому результату. А без стектрейсов отлаживать просто нереально. Сейчас приходится отказываться от proc_lib и даваемых ей преимуществ, запускать через spawn().
Re: [erlang] Почему при краше процесса не видно стектрейс?
От: DmitryMe  
Дата: 10.09.09 05:00
Оценка:
Здравствуйте, Васильич, Вы писали:

Наверно потому что

The module sys contains some functions for simple debugging of processes implemented using behaviours


Процесс должен реализовывать один из gen_* шаблонов.
Re[2]: [erlang] Почему при краше процесса не видно стектрейс
От: Васильич  
Дата: 10.09.09 06:40
Оценка:
Здравствуйте, DmitryMe, Вы писали:

DM>Наверно потому что


DM>

DM>The module sys contains some functions for simple debugging of processes implemented using behaviours


DM>Процесс должен реализовывать один из gen_* шаблонов.


Я тоже так сначала думал. Но ведь исходники gen_* шаблонов доступны, они сами построены на proc_lib и sys. И они не делают чего-то этакого, все стандартно, что сделано и у меня. Более того, вчера я наткнулся на еще кое-что.

Допустим есть процесс, который использует для запуска proc_lib (первый процесс из моего первого поста). Когда возникает рантайм-еррор — он падает без стектрейса. Но! Если поймать этот эксепшен вручную и потом сразу его бросить с помощью exit() — то все работает нормально! Я даже сделал специальную функцию:

runtime_error_workaround(R) ->
    case R of
        {'EXIT', Reason} -> exit(Reason);
        _ -> R
    end.


и использую ее вот так:

message_loop(Parent, Debug, State) ->
    receive
        {announce, Announce} ->
            NewState = runtime_error_workaround(catch handle_announce(State, Announce)),
            message_loop(Parent, Debug, NewState);
        {system, From, Request} ->
            sys:handle_system_msg(Request, From, Parent, ?MODULE, Debug, State);
        stop ->
            terminate(normal, State)
    end.


То есть, в изначальном эксепшене, который генерируется интерпретатором, присутствует вся необходимая инфа, в том числе и стектрейс (это я проверил). Если повторно бросить этот эксепшен через exit() — то вся информация из него показывается в error-репорте. Если же этот эксепшен перехватывается самой proc_lib — то стектрейс отсутствует. Такое ощущение, что она его обрезает, хотя судя по ее исходникам такого происходить не должно. Мистика? Или я что-то упускаю?

И у меня еще один вопрос в связи с этим: как можно в отладчике отлаживать системные библиотеки (ту же proc_lib)? Я запускаю отладчик через im(), он позволяет проинтерпретировать мои собственные модули, но не системные. Я хочу установить точку останова на момент, когда proc_lib перехватывает возникающие в процессе исключения, и посмотреть что с ними происходит.
Re[2]: [erlang] Почему при краше процесса не видно стектрейс
От: netch80 Украина http://netch80.dreamwidth.org/
Дата: 10.09.09 06:42
Оценка:
Здравствуйте, DmitryMe, Вы писали:

DM>Здравствуйте, Васильич, Вы писали:


DM>Наверно потому что


DM>

DM>The module sys contains some functions for simple debugging of processes implemented using behaviours


DM>Процесс должен реализовывать один из gen_* шаблонов.


Это как раз необязательно. Мы делали полноценные процессы без собственно gen_xxx(), это гиморно, но делается. Тут проблема в чём-то другом.
The God is real, unless declared integer.
Re: [erlang] Почему при краше процесса не видно стектрейс?
От: netch80 Украина http://netch80.dreamwidth.org/
Дата: 10.09.09 06:52
Оценка:
Здравствуйте, Васильич, Вы писали:

В>В общем, все как рекомендуется в доке. Теперь, как только в любом из этих процессов возникает рантаймовая ошибка, например function_clause, то процесс падает с причиной ошибки просто function_clause, без стектрейса:


В>=INFO REPORT==== 9-Sep-2009::23:20:16 ===

В> application: stp
В> exited: function_clause
В> type: temporary

В>=ERROR REPORT==== 9-Sep-2009::23:20:16 ===

В>** Generic server <0.53.0> terminating
В>** Last message in was {'DOWN',#Ref<0.0.0.58>,process,<0.48.0>,
В> function_clause}
В>** When Server state == {state,#Port<0.738>,undefined,<0.48.0>,undefined,on,
В> false,false,on,connected,undefined,0,
В> Port<0.736>,#Port<0.737>,
В> #Port<0.739>,#Port<0.740>}
В>** Reason for termination ==
В>** {stopped,{'EXIT',<0.48.0>,function_clause}}

Что-то я тут не понимаю, "кто на ком стоял". Сообщение приходит из 0.53.0. Причём причина его завершения напоминает то, что он слинкован с 0.48.0, получил exit для него и тут же завершился. В этом случае вообще-то трейс не имеет смысла: если Вы trap_exit'ом это не перехватываете, 'EXIT' убьёт линкованный процесс в любом состоянии. Кто именно был порождён через proc_lib? 0.48.0? Но у него же номер меньше, значит, наверняка был порождён раньше. Так кто у вас по-разному рождается в данных примерах — 0.48.0 или 0.53.0?

Кстати, рекомендую дать каждому процессу имя через register(), для отладки это полезнее.
Далее, SASL у Вас при этом запущен или нет? Если нет — рекомендую таки запустить, с ним возникают более подробные и осмысленные сообщения о происходящем.

В>Почему так, куда пропадает стек в первом случае? Я уже и гуглил, и изучал исходники proc_lib, gen_*, sys — ну нет там чего-то такого, что могло бы приводить к такому результату. А без стектрейсов отлаживать просто нереально. Сейчас приходится отказываться от proc_lib и даваемых ей преимуществ, запускать через spawn().


Ну вообще-то ничего не мешает сделать адекватный этому костыль в собственной функции верхнего уровня в процессе, по типу

  try
    real_work()
  catch C:E ->
    io:format("failed: ~p:~p~n", [C, E]),
    throw({rethrown_from_debug,C,E})
  end


только IMHO вначале надо сделать то, что я выше писал.
The God is real, unless declared integer.
Re[2]: [erlang] Почему при краше процесса не видно стектрейс
От: Васильич  
Дата: 10.09.09 07:36
Оценка:
Здравствуйте, netch80, Вы писали:

В>>=INFO REPORT==== 9-Sep-2009::23:20:16 ===

В>> application: stp
В>> exited: function_clause
В>> type: temporary

В>>=ERROR REPORT==== 9-Sep-2009::23:20:16 ===

В>>** Generic server <0.53.0> terminating
В>>** Last message in was {'DOWN',#Ref<0.0.0.58>,process,<0.48.0>,
В>> function_clause}
В>>** When Server state == {state,#Port<0.738>,undefined,<0.48.0>,undefined,on,
В>> false,false,on,connected,undefined,0,
В>> Port<0.736>,#Port<0.737>,
В>> #Port<0.739>,#Port<0.740>}
В>>** Reason for termination ==
В>>** {stopped,{'EXIT',<0.48.0>,function_clause}}

N>Что-то я тут не понимаю, "кто на ком стоял". Сообщение приходит из 0.53.0. Причём причина его завершения напоминает то, что он слинкован с 0.48.0, получил exit для него и тут же завершился. В этом случае вообще-то трейс не имеет смысла: если Вы trap_exit'ом это не перехватываете, 'EXIT' убьёт линкованный процесс в любом состоянии. Кто именно был порождён через proc_lib? 0.48.0? Но у него же номер меньше, значит, наверняка был порождён раньше. Так кто у вас по-разному рождается в данных примерах — 0.48.0 или 0.53.0?


0.48.0 — процесс, который крашится. 0.53.0 — этот процесс крутит odbc:init (ODBC используется этим самым моим процессом).

N>Кстати, рекомендую дать каждому процессу имя через register(), для отладки это полезнее.


Дал.

N>Далее, SASL у Вас при этом запущен или нет? Если нет — рекомендую таки запустить, с ним возникают более подробные и осмысленные сообщения о происходящем.


SASL не был запущен. Запустил. В целом, информации стало намного больше и я даже выцепил вот такие строки:

  crasher:
    initial call: odbc_import:init/4
    pid: <0.57.0>
    registered_name: odbc_import
    exception error: no function clause matching 
                     odbc_import:check_integer(atom)


Исходный function_clause по-прежнему без стектрейса. Однако в exception error наконец стало видно, кто сгенерировал эксепшен (odbc_import:check_integer(atom)). Такое ощущение, что proc_lib каким-то образом модифицирует эксепшен, убирая оттуда стектрейс. Хотя по исходникам этого не видно.

N>Ну вообще-то ничего не мешает сделать адекватный этому костыль в собственной функции верхнего уровня в процессе, по типу


N>
N>  try
N>    real_work()
N>  catch C:E ->
N>    io:format("failed: ~p:~p~n", [C, E]),
N>    throw({rethrown_from_debug,C,E})
N>  end
N>


Я уже сделал как писал тут
Автор: Васильич
Дата: 10.09.09
. Но это как бы именно костыль, а хочется сделать правильно. Да и просто понять, почему такое происходит.
Re: [erlang] Почему при краше процесса не видно стектрейс?
От: Mikl Kurkov Россия  
Дата: 10.09.09 10:30
Оценка: 3 (1)
Здравствуйте, Васильич, Вы писали:

В>Почему так, куда пропадает стек в первом случае? Я уже и гуглил, и изучал исходники proc_lib, gen_*, sys — ну нет там чего-то такого, что могло бы приводить к такому результату. А без стектрейсов отлаживать просто нереально. Сейчас приходится отказываться от proc_lib и даваемых ей преимуществ, запускать через spawn().


По-моему есть путаница в вопросах исключений и трейса. Попробую разъяснить.

В Erlang три вида исключений


При возникновении исключения никакого трейса в нем нет, только тип и причина. Трейс добавляет оператор catch и только для исключений рантайма.
Можно сравнить вывод catch для разных видов исключений.

  {catch erlang:error(err), catch exit(ext), catch throw(thr)}.

{{'EXIT',{err,[{erl_eval,do_apply,5},
               {erl_eval,expr,5},
               {erl_eval,expr_list,6},
               {erl_eval,expr,5},
               {shell,exprs,6},
               {shell,eval_exprs,6},
               {shell,eval_loop,3}]}},
 {'EXIT',ext},
 thr}


Здесь видно что catch не позволяет однозначно опрделить тип исключения и было ли оно вообще.
Это мешало полноценно их использовать, и поэтому появилась конструкция try...catch...end .

При обработке исключения в try..catch..end трейса нет:

  try erlang:error(err) catch C:E -> {C,E} end.
{error,err}


Но вместе c try..catch..end была добавлена функция erlang:get_stacktrace(),которая позволяет добавить трейс при необходимости.

 try erlang:error(err) catch C:E -> {C,E,erlang:get_stacktrace()} end.
{error,err,
       [{erl_eval,do_apply,5},
        {erl_eval,try_clauses,8},
        {shell,exprs,6},
        {shell,eval_exprs,6},
        {shell,eval_loop,3}]}


Что касается изначальной проблемы, то похоже что proc_lib в случае ошибок генерит специальный отчет crash_report,
который обычным логгером игнорируется, для вывода crash_report нужно запустить sasl или свой обработчик.

Для отладки кстати удобно включить трассировку вызовов функций.
У Joel Reymont есть удобная обертка для включения выключения трассировки всех функций конкретного модуля — здесь.

Подробности про исключения в Erlang — Erlang's Exception Handling Revisited

--
Mikl
Re[2]: [erlang] Почему при краше процесса не видно стектрейс
От: Васильич  
Дата: 10.09.09 12:40
Оценка:
Здравствуйте, Mikl Kurkov, Вы писали:

MK>По-моему есть путаница в вопросах исключений и трейса. Попробую разъяснить.


Огромное спасибо за разьяснение! В голове все постепенно встает на свои места
 
Подождите ...
Wait...
Пока на собственное сообщение не было ответов, его можно удалить.