error_logger events sent by emulator

classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

error_logger events sent by emulator

Loïc Hoguin-2
Hello,

I am playing with error_logger handlers at the moment. I notice that I
receive events like this one:

{error, <0.68.0>, {emulator,"~s~n",
                          ["Error in process <0.649.0> on node
'ct' with exit value:
{[{reason,function_clause},{mfa,{rest_resource_etags,generate_etag,2}},{stacktrace,[{cowboy_http,quoted_string,[<<17
bytes>>,#Fun<cowboy_http.19.115752622>],[{file,\"src/cowboy_http.erl\"},{line,653}]},{cowboy_http,nonempty_list,2,[{file,\"src/cowboy_http.erl\"},{...
\n"]}}

I remember reading about these from a previous discussion but I can't
find it right now. If I recall they are messages sent directly from the
C code, and again if I recall there was suggestions about removing this
type of error entirely and/or replacing with Erlang code instead of
making the C code aware of the error_logger.

Is there any plans to change this in the future? If not, can you provide
details on what exactly triggers these sort of events? It's hard to
decide what events to ignore without knowing that.

Thanks!

--
Lo?c Hoguin
http://ninenines.eu

Reply | Threaded
Open this post in threaded view
|

error_logger events sent by emulator

Loïc Hoguin-2
Me again.

Putting aside how it's sent by the C code, and seeing as I need to
handle the messages coming from the emulator for my purposes, I hit an
issue.

The emulator's error events are sent as a *string*. Not only a string,
but a string which, to my knowledge, can't be parsed with anything that
comes with OTP. In particular I need to figure out the number of
arguments of the last call in the stacktrace, and when it comes as a
list of arguments I get things like this:

     "[<<17 bytes>>,#Fun<cowboy_http.19.115752622>]"

If you have tips on how to get 2 from that format, please enlighten me.
Note that it should work not only in this case but also any other cases
including if it had arguments as lists or tuples.

Not only is it hard to programmatically figure out what's going on, but
it's also inconsistent with all the other error reports that
error_logger handlers receive.

Can anything be done about this, and how can I help? I'm willing to send
a patch to get proper Erlang terms instead of a string, but this is
happening in the C code so I'll need some directions.

Thanks.

On 04/20/2014 11:51 PM, Lo?c Hoguin wrote:

> Hello,
>
> I am playing with error_logger handlers at the moment. I notice that I
> receive events like this one:
>
> {error, <0.68.0>, {emulator,"~s~n",
>                           ["Error in process <0.649.0> on node
> 'ct' with exit value:
> {[{reason,function_clause},{mfa,{rest_resource_etags,generate_etag,2}},{stacktrace,[{cowboy_http,quoted_string,[<<17
> bytes>>,#Fun<cowboy_http.19.115752622>],[{file,\"src/cowboy_http.erl\"},{line,653}]},{cowboy_http,nonempty_list,2,[{file,\"src/cowboy_http.erl\"},{...
> \n"]}}
>
> I remember reading about these from a previous discussion but I can't
> find it right now. If I recall they are messages sent directly from the
> C code, and again if I recall there was suggestions about removing this
> type of error entirely and/or replacing with Erlang code instead of
> making the C code aware of the error_logger.
>
> Is there any plans to change this in the future? If not, can you provide
> details on what exactly triggers these sort of events? It's hard to
> decide what events to ignore without knowing that.
>
> Thanks!
>

--
Lo?c Hoguin
http://ninenines.eu

Reply | Threaded
Open this post in threaded view
|

error_logger events sent by emulator

Matthias Lang-2
Hi,

Lo?c wrote:
>I am playing with error_logger handlers at the moment. I notice that I
>receive events like this one:

>{error, <0.68.0>, {emulator,"~s~n",
>                          ["Error in process <0.649.0> on node
>'ct' with exit value:

>I remember reading about these from a previous discussion but I can't
>find it right now. If I recall they are messages sent directly from the
>C code, and again if I recall there was suggestions about removing this
>type of error entirely and/or replacing with Erlang code instead of
>making the C code aware of the error_logger.

I think the earlier discussion you remember starts here (my mail):

  http://erlang.org/pipermail/erlang-questions/2013-October/075867.html

My biased summary of the thread:

  - Everyone agreed the behaviour was unfortunate/nobody was a fan of it.

  - I thought it was so pointless that it might be possible to ditch
    the emulator code entirely, i.e. just don't report those errors.
    Others thought that might be a bad idea, though nobody gave a
    concrete example which showed why.

  - Anthony Ramine suggested a way to improve the current situation
    without tossing the code. It didn't feel satisfying, but it might
    be the least worst approach.

I ended up dealing with the problem by avoiding it---I wrapped spawn()
so that the errors I was seeing never made it to that emulator code.
proc_lib:spawn() does the same thing. But it looks like your problem
is more general than mine was.

Matt




Reply | Threaded
Open this post in threaded view
|

error_logger events sent by emulator

Loïc Hoguin-2
Hey, thanks for the pointers.

On 04/28/2014 12:03 AM, Matthias Lang wrote:

> I think the earlier discussion you remember starts here (my mail):
>
>    http://erlang.org/pipermail/erlang-questions/2013-October/075867.html
>
> My biased summary of the thread:
>
>    - Everyone agreed the behaviour was unfortunate/nobody was a fan of it.
>
>    - I thought it was so pointless that it might be possible to ditch
>      the emulator code entirely, i.e. just don't report those errors.
>      Others thought that might be a bad idea, though nobody gave a
>      concrete example which showed why.

After a little thinking I got to this point:

I'm OK with the C code sending these errors. There are a lot of other
errors sent by the emulator, and it doesn't seem like all of them could
be moved to the Erlang side anyway. So the VM has to know where to send
errors. It's very useful for newcomers too, start the shell, spawn a
process, it crashes, you get an error printed. Under no circumstances
should this feedback ever be removed (at least not by default).

I'm not OK with how this particular error is sent. What the code
basically does is:

  *  Detect process crash
  *  Extract stacktrace etc. as Erlang terms
  *  Format Erlang terms as short string
  *  Send string to error_logger

Note that the stacktrace may contain arguments depending on how the
process crashed. Also note that if the error isn't catched there is two
string formattings going on as the error received is {emulator, "~s~n",
Msg} and this results in another formatting call when printing it.

What I would like to happen:

  *  Detect process crash
  *  Extract stacktrace etc. as Erlang terms
  *  Make sure the stacktrace contains no arguments, only arity
  *  Make sure the stacktrace is below a certain size (for example last
5 calls by default, perhaps configurable through process flags)
  *  Send error as Erlang term to error_logger

The error received would be similar to {emulator, "Error in process ~p
on node ~p with exit value: ~p~n", [Pid, Node, Stacktrace]} which makes
it easy to extract information or format as desired. Basically the same
as what we get now, except pre-formatting.

Not sending arguments and limiting the stacktrace also ensures that we
don't flood the VM needlessly. In fact it's potentially better than what
we have today because we might not need to create an Erlang term for the
whole stacktrace and then print a short portion of it when formatting,
we can just take the last N calls. If the stacktrace is huge, we
potentially save a lot of resources.

I don't see it being backward incompatible as I'm probably the only
crazy person who went ahead and parsed that awful string to extract
information.

> I ended up dealing with the problem by avoiding it---I wrapped spawn()
> so that the errors I was seeing never made it to that emulator code.
> proc_lib:spawn() does the same thing. But it looks like your problem
> is more general than mine was.

Well I could solve it exactly the way you did to be perfectly honest. I
didn't think of that, so I ended up parsing the string for the info I
needed (and so far it works OK). But I feel it'd be better with a proper
OTP patch. I'm willing to write said patch if that seems interesting to
others.

So yeah, if any of what I just wrote makes sense to you, please tell me
and I'll do a first try at a patch.

--
Lo?c Hoguin
http://ninenines.eu

Reply | Threaded
Open this post in threaded view
|

error_logger events sent by emulator

Matthias Lang-2

Your suggested patch would remove the ugliest part of the current
behaviour, so if you have the time and energy, why not.

On Monday, April 28, Lo?c Hoguin wrote:

>  *  Detect process crash
>  *  Extract stacktrace etc. as Erlang terms
>  *  Make sure the stacktrace contains no arguments, only arity
>  *  Make sure the stacktrace is below a certain size (for example last 5
> calls by default, perhaps configurable through process flags)
>  *  Send error as Erlang term to error_logger

[...]

> Well I could solve it exactly the way you did to be perfectly honest. I
> didn't think of that, so I ended up parsing the string for the info I needed
> (and so far it works OK). But I feel it'd be better with a proper OTP patch.

That illustrates another problem: the presence of the "VM hack" makes
it harder to discover the straightforward way.

(Aside: the defaults are wrong on spawn(), it should really
link/monitor by default. If it did that, it would be perfectly obvious
why the shell prints error messages. But it's probably a few decades
too late to change that.)

Matthias