ERL-602: seq_trace token unexpectedly cleared by file:read_file

[OTP-Maintainer]

Original reporter: vincefoley Affected version: Not Specified Fixed in version: OTP-21.1 Component: erts Migrated from: https://bugs.erlang.org/browse/ERL-602

---

I'm experimenting with seq_trace which seems to be super powerful. However I've run into a case where the token gets unexpectedly cleared out...

I ran into it using Elixir, when calling a module that isn't yet loaded in a test. I tracked it down further and was able to reproduce it when simply calling `file:read_file`. Same thing happens if the file exists or not.

Example:

{code}
-module(seq_fail).
-include_lib("eunit/include/eunit.hrl").

seq_fail_test() ->
  seq_trace:set_token(label, 123),
  ?assertMatch({_, 123, _, _, _}, seq_trace:get_token()),

  {error, enoent} = file:read_file('not_there'),
  ?assertMatch({_, 123, _, _, _}, seq_trace:get_token()).
{code}

Running the test fails the second match:

{code}
  1) seq_fail:seq_fail_test/0: module 'seq_fail'
     Failure/Error: ?assertMatch({ _ , 123 , _ , _ , _ }, seq_trace : get_token ( ))
       expected: = { _ , 123 , _ , _ , _ }
            got: []
     %% .../_build/test/lib/seq_fail/src/seq_fail.erl:9:in `seq_fail:-seq_fail_test/0-fun-1-/0
{code}

I dug into the code for `file:read_file` and came across some interesting things (like erlang:dt_spread_tag) but couldn't track it any further...

[OTP-Maintainer]

vincefoley said:

I was able to track it further down to opening a port.. this also fails the second match:

{code}
port_test() ->
  seq_trace:set_token(label, 123),
  ?assertMatch({_, 123, _, _, _}, seq_trace:get_token()),

  _Port = open_port({spawn, "echo hello"}, [stream]),
  ?assertMatch({_, 123, _, _, _}, seq_trace:get_token()).
{code}

[OTP-Maintainer]

lukas said:

seq_trace tokens are not carried across ports, so this is behavior is intended.

http://erlang.org/doc/man/seq_trace.html#id149437

It would be nice to be able to do what you are describing, but it has not been implemented yet.

We are gradually moving more and more of the port functionality into NIFs which do not have this problem, so it may solve itself in the future.

[OTP-Maintainer]

vincefoley said:

I saw that bit of the documentation, but my understanding was that the token doesn't work "across" ports, as in the token isn't sent to the port. It wasn't clear that the token will actually be lost when the port call returns.

The behavior renders seq_trace pretty un-predictable, because common operations like opening a file, etc cause the token to be dropped. 

Do you think it would be a reasonable feature request to fix this? Perhaps the token could simply be saved before a port operation, and re-set after it?

[OTP-Maintainer]

lukas said:

If you think about ports as processes, then what happens is that the message being sent to the port (using port_command for instance) has the seq_trace token, but the reply from the port does not, which means that the token is set cleared. So there should be someway for the port to attach the seq_trace token to the messages that it sets.

I've attempted to implement this and similar features in the past and they seem trivial at first but quickly become quite complicated.

I think that we would be open to patches that solve this issue, but as we are in general moving away from ports and into nifs, I don't believe that we will prioritize implementing this. 

[OTP-Maintainer]

vincefoley said:

OK, thanks for the feedback! I'll be looking forward to the nif based future!

[OTP-Maintainer]

vincefoley said:

Hello there!

I was reading some erlang source, as one does, and came across this...

https://github.com/erlang/otp/blame/master/lib/kernel/test/seq_trace_SUITE.erl#L491

"OTP-4218 Messages from ports should not affect seq trace token"

Would this indicate that it's trying to ensure that the token isn't reset by the port message?

[OTP-Maintainer]

lukas said:

hmm, yes you are correct. The problem isn't messages sent by ports as I originally though, but messages that erts generates in order to make asynchronous requests synchronous.

I'll have to think a bit about what the best approach to solve this is.

Thanks for sticking with this! Turns out that it was a larger problem than I tough as this does not only effect ports, but many other scenarios as well.

[OTP-Maintainer]

lukas said:

A PR fixing this is now available: https://github.com/erlang/otp/pull/1846

[OTP-Maintainer]

vincefoley said:

Awesome, thanks!