[erlang-bugs] common_test + test_server_io errors

[Peter Andersson]

Hi Tim,

When a process that hasn't inherited the group leader from a test case
process (i.e typically one that hasn't been spawned directly or
indirectly from a test case) sends a printout to common_test (by means
of e.g ct:log), common_test will print the string to the "Unexpected I/O
log", which you find a link to from the test overview page. This is done
by actually sending the string to a process named test_server_io, which
performs the printing. It is passing the message from the common_test
logger to test_server_io that fails, because test_server_io has terminated.

Now, test_server_io should live for as long as common_test is up and
running (well, almost). You should not get that crash report unless
ct:log is called after the test run is finished or test_server_io has
crashed unexpectedly because of a bug. The latter should not be a silent
event - there should be some indication of such a crash during the test
run. Is it possible it's the former problem you encounter, or are you
sure the tests are still running when the printout happens? This thing
smells timing related error to me. There are only two short "windows"
during a test run when the common_test logger is alive while
test_server_io isn't: During startup and shutdown of the test run. If
the ct:log call happens during either window, you could get this error.

Is it easy for you to reproduce the error or does it only happen
occasionally?

We should try to rule out that there's a bug that causes test_server
failure. Then, the timing problem I described above is quite easily
fixed by making sure common_test prints to stdout if test_server isn't
up and running. I'll implement a fix for this right now, in any event.

Best regards,
Peter

Ericsson AB, Erlang/OTP


Tim Watson wrote:
> I'm seeing some weird errors in my common_test suites since upgrading
> to R16B01 - I'd like to know if this is a bug or if my code is doing
> something wrong...
>
> ct_util_server got EXIT from <0.227.0>: {noproc,
>                                         {gen_server,call,
>                                          [test_server_io,
>                                           {print,xxxFrom,unexpected_io,
>                                            [[[["<div
> class=\"default\"><b>*** User 2013-06-26 16:47:39.122 ***</b>"],
>                                               "\n",
>                                               [91,102,114,97,109,101,119,111,
>                                                114,107,93,32,119,97,116,99,
>                                                104,100,111,103,58,32,110,111,
>                                                32,112,114,111,99,115,32,116,
>                                                111,32,107,105,108,108,"\n"]],
>                                              "\n","</div>"]]},
>                                           infinity]}}
>
> That message originated in these lines of code, running in a process
> started outside of common_test:
>
> log(framework, "watchdog: no procs to kill~n", []);
>
> which calls another module:
>
> log(Scope, Fmt, Args) ->
>    gen_event:sync_notify(systest_event_log, {Scope, Fmt, Args}).
>
> which ends up in the following handler (amongst other places):
>
> write_log(EvId, _Fd, What, Args) ->
>    ct:log("[" ++ as_string(EvId) ++ "] " ++ as_string(What), Args).
>
> So what's up with the "unexpected_io" error here, and *why* has this
> brought the whole common_test run down?
>
> Thanks,
>
> Tim
>
>
>
> ------------------------------------------------------------------------
>
> _______________________________________________
> erlang-bugs mailing list
> erlang-bugs@REDACTED
> http://erlang.org/mailman/listinfo/erlang-bugs
>