[erlang-bugs] common_test + test_server_io errors

[Peter Andersson]

Hi Tim,

A call to ct:log/2 when Common Test is not running (i.e. before or after
the execution of the ct_run program or the ct:run_test/1 function), is
ignored, both in R15 and R16.

For calls to ct:log/2 when Common Test is running, this is the change
from R15 to R16:

In R15:
If ct:log/2 is called on a test case process, or one that has inherited
the group leader from a test case process (typically one spawned from a
test case), the string is printed to the test case log. This is true if
the test case in question is still running. Otherwise the log file is no
longer open. And if the latter, Common Test will either print the string
to the current test case log instead, if one (and only one!) test case
is executing, otherwise print the string to the CT Framework log. This
means that in R15, printouts by means of ct:log/2 from processes unknown
to Common Test, end up either in a test case log or in the CT Framework
log.

In R16:
If ct:log/2 is called on a test case process, or one that has inherited
the group leader from a test case process, the string is printed to the
test case log (as in R15). If the test case in question is finished and
the log file has been closed, the string is printed to the "unexpected
i/o" log (via the test_server_io process) instead. Printouts by means of
ct:log/2 from processes unknown to Common Test, also always end up in
the unexpected i/o log.

Printouts from CT hook functions are "safe" in the sense that they
execute sequentially pre/post test suite/group/case execution. It's not
possible that a call to ct:log/2 from a hook function "comes in too soon
or late", i.e. gets handled before/after Common Test has
started/finished executing.

In general, if one knows that Common Test is running (which is the time
between the CT hook init and terminate call, or the start_logging and
stop_logging event message), it is safe to call ct:log/2 or ct:pal/2
from anywhere and find the data in either the test case logs or in the
unexpected i/o log (depending on the group leader setting). Printouts
that happen before or after the execution of a test suite, group or
case, end up in the unexpected i/o log.

The reason for the exit you reported initially, is that if a log call
happens during startup or shutdown of Common Test, then, during a short
window, it's possible that Common Test fails to communicate with Test
Server and crashes.

Before I try to answer your question below, I need to understand better
what you want to happen to the log printouts that take place during your
configuration/setup phase (before the test run starts) and/or during the
teardown phase (when Common Test has shut down). If Common Test - in an
offline mode (i.e. not running) - should attempt to write incoming
ct:log/2 strings to a file, the best it can do really, is to
write/append them to say a circular log file in the current working
directory. This is possible, but it will be difficult to know which
printouts belong to which test runs when analyzing the logs, and as far
as I understand, this is the sort of thing you're trying to avoid anyway.

As far as I see, it's quite possible to do something clever with log
printouts that happen *before* Common Test starts. They could be
buffered in a temporary file then read and resent by a CT hook init
function so that this data ends up first in the unexpected i/o log for
the test run. The problem here is what to do with printouts that happen
*after* Common Test has stopped but before your teardown is finished.
Another possibility could maybe be, if possible, to change the order of
the whole session so that Common Test is always started before your
configuration/setup (CT hooks can for example be added dynamically) and
not stopped until teardown is also finished. Perhaps an init and
terminate function in a high prio CT hook module could be used to
synchronize this. Sounds feasible to me.

Let me know if I understand your problem correctly and tell me what
ideas/requests you have and let's move on from there.

Best regards,
Peter

Ericsson AB, Erlang/OTP

Tim Watson wrote:
> So chaps, I've found the commit that altered the IO handling in
> test_server (in fact, the addition of test_server_io). To clarify,
> prior to the addition of test_server_io, calls to ct:log/2 (and
> friends, e.g., ct:pal/2 and so on) would succeed even if no test was
> running and end up being handled as if they resided in before/after
> suite and/or before/after testcase functions. Now it seems that I've
> got to vet all the processes that might end up calling ct:log/2
> (indirectly via my event manager) somehow, but there's no proper API
> to determine whether or not it is safe to do so. Having all my
> debug/info level testing framework logs emitted to the HTML files was
> a big reason for choosing common_test, so I'm loth to redirect them
> elsewhere. My code is basically doing lots of custom (data driven)
> setup/teardown before and after test suites and test cases, and even
> though some of this runs before (or during) the common_test test run
> is started, I *really* don't want to have to create yet another file
> location that needs to be inspected when tests fail. I'm also not keen
> on filling up stdio with lots of logging noise.
>
> Any ideas how I can work around this situation without shooting myself
> in the head/foot? ;)
>
> Cheers,
> Tim
>
> On 12 Jul 2013, at 08:36, Tim Watson wrote:
>
>> Hi Lukas, thanks for letting me know!
>>
>> Cheers,
>> Tim
>>
>> On 12 Jul 2013, at 08:29, Lukas Larsson <lukas@REDACTED
>> <mailto:lukas@REDACTED>> wrote:
>>
>>> Hello Tim,
>>>
>>> Peter is currently away enjoying the sunny summer here in Sweden.
>>> I'm sure he will get back to you when he comes back!
>>>
>>> Lukas
>>> On 12/07/13 02:03, Tim Watson wrote:
>>>> On 1 July 2013 10:25, Tim Watson <watson.timothy@REDACTED
>>>> <mailto:watson.timothy@REDACTED>> wrote:> We should try to rule
>>>> out that there's a bug that causes test_server
>>>>
>>>>     > failure.
>>>>
>>>>     How can I assist in verifying that?
>>>>
>>>>
>>>> Any more news on this? Is there anything more I can do to assist?
>>>>
>>>> Cheers,
>>>> Tim
>>>>
>>>>
>>>> _______________________________________________
>>>> erlang-bugs mailing list
>>>> erlang-bugs@REDACTED
>>>> http://erlang.org/mailman/listinfo/erlang-bugs
>>>>         
>>>
>