Force failing CHECK/DCHECKs to end the process on Windows....

Force failing CHECK/DCHECKs to end the process on Windows.

The current implementation of Windows-only hook simply calls FAIL.
According to http://code.google.com/p/googletest/issues/list?cursor=234
it is a misuse of FAIL macros (it may not shut down the process).

As a result, it was impossible to write death tests on windows.

BUG=24885
Committed: http://src.chromium.org/viewvc/chrome?view=rev&revision=34273

[Timur Iskhodzhanov, 2009-12-09 22:51:50]

Hi,

I've seen your names among the recent commiters to base/test/test_suite.h

On Windows, the handling of CHECK/DCHECK failure is slightly different from
Mac/Linux.
We use FAIL macro from gtest and seems like we do it incorrectly.
Please see
http://code.google.com/p/chromium/issues/detail?id=24885
http://code.google.com/p/googletest/issues/detail?id=234
for the details.

I'm trying to fix this difference (it results in impossibility of writing death
tests on Windows).
Please take a look at my proposed patch.

Thank you,
Timur Iskhodzhanov

[Paweł Hajdan Jr., 2009-12-10 07:22:09]

This seems a little hacky, so I'd really want to try other possibilities first.

So, my understanding is that we use a custom assert handler to suppress dialog
messages on Windows. It seems that we only need that on Windows (could you check
that?).

So how about only calling SetLogAssertHandler on Windows (so that other systems
just abort on DCHECK), and changing the handler for Windows so that it
explicitly terminates the process in a way that is known to be recognized
properly as a crashed process?

[Timur Iskhodzhanov, 2009-12-10 07:50:26]

On 2009/12/10 07:22:09, Paweł Hajdan Jr. wrote:
> So, my understanding is that we use a custom assert handler to suppress dialog
> messages on Windows. It seems that we only need that on Windows (could you
check
> that?).
Yes
 
> So how about only calling SetLogAssertHandler on Windows (so that other
systems
> just abort on DCHECK), and changing the handler for Windows so that it
> explicitly terminates the process in a way that is known to be recognized
> properly as a crashed process?
logging::SetLogAssertHandler(UnitTestAssertHandler);
is already inside "#if defined(OS_WIN)" section
(see http://codereview.chromium.org/482001/diff/2003/2004 lines 187-203)

I think we can write something like "exit(1)" as the AssertHandler, but then
we'd need to print out the error message manually.
FAIL() with throw_on_failure==false actually does the same trick.

> This seems a little hacky, so I'd really want to try other possibilities
first.
I'd like that too. I feel like doing a hack to an existing dirty hack...
Suggestions are welcome!

[Paweł Hajdan Jr., 2009-12-10 08:43:55]

Thanks for explaining things. I don't understand yet, why if we're going to
throw on FAIL(), can't we just fail on the DCHECK? Isn't that the same "kind of
failure" anyway?

Some comments below if the above is not possible.

http://codereview.chromium.org/482001/diff/2003/2004
File base/test/test_suite.h (right):

http://codereview.chromium.org/482001/diff/2003/2004#newcode151
base/test/test_suite.h:151: // Force FAIL to end the process.
Please expand this comment to briefly say why we want to end the process, etc.

http://codereview.chromium.org/482001/diff/2003/2004#newcode156
base/test/test_suite.h:156: #if defined(OS_WIN)
Could you move this #ifdef up to include UnitTestAssertHandler to better
indicate that it's only for Windows?

http://codereview.chromium.org/482001/diff/2003/2004#newcode168
base/test/test_suite.h:168: #endif
nit: // defined(OS_WIN)

[Paweł Hajdan Jr., 2009-12-10 08:44:47]

On 2009/12/10 08:43:55, Paweł Hajdan Jr. wrote:
> Thanks for explaining things. I don't understand yet, why if we're going to
> throw on FAIL(), can't we just fail on the DCHECK? Isn't that the same "kind
of
> failure" anyway?

Just to clarify, I meant "why do we need UnitTestAssertHandler, if it's going to
terminate the process anyway".

[Timur Iskhodzhanov, 2009-12-10 15:34:53]

Actually, I'm not very much familiar with the code, I had these questions
recently as well :-)

On 2009/12/10 08:44:47, Paweł Hajdan Jr. wrote:
> On 2009/12/10 08:43:55, Paweł Hajdan Jr. wrote:
> > Thanks for explaining things. I don't understand yet, why if we're going to
> > throw on FAIL(), can't we just fail on the DCHECK? Isn't that the same "kind
> of
> > failure" anyway?
The assert handler hook is called from base::Logging::~Logging() if severity ==
FATAL, which is called from CHECK/DCHECK.
If you call CHECK/DCHECK from the hook, you'll get an infinite recursion.

> Just to clarify, I meant "why do we need UnitTestAssertHandler, if it's going
to
> terminate the process anyway".
The default action of ~Logging() is to break to the debugger (int 3)
According to the comment on line 156, it looks like "int 3" gives us weird
message boxes on Windows, they are not friendly to our bots etc.
To avoid calling "int 3", we add a hook to ~Logging on Windows

--
I'll do the changes you've asked - soon.

[Paweł Hajdan Jr., 2009-12-10 17:19:49]

On 2009/12/10 15:34:53, Timur Iskhodzhanov wrote:
> The default action of ~Logging() is to break to the debugger (int 3)
> According to the comment on line 156, it looks like "int 3" gives us weird
> message boxes on Windows, they are not friendly to our bots etc.
> To avoid calling "int 3", we add a hook to ~Logging on Windows

So the plan I'd like to see would be like this:

- let's do the fixes to this patch and land it (to not delay things too much)
- get a patch into googletest so that we don't get problems with the message
boxes and clean up test_suite.h

This way we end up with a clean flow of control in case of a DCHECK failure in
tests.

[Timur Iskhodzhanov, 2009-12-10 17:31:29]

On 2009/12/10 17:19:49, Paweł Hajdan Jr. wrote:
> On 2009/12/10 15:34:53, Timur Iskhodzhanov wrote:
> > The default action of ~Logging() is to break to the debugger (int 3)
> > According to the comment on line 156, it looks like "int 3" gives us weird
> > message boxes on Windows, they are not friendly to our bots etc.
> > To avoid calling "int 3", we add a hook to ~Logging on Windows
> 
> So the plan I'd like to see would be like this:
> 
> - let's do the fixes to this patch and land it (to not delay things too much)
Will do in a couple of minutes
> - get a patch into googletest so that we don't get problems with the message
> boxes and clean up test_suite.h
I think this is not a googletest issue.
CHECK/DCHECK are chromium-specific and it's base::Logging that shows up the
dialogs. The hook we're talking about is the very method we were suppressing the
dialogs so far.

> This way we end up with a clean flow of control in case of a DCHECK failure in
> tests.

[Paweł Hajdan Jr., 2009-12-10 17:41:00]

> > - let's do the fixes to this patch and land it (to not delay things too
much)
> Will do in a couple of minutes

Great!

> > - get a patch into googletest so that we don't get problems with the message
> > boxes and clean up test_suite.h
> I think this is not a googletest issue.
> CHECK/DCHECK are chromium-specific and it's base::Logging that shows up the
> dialogs. The hook we're talking about is the very method we were suppressing
the
> dialogs so far.

Ah, indeed, a base/logging issue. I'll think more about that. It must be fixable
in a more elegant way.

[Timur Iskhodzhanov, 2009-12-10 17:56:39]

Please take another look

http://codereview.chromium.org/482001/diff/2003/2004
File base/test/test_suite.h (right):

http://codereview.chromium.org/482001/diff/2003/2004#newcode151
base/test/test_suite.h:151: // Force FAIL to end the process.
On 2009/12/10 08:43:55, Paweł Hajdan Jr. wrote:
> Please expand this comment to briefly say why we want to end the process, etc.

Done.

http://codereview.chromium.org/482001/diff/2003/2004#newcode156
base/test/test_suite.h:156: #if defined(OS_WIN)
I did a slightly different thing with #ifdefs, please take a look
On 2009/12/10 08:43:55, Paweł Hajdan Jr. wrote:
> Could you move this #ifdef up to include UnitTestAssertHandler to better
> indicate that it's only for Windows?

http://codereview.chromium.org/482001/diff/2003/2004#newcode168
base/test/test_suite.h:168: #endif
On 2009/12/10 08:43:55, Paweł Hajdan Jr. wrote:
> nit: // defined(OS_WIN)

Done.

[Paweł Hajdan Jr., 2009-12-10 18:15:25]

I've just filed http://crbug.com/29997 to track that. Please put the link
somewhere in the comment. After that, LGTM.

[Timur Iskhodzhanov, 2009-12-10 18:29:24]

Done. Is it fine now?
On 2009/12/10 18:15:25, Paweł Hajdan Jr. wrote:
> I've just filed http://crbug.com/29997 to track that. Please put the link
> somewhere in the comment. After that, LGTM.

[Paweł Hajdan Jr., 2009-12-10 18:31:18]

Sure. LGTM.

[Timur Iskhodzhanov, 2009-12-10 18:32:27]

Aw, crap, that's not fine.
If one test fails, it breaks the execution of the consequent tests, arrrr
On 2009/12/10 18:29:24, Timur Iskhodzhanov wrote:
> Done. Is it fine now?
> On 2009/12/10 18:15:25, Paweł Hajdan Jr. wrote:
> > I've just filed http://crbug.com/29997 to track that. Please put the link
> > somewhere in the comment. After that, LGTM.

[Timur Iskhodzhanov, 2009-12-10 18:33:01]

On 2009/12/10 18:32:27, Timur Iskhodzhanov wrote:
> Aw, crap, that's not fine.
> If one test fails, it breaks the execution of the consequent tests, arrrr
Or is it an expected behaviour?

[Paweł Hajdan Jr., 2009-12-10 18:36:08]

On 2009/12/10 18:33:01, Timur Iskhodzhanov wrote:
> On 2009/12/10 18:32:27, Timur Iskhodzhanov wrote:
> > Aw, crap, that's not fine.
> > If one test fails, it breaks the execution of the consequent tests, arrrr
> Or is it an expected behaviour?

No, it isn't. :(

[M-A Ruel, 2009-12-10 18:49:35]

Random note: Please reply to the try job email when the slave is hosed.

will look when you find a way to fix it. Personally, I'd prefer if the death
tests where always out of process.

http://codereview.chromium.org/482001/diff/9006/10003
File base/test/test_suite.h (right):

http://codereview.chromium.org/482001/diff/9006/10003#newcode153
base/test/test_suite.h:153: // By default, base::LogMessage::~LogMessage calls
DebugUtil::BreakDebugger()
Thanks for the doc.

[Timur Iskhodzhanov, 2009-12-10 19:05:22]

Hm, that looks like it IS the expected behaviour!

On Linux, I tried the following patch on a clean client:
//////////////////////////
--- base/cancellation_flag_unittest.cc
+++ base/cancellation_flag_unittest.cc
@@ -47,6 +47,9 @@ TEST(CancellationFlagTest, DoubleSetTest) {
   ASSERT_TRUE(flag.IsSet());
   flag.Set();
   ASSERT_TRUE(flag.IsSet());
+  LOG(ERROR) << "AAA";
+  CHECK(false);
+  LOG(ERROR) << "BBB";
 }
//////////////////////////
$ ./sconsbuild/Debug/base_unittests --gtest_filter="*Fl*"
Note: Google Test filter = *Fl*
[==========] Running 4 tests from 2 test cases.
[----------] Global test environment set-up.
[----------] 3 tests from CancellationFlagTest
[ RUN      ] CancellationFlagTest.SimpleSingleThreadedTest
[       OK ] CancellationFlagTest.SimpleSingleThreadedTest (0 ms)
[ RUN      ] CancellationFlagTest.DoubleSetTest
[1486:1486:1210/105407:91962220152:ERROR:base/cancellation_flag_unittest.cc(50)]
AAA
[1486:1486:1210/105407:91962220334:FATAL:base/cancellation_flag_unittest.cc(51)]
Check failed: false. 
[1486:1486:1210/105407:91962220334:FATAL:base/cancellation_flag_unittest.cc(51)]
Check failed: false. 
Backtrace:
	./sconsbuild/Debug/base_unittests [0x637601]
	./sconsbuild/Debug/base_unittests [0x64d2c9]
	./sconsbuild/Debug/base_unittests [0x4caede]
	./sconsbuild/Debug/base_unittests [0x6b3baf]
	./sconsbuild/Debug/base_unittests [0x6b7320]
	./sconsbuild/Debug/base_unittests [0x6b7456]
	./sconsbuild/Debug/base_unittests [0x6b7eb5]
	./sconsbuild/Debug/base_unittests [0x6b8005]
	./sconsbuild/Debug/base_unittests [0x4bf899]
	./sconsbuild/Debug/base_unittests [0x4be819]
	/lib/libc.so.6(__libc_start_main+0xf4) [0x7fea6f90d1c4]
	./sconsbuild/Debug/base_unittests [0x4be5a9]

Trace/breakpoint trap
////////////////////////////////
$ ./sconsbuild/Release/base_unittests --gtest_filter="*Fl*"
Note: Google Test filter = *Fl*
[==========] Running 4 tests from 2 test cases.
[----------] Global test environment set-up.
[----------] 3 tests from CancellationFlagTest
[ RUN      ] CancellationFlagTest.SimpleSingleThreadedTest
[       OK ] CancellationFlagTest.SimpleSingleThreadedTest (0 ms)
[ RUN      ] CancellationFlagTest.DoubleSetTest
[2774:2774:1210/110020:92334610073:ERROR:base/cancellation_flag_unittest.cc(50)]
AAA
[2774:2774:1210/110020:92334610176:FATAL:base/cancellation_flag_unittest.cc(51)]
Check failed: false. 
Trace/breakpoint trap
//////////////////////////////////

This is exactly the same behaviour as we get on Windows AFTER applying my patch.
BEFORE applying my patch, we see "BBB" line on Windows, which means the test
continues to execute.

Am I missing something?

On 2009/12/10 18:33:01, Timur Iskhodzhanov wrote:
> On 2009/12/10 18:32:27, Timur Iskhodzhanov wrote:
> > Aw, crap, that's not fine.
> > If one test fails, it breaks the execution of the consequent tests, arrrr
> Or is it an expected behaviour?

[Paweł Hajdan Jr., 2009-12-10 19:34:03]

Sorry, I misinterpreted your message about other tests being "disrupted" as
"they run, but behave weirdly". Terminating the process on DCHECK is expected
behavior.

[Timur Iskhodzhanov, 2009-12-10 20:18:27]

In order to be sure, I've uploaded http://codereview.chromium.org/491009
which intentionally fails on CHECK in one test, printing a couple of LOG(ERROR)
lines before and after the CHECK.

On Linux and Mac, CHECK stopped the tests
Linux
http://build.chromium.org/buildbot/try-server/builders/linux/builds/11369/ste...
Mac
http://build.chromium.org/buildbot/try-server/builders/mac/builds/11404/steps...

On Windows, it didn't
http://build.chromium.org/buildbot/try-server/builders/win/builds/11861/steps...
but it's very likely that the test itself continued to execute after the CHECK
failure, which is an error itself.
(the LOG(ERROR) lines are not present in the log because of some
windows-specific logging-on-bots stuff in Chromium...)

I think it is OK to commit the patch to base/test/test_suite.h
(please verify my sanity with LGTM once again)
and then I'll create a separate issue "Allow other tests to continue if one test
fails on a CHECK".

On 2009/12/10 19:05:22, Timur Iskhodzhanov wrote:
> Hm, that looks like it IS the expected behaviour!
> 
> On Linux, I tried the following patch on a clean client:
> //////////////////////////
> --- base/cancellation_flag_unittest.cc
> +++ base/cancellation_flag_unittest.cc
> @@ -47,6 +47,9 @@ TEST(CancellationFlagTest, DoubleSetTest) {
>    ASSERT_TRUE(flag.IsSet());
>    flag.Set();
>    ASSERT_TRUE(flag.IsSet());
> +  LOG(ERROR) << "AAA";
> +  CHECK(false);
> +  LOG(ERROR) << "BBB";
>  }
> //////////////////////////
> $ ./sconsbuild/Debug/base_unittests --gtest_filter="*Fl*"
> Note: Google Test filter = *Fl*
> [==========] Running 4 tests from 2 test cases.
> [----------] Global test environment set-up.
> [----------] 3 tests from CancellationFlagTest
> [ RUN      ] CancellationFlagTest.SimpleSingleThreadedTest
> [       OK ] CancellationFlagTest.SimpleSingleThreadedTest (0 ms)
> [ RUN      ] CancellationFlagTest.DoubleSetTest
>
[1486:1486:1210/105407:91962220152:ERROR:base/cancellation_flag_unittest.cc(50)]
> AAA
>
[1486:1486:1210/105407:91962220334:FATAL:base/cancellation_flag_unittest.cc(51)]
> Check failed: false. 
>
[1486:1486:1210/105407:91962220334:FATAL:base/cancellation_flag_unittest.cc(51)]
> Check failed: false. 
> Backtrace:
> 	./sconsbuild/Debug/base_unittests [0x637601]
> 	./sconsbuild/Debug/base_unittests [0x64d2c9]
> 	./sconsbuild/Debug/base_unittests [0x4caede]
> 	./sconsbuild/Debug/base_unittests [0x6b3baf]
> 	./sconsbuild/Debug/base_unittests [0x6b7320]
> 	./sconsbuild/Debug/base_unittests [0x6b7456]
> 	./sconsbuild/Debug/base_unittests [0x6b7eb5]
> 	./sconsbuild/Debug/base_unittests [0x6b8005]
> 	./sconsbuild/Debug/base_unittests [0x4bf899]
> 	./sconsbuild/Debug/base_unittests [0x4be819]
> 	/lib/libc.so.6(__libc_start_main+0xf4) [0x7fea6f90d1c4]
> 	./sconsbuild/Debug/base_unittests [0x4be5a9]
> 
> Trace/breakpoint trap
> ////////////////////////////////
> $ ./sconsbuild/Release/base_unittests --gtest_filter="*Fl*"
> Note: Google Test filter = *Fl*
> [==========] Running 4 tests from 2 test cases.
> [----------] Global test environment set-up.
> [----------] 3 tests from CancellationFlagTest
> [ RUN      ] CancellationFlagTest.SimpleSingleThreadedTest
> [       OK ] CancellationFlagTest.SimpleSingleThreadedTest (0 ms)
> [ RUN      ] CancellationFlagTest.DoubleSetTest
>
[2774:2774:1210/110020:92334610073:ERROR:base/cancellation_flag_unittest.cc(50)]
> AAA
>
[2774:2774:1210/110020:92334610176:FATAL:base/cancellation_flag_unittest.cc(51)]
> Check failed: false. 
> Trace/breakpoint trap
> //////////////////////////////////
> 
> This is exactly the same behaviour as we get on Windows AFTER applying my
patch.
> BEFORE applying my patch, we see "BBB" line on Windows, which means the test
> continues to execute.
> 
> Am I missing something?
> 
> On 2009/12/10 18:33:01, Timur Iskhodzhanov wrote:
> > On 2009/12/10 18:32:27, Timur Iskhodzhanov wrote:
> > > Aw, crap, that's not fine.
> > > If one test fails, it breaks the execution of the consequent tests, arrrr
> > Or is it an expected behaviour?

[Paweł Hajdan Jr., 2009-12-10 20:25:25]

On 2009/12/10 20:18:27, Timur Iskhodzhanov wrote:
> I think it is OK to commit the patch to base/test/test_suite.h
> (please verify my sanity with LGTM once again)

LGTM

> and then I'll create a separate issue "Allow other tests to continue if one
test
> fails on a CHECK".

That seems a little suspicious. After a CHECK the process may be in an
inconsistent state, which may affect other tests. If you want, you can work on
running each test in a separate process (we already do that for browser_tests).

[M-A Ruel, 2009-12-10 20:29:04]

I still have no opinion on this as long as the behavior is eventually set to be
consistent across all platforms.

lgtm