Skip to content

CDRIVER-4537 Ensure all aborts in test suite are preceeded by flushes #1164

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 2 commits into from
Dec 16, 2022

Conversation

eramongodb
Copy link
Contributor

@eramongodb eramongodb commented Dec 15, 2022

This PR extends the work done for CDRIVER-4537 by #1161. Verified by this patch.

This PR ensures (almost) all instances of a call to abort() within src/libmongoc/tests is replaced by an invocation of test_error () instead. The only remaining exceptions are:

  • TestSuite.h and TestSuite.c: defines assertion macros used by test suite.
  • future.c: avoid including TestSuite.h (unnecessary concern?)
  • test-mongoc-gssapi.c: its own executable; avoid introducing linkage with TestSuite.c.

All abort () are replaced by a call to test_error, which handles flushing of stdout and stderr. Any immediately preceeding messages emited via fprintf() or MONGOC_ERROR are moved into the call to test_error. Final '\n' characters were removed from error messages as test_error ensures the emitted message is followed by a newline character.

This PR is motivated by confusing errors messages in failing tasks such as in this patch:

test error in: /data/mci/4128de49870bba0675944a05b9a9b9bb/mongoc/src/libmongoc/tests/unified/test-diagnostics.c 162:test_diagnostics_abort()
****************************** BEGIN_MONGOC_ERROR ******************************
test info:
[/data/mci/4128de49870bba0675944a05b9a9b9bb/mongoc/src/libmongoc/tests/unified/runner.c:1695 run_one_test_file()]
test file: observeSensitiveCommands
[/data/mci/4128de49870bba0675944a05b9a9b9bb/mongoc/src/libmongoc/tests/unified/runner.c:1699 run_one_test_file()]
running test: getnonce is observed with observeSensitiveCommands=true
error context:
[/data/mci/4128de49870bba0675944a05b9a9b9bb/mongoc/src/libmongoc/tests/unified/runner.c:1622 test_run()]
running operations
2022/12/15 10:04:17.0445: [32793]:    DEBUG:       mongoc: topology changed, adding server id: 1
[/data/mci/4128de49870bba0675944a05b9a9b9bb/mongoc/src/libmongoc/tests/unified/runner.c:1010 test_run_operations()]
2022/12/15 10:04:17.0566: [32793]:    DEBUG:       mongoc: [/data/mci/4128de49870bba0675944a05b9a9b9bb/mongoc/src/libmongoc/tests/unified/runner.c:1666 run_one_test_file()]
running operation: { "name" : "runCommand", "object" : "database0", "arguments" : { "commandName" : "getnonce", "command" : { "getnonce" : { "$numberInt" : "1" } } } }
test file: observeSensitiveCommands
2022/12/15 10:04:17.0566: [32793]:    DEBUG:       mongoc: [/data/mci/4128de49870bba0675944a05b9a9b9bb/mongoc/src/libmongoc/tests/unified/runner.c:1695 run_one_test_file()]
[/data/mci/4128de49870bba0675944a05b9a9b9bb/mongoc/src/libmongoc/tests/unified/operation.c:3431 operation_run()]
test file: observeSensitiveCommands
checking for result ((NULL)) / error ((NULL))
2022/12/15 10:04:17.0566: [32793]:    DEBUG:       mongoc: [/data/mci/4128de49870bba0675944a05b9a9b9bb/mongoc/src/libmongoc/tests/unified/runner.c:1699 run_one_test_file()]
error: expected success, but got error: no such command: 'getnonce'
running test: getnonce is observed with observeSensitiveCommands=true
******************************* END_MONGOC_ERROR *******************************
2022/12/15 10:04:17.0637: [32793]:    DEBUG:       mongoc: running operation: { "name" : "runCommand", "object" : "database0", "arguments" : { "commandName" : "getnonce", "command" : { "getnonce" : { "$numberInt" : "1" } } } }
2022/12/15 10:04:17.0661: [32793]:    DEBUG:       mongoc: [/data/mci/4128de49870bba0675944a05b9a9b9bb/mongoc/src/libmongoc/tests/unified/operation.c:3431 operation_run()]
checking for result ((NULL)) / error ((NULL))
2022/12/15 10:04:17.0661: [32793]:    DEBUG:       mongoc: [/data/mci/4128de49870bba0675944a05b9a9b9bb/mongoc/src/libmongoc/tests/unified/runner.c:1010 test_run_operations()]
running operation: { "name" : "runCommand", "object" : "database0", "arguments" : { "commandName" : "getnonce", "command" : { "getnonce" : { "$numberInt" : "1" } } } }
2022/12/15 10:04:17.0661: [32793]:    DEBUG:       mongoc: [/data/mci/4128de49870bba0675944a05b9a9b9bb/mongoc/src/libmongoc/tests/unified/runner.c:1622 test_run()]
running operations
.evergreen/scripts/run-tests.sh: line 190:  2157 Abort trap: 6           (core dumped) ./src/libmongoc/test-libmongoc --no-fork $TEST_ARGS -d

Synchronization of stdout and stderr ensures the output is not interspersed with stdout messages, as demonstrated by this patch:

test error in: /data/mci/3d1ca01040c2e1c449ccfee0ddfb7500/mongoc/src/libmongoc/tests/unified/test-diagnostics.c 162:test_diagnostics_abort()
****************************** BEGIN_MONGOC_ERROR ******************************
test info:
[/data/mci/3d1ca01040c2e1c449ccfee0ddfb7500/mongoc/src/libmongoc/tests/unified/runner.c:1695 run_one_test_file()]
test file: observeSensitiveCommands
[/data/mci/3d1ca01040c2e1c449ccfee0ddfb7500/mongoc/src/libmongoc/tests/unified/runner.c:1699 run_one_test_file()]
running test: getnonce is observed with observeSensitiveCommands=true
error context:
[/data/mci/3d1ca01040c2e1c449ccfee0ddfb7500/mongoc/src/libmongoc/tests/unified/runner.c:1622 test_run()]
running operations
[/data/mci/3d1ca01040c2e1c449ccfee0ddfb7500/mongoc/src/libmongoc/tests/unified/runner.c:1010 test_run_operations()]
running operation: { "name" : "runCommand", "object" : "database0", "arguments" : { "commandName" : "getnonce", "command" : { "getnonce" : { "$numberInt" : "1" } } } }
[/data/mci/3d1ca01040c2e1c449ccfee0ddfb7500/mongoc/src/libmongoc/tests/unified/operation.c:3431 operation_run()]
checking for result ((NULL)) / error ((NULL))
error: expected success, but got error: no such command: 'getnonce'
******************************* END_MONGOC_ERROR *******************************
.evergreen/run-tests.sh: line 143:  6430 Aborted                 (core dumped) ./src/libmongoc/test-libmongoc --no-fork $TEST_ARGS -d

@eramongodb eramongodb self-assigned this Dec 15, 2022
Copy link
Collaborator

@kevinAlbs kevinAlbs left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Easier to read log output is really helpful.

future.c: avoid including TestSuite.h (unnecessary concern?)

That might be OK. mock-server.c already includes TestSuite.h. An eventual improvement may be to split the assertions from TestSuite.h into a separate header. But not necessary in this PR.

Comment on lines +10 to +17
#define FUTURE_TIMEOUT_ABORT \
if (1) { \
fflush (stdout); \
fprintf (stderr, "%s timed out\n", BSON_FUNC); \
fflush (stderr); \
abort (); \
} else \
((void) 0)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm curious why we use this if (1) { ... } else pattern in several places rather than the more common do { ... } while (0)?

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think that pattern started recently from @vector-of-bool. This article describes the motivation.

Comment on lines +1585 to +1591
#define ASSERT_OP_TIMES_EQUAL(_a, _b) \
if ((_a).t != (_b).t || (_a).i != (_b).i) { \
test_error (#_a " (%d, %d) does not match " #_b " (%d, %d)", \
(_a).t, \
(_a).i, \
(_b).t, \
(_b).i); \
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would suggest that we wrap multiline macros such as this in a do { ... } while (0), since as written it can behave unexpectedly within an if/else, for example, if we have the following code, we will get a syntax error:

 11 #define FOO(X) \
 12     if (X) { \
 13         foo(X); \
 14         bar(X); \
 15     }
...
 25 int main(int argc, char **argv) {
 26     if (argc > 2)
 27         FOO(argc);
 28     else
 29         puts("hello");
 30 }

Syntax error:

2022-12-16 9:04:05 [~/src/test]$ gcc dowhile.c
dowhile.c:28:5: error: expected expression
    else
    ^
1 error generated.

However, if we wrap in a do/while(0), the macro works as expected:

 17 #define BAR(X) \
 18     do { \
 19         if (X) { \
 20             foo(X); \
 21             bar(X); \
 22         } \
 23     } while (0)
 24
 25 int main(int argc, char **argv) {
 26     if (argc > 2)
 27         BAR(argc);
 28     else
 29         puts("hello");
 30 }

Compiles as expected:

2022-12-16 9:04:37 [~/src/test]$ gcc dowhile.c
2022-12-16 9:04:38 [~/src/test]$

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good spot. Updated accordingly using the pattern described in your other comment.

Copy link
Contributor

@kkloberdanz kkloberdanz left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@eramongodb eramongodb merged commit d113429 into mongodb:master Dec 16, 2022
@eramongodb eramongodb deleted the cdriver-4537 branch December 16, 2022 16:39
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants