search

cedarbdd / cedar

BDD-style testing using Objective-C
http://groups.google.com/group/cedar-discuss
1.19k stars 140 forks source link

Console output is logged out of order #370

Open reneighbor opened 8 years ago

reneighbor commented 8 years ago

When logging print statements in the body of Cedar tests, we'd expect the print-out to show up AFTER the output logging the init for Cedar tests. However, it is consistently showing up AFTER the output for Cedar tests. Example:

Image of print before Cedar output

This is happening when project contains tests written in both Swift and Obj-C, as well as when the project contains only Cedar tests written in Swift or Cedar tests written in Obj-C.

Additionally, while the print output is consistently happening before the Cedar initializing output, at some times the print output is interrupted by the output specifying the test file location. Example:

Image of print interrupted by test file location

If you compare the image above with the first image, you'll see the test file location is usually in the very end of the test output.

According to Tim, we're also sometimes seeing the print output individual messages actually interrupted by the test file location output. This does not happen in a consistent way.

Our hypothesis is that the different sections of the console output are coming from different sources (std err, std out), and additionally both XCTest and Cedar are contributing to the output. The sources are getting out of order, which is causing this problem.

briancroom commented 8 years ago

Hey @reneighbor,

The reason you're seeing logs during your tests appear separated from the Cedar reporting is that Cedar uses the CDRBufferedDefaultReporter as the default reporter when running under an XCTest bundle. This is to ensure that the spec results summary is doesn't get scattered amidst XCTest's own verbose output which is streamed during the test run. If you'd like, you can override the reporter class being used by using the CEDAR_REPORTER_CLASS environment variable.

What really surprises me about your screenshots is that I'm not seeing the usual XCTest logs about test suites and test cases starting and completing. This is the sort of output I'd expect to see (from one of Cedar's own test bundles):

Test Suite 'All tests' started at 2016-01-25 13:33:31.028
Test Suite 'Cedar-OSX SpecBundle.xctest' started at 2016-01-25 13:33:31.972
Test Suite 'ExampleApplicationTestsWithXCTest' started at 2016-01-25 13:33:31.972
Test Case '-[ExampleApplicationTestsWithXCTest testMainBundleIsTheAppBundle]' started.
Test Case '-[ExampleApplicationTestsWithXCTest testMainBundleIsTheAppBundle]' passed (0.001 seconds).
Test Case '-[ExampleApplicationTestsWithXCTest testRunningCedarExamples]' started.
Test Case '-[ExampleApplicationTestsWithXCTest testRunningCedarExamples]' passed (0.001 seconds).
Test Suite 'ExampleApplicationTestsWithXCTest' passed at 2016-01-25 13:33:31.976.
     Executed 2 tests, with 0 failures (0 unexpected) in 0.001 (0.003) seconds
Test Suite 'Cedar-OSX SpecBundle.xctest' passed at 2016-01-25 13:33:31.976.
     Executed 2 tests, with 0 failures (0 unexpected) in 0.001 (0.005) seconds
Test Suite 'Cedar' started at 2016-01-25 13:33:31.977
Test Suite 'Cedar_OSX_SpecBundle.XCTAssertSpec' started at 2016-01-25 13:33:31.978
Test Case '-[_Cedar_OSX_SpecBundle.XCTAssertSpec XCTAssert_calls_in_a_Swift_Cedar_spec_should_allow_a_passing_assertion]' started.
Test Case '-[_Cedar_OSX_SpecBundle.XCTAssertSpec XCTAssert_calls_in_a_Swift_Cedar_spec_should_allow_a_passing_assertion]' passed (0.006 seconds).
Test Case '-[_Cedar_OSX_SpecBundle.XCTAssertSpec XCTAssert_calls_in_a_Swift_Cedar_spec_should_allow_a_failing_assertion]' started.
Test Case '-[_Cedar_OSX_SpecBundle.XCTAssertSpec XCTAssert_calls_in_a_Swift_Cedar_spec_should_allow_a_failing_assertion]' passed (0.020 seconds).
Test Suite 'Cedar_OSX_SpecBundle.XCTAssertSpec' passed at 2016-01-25 13:33:32.009.
     Executed 2 tests, with 0 failures (0 unexpected) in 0.026 (0.031) seconds
Test Suite 'CDRXCTestSuiteSpec' started at 2016-01-25 13:33:32.009
Test Case '-[_CDRXCTestSuiteSpec should_report_that_each_parent_example_group_has_started_and_ended]' started.
Test Case '-[_CDRXCSimulatedTestSuiteSpec with_nested_groups_lots_of_nested_groups_no_really_lots_of_nested_groups_should_start_and_finish_each_example_group]' started.
Test Case '-[_CDRXCSimulatedTestSuiteSpec with_nested_groups_lots_of_nested_groups_no_really_lots_of_nested_groups_should_start_and_finish_each_example_group]' passed (0.001 seconds).
Test Case '-[_CDRXCTestSuiteSpec should_report_that_each_parent_example_group_has_started_and_ended]' passed (0.002 seconds).
Test Case '-[_CDRXCTestSuiteSpec should_report_that_pending_examples_have_started_and_ended]' started.
Test Case '-[_CDRXCSimulatedTestSuiteSpec with_nested_groups_lots_of_nested_groups_no_really_lots_of_nested_groups_should_start_and_finish_each_example_group]' started.
Test Case '-[_CDRXCSimulatedTestSuiteSpec with_nested_groups_lots_of_nested_groups_no_really_lots_of_nested_groups_should_start_and_finish_each_example_group]' passed (0.001 seconds).
Test Case '-[_CDRXCTestSuiteSpec should_report_that_pending_examples_have_started_and_ended]' passed (0.005 seconds).
Test Suite 'CDRXCTestSuiteSpec' passed at 2016-01-25 13:33:32.018.
     Executed 2 tests, with 0 failures (0 unexpected) in 0.007 (0.009) seconds
Test Suite 'CDRXCSimulatedTestSuiteSpec' started at 2016-01-25 13:33:32.019
Test Case '-[_CDRXCSimulatedTestSuiteSpec with_nested_groups_lots_of_nested_groups_no_really_lots_of_nested_groups_should_start_and_finish_each_example_group]' started.
Test Case '-[_CDRXCSimulatedTestSuiteSpec with_nested_groups_lots_of_nested_groups_no_really_lots_of_nested_groups_should_start_and_finish_each_example_group]' passed (0.001 seconds).
Test Suite 'CDRXCSimulatedTestSuiteSpec' passed at 2016-01-25 13:33:32.020.
     Executed 1 test, with 0 failures (0 unexpected) in 0.001 (0.002) seconds
Test Suite 'Cedar' passed at 2016-01-25 13:33:32.021.
     Executed 5 tests, with 0 failures (0 unexpected) in 0.033 (0.044) seconds
Cedar Version: 0.12.0 (9a78c7ef5489ae3d0076e87b51346e1d5a2f054e)
Running With Random Seed: 46813

....P.P

PENDING CDRXCSimulatedTestSuite with nested groups lots of nested groups no really, lots of nested groups should report pending examples before the first test to run
PENDING CDRXCSimulatedTestSuite with nested groups lots of nested groups no really, lots of nested groups should report pending examples after the last test to run

Finished in 0.0474 seconds

7 examples, 0 failures, 2 pending
Test Suite 'All tests' passed at 2016-01-25 13:33:32.025.
     Executed 7 tests, with 0 failures (0 unexpected) in 0.035 (0.997) seconds

Test session log:
    /var/folders/_v/_fff7r3n7zg1h27zpz5dv1g5bd9ssr/T/com.apple.dt.XCTest-status/Session-2016-01-25_13:33:13-5EDjbu.log

Regarding the mixed up ordering, I think you're right about it being due to different sources for the output, however it's actually separate processes that are contributing during the test run.