Skip to content
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

Add logging for V2 test scheduler as temporary workaround until V2 UI is finished #7729

Merged

Conversation

Eric-Arellano
Copy link
Contributor

@Eric-Arellano Eric-Arellano commented May 14, 2019

We want to add logging to ./pants test when using V2 both as a matter of UI and to avoid Travis timeouts of not receiving input for 10+ minutes.

Eventually, we should be doing this via a Logging singleton, similar to the Console singleton, per #6004. This acts as a temporary workaround in the meantime.

Result

$ ./pants --no-v1 --v2 test tests/python/pants_test/util:strutil tests/python/pants_test/util:dirutil tests/python/pants_test/util:contextutil tests/python/pants_test/util:tarutil tests/python/pants_test/util:argutil tests/python/pants_test/util:collections
18:53:47 [INFO] Starting tests: tests/python/pants_test/util:strutil
18:53:47 [INFO] Starting tests: tests/python/pants_test/util:dirutil
18:53:47 [INFO] Starting tests: tests/python/pants_test/util:argutil
18:53:47 [INFO] Starting tests: tests/python/pants_test/util:contextutil
18:53:47 [INFO] Starting tests: tests/python/pants_test/util:tarutil
18:53:47 [INFO] Starting tests: tests/python/pants_test/util:collections
18:53:57 [INFO] Tests succeeded: tests/python/pants_test/util:argutil
18:53:59 [INFO] Tests succeeded: tests/python/pants_test/util:collections
18:53:59 [INFO] Tests succeeded: tests/python/pants_test/util:strutil
18:53:59 [INFO] Tests succeeded: tests/python/pants_test/util:tarutil
18:54:00 [INFO] Tests failed: tests/python/pants_test/util:contextutil
18:54:03 [INFO] Tests failed: tests/python/pants_test/util:dirutil
tests/python/pants_test/util:strutil stdout:
============================= test session starts ==============================
platform darwin -- Python 3.6.8, pytest-3.6.4, py-1.8.0, pluggy-0.7.1
rootdir: /Users/eric/DocsLocal/code/projects/pants/.pants.d/process-executionTYuLur, inifile:
plugins: timeout-1.2.1, cov-2.4.0
collected 5 items

pants_test/util/test_strutil.py .....                                    [100%]

=========================== 5 passed in 0.07 seconds ===========================

tests/python/pants_test/util:dirutil stdout:
...

Copy link
Contributor Author

@Eric-Arellano Eric-Arellano left a comment

Choose a reason for hiding this comment

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

Open questions:

  1. Do we like the output shown in the PR description?
  2. Will this support config logging levels? I haven't looked into this yet.
  3. The coordinator tests now fail because their stdout has the logging information. Should we teach the tests to be okay with logs, or turn off the logs in those tests somehow
    def test_coordinator_python_test(self):
    target_adaptor = PythonTestsAdaptor(type_alias='python_tests')
    result = run_rule(coordinator_of_tests, HydratedTarget(Address.parse("some/target"), target_adaptor, ()), {
    (PyTestResult, HydratedTarget): lambda _: PyTestResult(status=Status.FAILURE, stdout='foo', stderr=''),
    })
    self.assertEqual(result, TestResult(status=Status.FAILURE, stdout='foo', stderr=''))
    def test_coordinator_unknown_test(self):
    target_adaptor = PythonTestsAdaptor(type_alias='unknown_tests')
    with self.assertRaises(Exception) as cm:
    run_rule(coordinator_of_tests, HydratedTarget(Address.parse("some/target"), target_adaptor, ()), {
    (PyTestResult, HydratedTarget): lambda _: PyTestResult(status=Status.FAILURE, stdout='foo', stderr=''),
    })
    self.assertEqual(str(cm.exception), "Didn't know how to run tests for type unknown_tests")

cc @stuhood

Copy link
Member

@stuhood stuhood left a comment

Choose a reason for hiding this comment

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

Thanks, just nits.

src/python/pants/rules/core/test.py Outdated Show resolved Hide resolved
src/python/pants/rules/core/test.py Outdated Show resolved Hide resolved
@Eric-Arellano
Copy link
Contributor Author

  1. Will this support config logging levels? I haven't looked into this yet.

Yes, it does hook up properly. ./pants --no-v1 --v2 -lwarn test tests/python/pants_test/util: will not show any logs.

  1. The coordinator tests now fail because their stdout has the logging information. Should we teach the tests to be okay with logs, or turn off the logs in those tests somehow?

@stuhood how do you recommend approaching this? Usually we would use TestBase.captured_logging, but our rule testing infrastructure does not offer this. I don't think it would make sense to add the functionality to the rule testing code because we are still waiting for the Logging singleton implementation.

Should we just modify the tests and accept that they will now be a little more brittle? Or change from assertEqual to assertIn?

@stuhood
Copy link
Member

stuhood commented May 14, 2019

@stuhood how do you recommend approaching this? Usually we would use TestBase.captured_logging, but our rule testing infrastructure does not offer this. I don't think it would make sense to add the functionality to the rule testing code because we are still waiting for the Logging singleton implementation.

If those tests were extending ConsoleRuleTestBase, then I think that it might be possible to capture this logging? But I'm also not sure why captured_logging wouldn't just work in any TestBase case, due to how it is implemented.

In the case of an integration test, either disabling logging via -lwarn or accepting fragility seem like the options.

@Eric-Arellano
Copy link
Contributor Author

Oops, turns out they did indeed extend TestBase. My bad for missing that.

Thanks for the help!

@Eric-Arellano Eric-Arellano marked this pull request as ready for review May 14, 2019 21:20
@Eric-Arellano Eric-Arellano changed the title WIP: Add logging for V2 test scheduler Add logging for V2 test scheduler May 14, 2019
Copy link
Member

@stuhood stuhood left a comment

Choose a reason for hiding this comment

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

Thanks!

@blorente
Copy link
Contributor

I'm undecided about the format of this. Particularly, I'd (personally, I can be wrong) love for successful test runs to have as little output as possible, eventually something very close to:

$ ./pants --v2 --no-v1 test ...

  SUCCESS

Basically, I usually don't care about the tests that have succeeded, just the ones that have not. If we log at the info level here, we are unconditionally printing a bunch of output (up to several thousands of lines) even in successful cases. I can't think of any case where, as a user, I care about when a successful test has finished. I'm also not sure that I care about when tests have started, unless I'm debugging an issue I know about, but there might be some. I think the biggest value of this comes from an easily parseable summary of what tests went wrong.

So, my proposal:

  • Move the log level to -ldebug
  • If necessary, print a summary to stderr at the end of fast_test, that is easily parseable. This is extremely useful for scripts that fetch the output of runs from CI and generate automatic repros. Something along the lines of:
The following targets failed:

  tests/my/test:tests
  some/other:tests

So, I'd argue in favour of moving this to the -ldebug level.

Copy link
Contributor

@blorente blorente left a comment

Choose a reason for hiding this comment

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

But also it's a matter of opinion, I'm fine with the format and the code changes in general :)

@Eric-Arellano
Copy link
Contributor Author

So, I'd argue in favour of moving this to the -ldebug level.

I think that's a great suggestion! Really we only care about this logging when using our ci.sh script, because we run so many targets all at once and we need to work around the Travis 10 minute timeout.

But you're right that in general people won't care when the test started or finished, especially when locally running one or two targets.

@Eric-Arellano
Copy link
Contributor Author

So, I'd argue in favour of moving this to the -ldebug level.

Hm, on second thought, I'm not as certain anymore. Running with -ldebug leads to very verbose output:

./pants --no-v1 --v2 -ldebug test tests/python/pants_test/util:strutil
08:59:50 [DEBUG] pants.base.exception_sink:pid=92826: re-enabling faulthandler
08:59:50 [DEBUG] pants.build_graph.build_configuration:pid=92826: Target alias resources has already been registered. Overwriting!
08:59:51 [DEBUG] pants.base.project_tree:pid=92826: ProjectTree ignore_patterns: ['.*/', '/dist/', '/build-support/*.venv/', '/build-support/bin/native/src']
08:59:51 [DEBUG] pants.init.target_roots_calculator:pid=92826: spec_roots are: Specs(dependencies<Exactly(tuple)>=(SingleAddress(directory='tests/python/pants_test/util', name='strutil'),), matcher<Exactly(SpecsMatcher)>=SpecsMatcher(tags<Exactly(tuple)>=(), exclude_patterns<Exactly(tuple)>=()))
08:59:51 [DEBUG] pants.init.target_roots_calculator:pid=92826: changed_request is: ChangedRequest(changes_since=None, diffspec=None, include_dependees=none, fast=False)
08:59:51 [DEBUG] pants.init.target_roots_calculator:pid=92826: owned_files are: []
08:59:51 [DEBUG] pants.init.engine_initializer:pid=92826: requesting <class 'pants.rules.core.test.Test'> to satisfy execution of `test` goal
08:59:51 [DEBUG] engine::scheduler: Launching 1 roots.
08:59:51 [DEBUG] fs::store::local: Initializing ShardedLmdb at root "/Users/eric/.cache/pants/lmdb_store/files"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/files/0"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/files/0"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/files/1"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/files/1"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/files/2"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/files/2"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/files/3"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/files/3"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/files/4"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/files/4"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/files/5"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/files/5"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/files/6"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/files/6"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/files/7"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/files/7"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/files/8"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/files/8"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/files/9"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/files/9"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/files/a"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/files/a"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/files/b"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/files/b"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/files/c"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/files/c"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/files/d"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/files/d"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/files/e"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/files/e"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/files/f"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/files/f"
08:59:51 [DEBUG] fs::store::local: Initializing ShardedLmdb at root "/Users/eric/.cache/pants/lmdb_store/directories"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/directories/0"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/directories/0"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/directories/1"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/directories/1"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/directories/2"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/directories/2"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/directories/3"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/directories/3"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/directories/4"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/directories/4"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/directories/5"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/directories/5"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/directories/6"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/directories/6"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/directories/7"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/directories/7"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/directories/8"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/directories/8"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/directories/9"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/directories/9"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/directories/a"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/directories/a"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/directories/b"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/directories/b"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/directories/c"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/directories/c"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/directories/d"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/directories/d"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/directories/e"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/directories/e"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb content database for "/Users/eric/.cache/pants/lmdb_store/directories/f"
08:59:51 [DEBUG] fs::store::local: Making ShardedLmdb lease database for "/Users/eric/.cache/pants/lmdb_store/directories/f"
08:59:51 [DEBUG] pants.rules.core.test:pid=92826: Starting tests: tests/python/pants_test/util:strutil
08:59:59 [DEBUG] pants.rules.core.test:pid=92826: Tests succeeded: tests/python/pants_test/util:strutil
tests/python/pants_test/util:strutil stdout:
============================= test session starts ==============================
platform darwin -- Python 3.6.8, pytest-3.6.4, py-1.8.0, pluggy-0.7.1
rootdir: /Users/eric/DocsLocal/code/projects/pants/.pants.d/process-execution0twgRV, inifile:
plugins: cov-2.4.0, timeout-1.2.1
collected 5 items

pants_test/util/test_strutil.py .....                                    [100%]

=========================== 5 passed in 0.07 seconds ===========================


tests/python/pants_test/util:strutil                                            .....   SUCCESS
08:59:59 [DEBUG] engine::scheduler: Root Select((<pants.engine.console.Console object at 0x10ae82c18>+OptionsBootstrapper(env_tuples<Exactly(tuple)>=(('PANTS_DEV', '1'), ('PANTS_PYTHON_SETUP_INTERPRETER_CONSTRAINTS', "['CPython==3.6.8']")), bootstrap_args<Exactly(tuple)>=('-ldebug',), args<Exactly(tuple)>=('/Users/eric/DocsLocal/code/projects/pants/src/python/pants/bin/pants_loader.py', '--no-v1', '--v2', '-ldebug', 'test', 'tests/python/pants_test/util:strutil'), config<SubclassesOf(Config)>=_ChainedConfig(chained_configs=(<pants.option.config._SingleFileConfig object at 0x10769ff28>,)))+Specs(dependencies<Exactly(tuple)>=(SingleAddress(directory='tests/python/pants_test/util', name='strutil'),), matcher<Exactly(SpecsMatcher)>=SpecsMatcher(tags<Exactly(tuple)>=(), exclude_patterns<Exactly(tuple)>=()))), Test) completed.
08:59:59 [DEBUG] pants.engine.scheduler:pid=92826: computed 1 nodes in 8.323910 seconds. there are 64 total nodes.

All we're after is the logs about when tests start and when they finish, so that ./pants --no-v1 --v2 test src/python:: tests/python:: does not give no output until it's completely done and to avoid the Travis timeout. Setting it at -ldebug means we would as a consequence be logging all this other noise we don't care about in CI.

@illicitonion @stuhood @cosmicexplorer what do you all recommend? -ldebug, -linfo, or an entirely alternative solution?

@stuhood
Copy link
Member

stuhood commented May 15, 2019

@blorente : With pantsd, the log message only triggers on the first run in a session, and then again when something has been invalidated.

@stuhood
Copy link
Member

stuhood commented May 15, 2019

@Eric-Arellano : IMO, leave it at info. We should be biasing toward the behavior with pantsd.

@illicitonion
Copy link
Contributor

I just had a bunch of discussion with @blorente about this...

I think this is a reasonable short-term hack, but I have some different ideas for the long term.

I think that there are two use-cases for this logging:

  1. Show some watcher (either a user, or travis) that pants isn't hanging.
  2. Give enough useful information that if one particular test is hanging, the user knows which test to debug.

There are two "modes" of pants running:
a. A user is running streaming to a live TTY.
b. Pants is running piped to something that isn't a live TTY.

The v2 UI is meant to solve both 1 and 2, for case a.
This is manually re-implementing the heavy-hitters portion of the v2 UI. Ideally, we wouldn't be manually implementing this for every console_rule (or rule type in general).

I think the solution I'd like to see long term is something along the lines of:
Remove this logging.
When streaming to a live TTY, we just rely on the v2 UI to display this information.
When not streaming to a live TTY (either on travis, or when piping to a file, or whatever), we periodically dump the heavy hitters to stderr. Maybe every (configurable) 30 seconds, or maybe when the heavy hitters we'd be displaying change, or maybe some combination of the two.

Until the v2 UI lands, I'm happy to add this logging, but I think it's an until-v2-ui hack rather than the right long-term solution... I'm cool with this being at info level, though I may remove the logging for the success cases.

@Eric-Arellano
Copy link
Contributor Author

Great feedback and plan. Thank you for that. I linked to it in #6004 + a TODO comment.

Stu and I discussed that we're going to keep the success logging for now to avoid Travis timeouts and for the scenario of running a bunch of tests, but then the Pants process terminating early (either control-c or timeout), and still wanting to be able to get some useful information about the results.

@Eric-Arellano Eric-Arellano changed the title Add logging for V2 test scheduler Add logging for V2 test scheduler as temporary workaround until V2 UI is finished May 15, 2019
@Eric-Arellano Eric-Arellano merged commit df97a31 into pantsbuild:master May 15, 2019
@Eric-Arellano Eric-Arellano deleted the v2-pytest-timeout-logging branch May 15, 2019 18:56
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.

4 participants