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

Game Runner thread / subprocess improvements #571

Merged
merged 68 commits into from
Oct 9, 2020

Conversation

keturn
Copy link
Member

@keturn keturn commented May 8, 2020

This is all about what happens when you push that "⏵ Run Game" button.

Things in scope include:

  • On failure to launch, let the user know as soon as we do. (Instead of freezing for five seconds first.)
  • Error messages from the failing game task should appear in the Logs tab by default. improve failed launch UX #550

This branch introduces the use of TestFX in order to test code relying on JavaFX classes.

How to test

All the things that involve starting a game and configuring what happens when it starts and exits.

Outstanding before merging

This branch is in a working state at the moment but there are some things to clean up before it'll be out of draft status.

  • merge dependency branch test-logs test: use spf4j-slf4j-test to unit test logging #562.
  • make sure github validation can run the unit tests.
  • case of process-had-no-error-but-was-done-very fast. (I considered forgetting about this requirement, until I realized that it would be bad in conjunction with the exit-after-launch setting.)
  • move executor-specific things out of ApplicationController.
  • the case of log-level = None && exit-after-launch = true

maybe nice to have

Comment if these look important:

  • gradle task to run tests in headless-mode even when run on a fully graphics-capable dev environment (or flag to existing test task)
  • update acceptance tests.
  • yet more docstrings. (I think the more outward-facing methods are documented, but there's not 100% coverage of all private methods and fields)
  • Windows? There are some unit tests marked as Disabled-on-Windows because I don't know if they'll run there. Will they? Do we need alternate test implementations for Windows? Can any of those tests be covered by cross-platform code instead?
  • TestGameStarter unit tests for heap-min, heap-max, and log-level.

@keturn
Copy link
Member Author

keturn commented May 9, 2020

Hmm. Github action is failing with:

TestRunGameTask > testGameOutput() FAILED
    java.lang.RuntimeException at WaitForAsyncUtils.java:301
        Caused by: java.lang.UnsupportedOperationException at GtkApplication.java:173

...you want to give me any other details about that, github action? like which invocation of WaitForAsyncUtils that was, or what the heck is on line 173 of GtkApplication.java?

Well. I guess we add "get tests to run under CI" to the list. It's quite possible there's a thing we have to do to tell TestFX it's in headless mode or something.

@keturn
Copy link
Member Author

keturn commented May 9, 2020

My copy of GtkApplication.java says that UnsupportedOperationException should come with a message:

            if (libraryToLoad == QUERY_NO_DISPLAY) {
                throw new UnsupportedOperationException("Unable to open DISPLAY");

@keturn
Copy link
Member Author

keturn commented May 11, 2020

For adding an option to force headless mode, gradle can add system properties to the tests: https://docs.gradle.org/current/dsl/org.gradle.api.tasks.testing.Test.html#org.gradle.api.tasks.testing.Test:systemProperties(java.util.Map)

not sure what the most ergonomic way would be to invoke that. I was thinking of adding a --headless option to the existing test task, but I don't know if we can add fields to existing tasks like that. Maybe we end up making a new headlessTest task that extends the base one?

@keturn
Copy link
Member Author

keturn commented May 11, 2020

Okay. I added a bunch of javadocs.

Let me know when you see other things I've added in here that still could use documenting.

@keturn keturn marked this pull request as ready for review May 25, 2020 23:50
@keturn
Copy link
Member Author

keturn commented May 26, 2020

Okay, I think I've fixed the regression where this branch wasn't considering the launch a failure if it came back right away. With that, I think this branch is viable.

There's a little more polish and rigor it could have, described by the checklist in the main body of this issue, but I think a lot of those are negotiable depending on how much weight the reviewers give them.

@skaldarnar & @jdrueckert, I'd like for this branch to not get lost in the land of things-that-almost-were. I think it does a significant amount to improve the sort of experience described in #550, and in my humble opinion leaves the code in a better place technically.

Let me know if the test-logs dependency is a blocker and I can pull that out. I never wanted to get in to a fight with slf4j on the classpath, I was just trying to get to a place where I could do some test-driven development for working on GameRunner's quirks. That now accomplished, I care more about having the application code merged than I do for the mess of groovy code that's trying to manage the dependency conflicts.

Copy link
Member

@skaldarnar skaldarnar left a comment

Choose a reason for hiding this comment

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

Part 1 (up to src/main/java/org/terasology/launcher/game/GameStarter.java)

I still don't fully understand the details of what's going on, but I guess you can live with merging this now and reacting to changes and requirements in the future. If this becomes a blocker in going forward with Java 14+, we'll throw it out/adapt it/replace it 😉

... and conflicts in build.gradle o.O

build.gradle Outdated
testImplementation('org.spf4j:spf4j-slf4j-test:8.8.+') {
because "testable logging"
}
testImplementation("org.slf4j:slf4j-api:1.7.+!!") {
Copy link
Member

Choose a reason for hiding this comment

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

.+!!" the elder speak to me - what do they want to tell me o.O

Copy link
Member Author

Choose a reason for hiding this comment

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

1.7.+ prefixed version range, any 1.7.x version

!! strict version. that is, if something else pulled in slf4j-api 1.8, do not consider that to satisfy this dependency, because it does not match 1.7.

oh, that page shows there are ways we could write this out in the DSL instead of the symbol-heavy shorthand:

testImplementation("org.slf4j:slf4j-api") {
    version {
        strictly("1.7.+")
    }
}

@skaldarnar skaldarnar added Topic: Documentation Documentation and technical writing. Type: Enhancement New features or noticable improvements. labels May 28, 2020
keturn added 15 commits June 1, 2020 14:37
This is a slf4j provider made to write test assertions against.

But there can be only one slf4j provider on your classpath at the same time, otherwise who knows which will be used.

the remal.component-metadata plugin identifies a lot of these sorts of conflicts so they don't happen silently.

but that doesn't have spf4j-slf4j-test in its list of things it knows about, so we also need to specify that.

once you've identified conflicts, you have to resolve them, which takes ten lines for some reason, so I put it in a function.

debugging wasn't working very well on scripts included with `apply from`, and that's how I ended up writing a gradle plugin.
with slight refactor to avoid mocking static method on Thread.
The more I look at it the more it circles back to the current design.
like `hasItems` but it checks from one collection you pass to it, not each one of a variable number of arguments.
so other tests can use jupiter Extension
We use TestFX so the JavaFX Task has an Application Thread to run in.
Replace the GameStarter Interface with Callable<Process>.
We don't want thread cancellation to terminate the process.
@lgtm-com
Copy link

lgtm-com bot commented Sep 7, 2020

This pull request introduces 1 alert when merging 6667350 into 761f149 - view on LGTM.com

new alerts:

  • 1 for Potential input resource leak

@keturn
Copy link
Member Author

keturn commented Sep 7, 2020

There might be an intermittent test failure? because the checks shown on this PR pass, but there's a failure reported on https://github.com/keturn/TerasologyLauncher/actions/runs/243384472

@skaldarnar
Copy link
Member

skaldarnar commented Oct 5, 2020

Since this PR is so huge I wanted to start with compiling the code locally and running the tests. After some trouble with the unicode characters introduced there these are the test results when executing the suite in IntelliJ on Windows:
image
... not very satisfying 😞 Running gradlew test from in the Windows git bash shows a similar result:

TestRunGameTask > testExeNotFound() FAILED
    java.lang.AssertionError at TestRunGameTask.java:176

TestFileUtils > testCannotCreateDirectory() FAILED
    java.lang.AssertionError at TestFileUtils.java:58

TestFileUtils > testNoPerms() FAILED
    java.lang.UnsupportedOperationException at TestFileUtils.java:83

43 tests completed, 3 failed, 3 skipped

@keturn
Copy link
Member Author

keturn commented Oct 5, 2020

Good to know. There's a lot of platform-specific quirks to both filesystems and process execution, and I haven't had a Windows environment to test in.

and, bleh, that's not a very informative test failure message. Looks like I'll have to get that Windows VM up when I have more disk space.

@keturn
Copy link
Member Author

keturn commented Oct 5, 2020

wait, I don't see any TestFileUtils changes in this branch. Do those failures happen for you on the main branch?

@keturn
Copy link
Member Author

keturn commented Oct 5, 2020

Continuing from discord:

for PR-2 and PR-3 I'm thinking of adding the feature code/refactoring first, without any tests, and adding the tests in PR-3 only. In github, you can set the target of PR-3 to PR-2, and the two diffs will show a bit cleaner. I can review them separately, we merge them together, and then we merge both to master.... or we can merge both to master on their own if you don't mind having a commit in the main branch without the tests 😉

I feel like I'm misunderstanding something significant about what you're looking for out of this.

From just a GitHub UI perspective, if you're reviewing by file, implementation is already separated from tests, and the src/main/* files are sorted before the src/test/* files.

From a reviewer's perspective, I don't know why a reviewer would ask to review the code without its tests. Knowing what is tested and how is a big concern when I do reviews. Ideally, tests also inform the reader about how the code under test is used and why it has some of the wrinkles it does.

(In practice, I often find that when reading a test I have a hard time identifying the important parts of it among all the other stuff that's boilerplate. I'm interested in getting better at that, in both reading and writing tests, so feedback on test legibility is very welcome here.)

all of which to say I don't know how to implement that PR-splitting suggestion in a way that seems like it will be helpful.

@keturn
Copy link
Member Author

keturn commented Oct 5, 2020

Some landmarks for navigating this package:

  • launcher.game.GameService is the entry point, and the part you looked at previously. It's a javafx.concurrent.Service because that seems to be the javafx abstraction that best fits this, as this thing that has its own lifecycle and is not itself in the tree of UI elements. Using the JavaFX-specific class seemed worth doing because JavaFX has rules about which things do and don't happen on the application thread, and using its implementation of these interfaces helps manage that.
  • launcher.game.GameStarter retains a lot of its responsibilities from before: It's responsible for knowing how to turn our various options in to a Process with all the right arguments. But the code responsible for monitoring the state of that process has been split out to –
  • launcher.game.RunGameTask, again using the javafx-specific javafx.concurrent.Task to stay on javafx's good side about how to communicate between threads. This is where we put all the gnarly details about how we decide if the game process is alive and healthy. A chief outcome of this PR is to take that logic that was scattered around GameStarter and the Controller and contain it in this nicely Task-shaped interface.

@keturn
Copy link
Member Author

keturn commented Oct 6, 2020

(dis)honorable mention:

StringIteratorInputStream (under src/test/):

* An {@code InputStream} fed by an {@code Iterator<String>}.
* <p>
* Testing something that consumes an {@link InputStream} {@linkplain BufferedReader#lines() line-by-line}? Your test
* fixture has a list of strings to use as inputs; how hard could it be to get an InputStream that will pass them one
* at a time?

This is a class that I'm inordinately proud I got to work, and I also fear is the worst for maintainability.

I think the way to get it to go away is to factor out this bit of RunGameTask.monitorProcess

// log each line of process output
var gameOutput = new BufferedReader(new InputStreamReader(process.getInputStream()));
gameOutput.lines().forEachOrdered(this::handleOutputLine);

that is InputStreamStream<String> lines into something with its own interface that the tests can provide an alternate implementation of, one that doesn't require running test input through BufferedReader.

The fear I have about getting rid of StringIteratorInputStream is that maybe those ugly little details like "calling .available() has an invisible side-effect so calling it twice in a row behaves differently than just calling it once" will end up being somehow important as we try to deal with edge cases with subprocesses on our various supported platforms, and then we'll want this InputStream implementation we can use to simulate those cases.

Is that paranoid?

Copy link
Member

@skaldarnar skaldarnar left a comment

Choose a reason for hiding this comment

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

Went through all the files once 💪 😩 - looks good so far, some comments and merge conflicts to resolve, but otherwise we're close to getting this merged!

if ((!valueSet) && START_MATCH.test(line)) {
declareSurvival();
}
logger.info("Game output: {}", line);
Copy link
Member

Choose a reason for hiding this comment

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

Should we log the game's output on INFO level? How complicated is it to still get the launcher logs itself? I image this could be hard to untangle in case somebody really needs to look at the logs... the game does write log files separately anyways, doesn't it?

Copy link
Member Author

Choose a reason for hiding this comment

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

I think the short-term answer for this is that the Launcher tab where you see log output is implemented as a log destination, so if we don't re-log stuff it's not visible there.

*
* @see <a href="https://github.com/TomasMikula/ReactFX/blob/v2.0-M5/reactfx/src/main/java/org/reactfx/util/FxTimer.java">ReactFX</a>
*/
public static final class FxTimer {
Copy link
Member

Choose a reason for hiding this comment

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

As discussed in #586 this may just live in a file on it's own.

* For example:
* <p>
* {@code
* assertThat(Arrays.asList("foo", "bar", "baz"), hasItemsFrom(List.of("baz", "foo")))
Copy link
Member

Choose a reason for hiding this comment

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

I think in the example it would make sense to highlight that this is not about includes but a weaker form. The list on the right might contain elements that are not present on the left side. In other words, the intersection of the lists interpreted as sets is not empty - is my understanding correct?

Suggested change
* assertThat(Arrays.asList("foo", "bar", "baz"), hasItemsFrom(List.of("baz", "foo")))
* assertThat(Arrays.asList("foo", "bar", "baz"), hasItemsFrom(List.of("faz", "foo")))

Comment on lines 35 to 39
return "nope" + new Random()
.ints(16, 0, 255).mapToObj(
i -> Integer.toString(i, Character.MAX_RADIX)
)
.collect(Collectors.joining());
Copy link
Member

Choose a reason for hiding this comment

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

Maybe less custom coding here?

Suggested change
return "nope" + new Random()
.ints(16, 0, 255).mapToObj(
i -> Integer.toString(i, Character.MAX_RADIX)
)
.collect(Collectors.joining());
return "nope-" + UUID.randomUUID().toString();

Copy link
Member Author

Choose a reason for hiding this comment

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

oh, this was just me making up garbage names for testing files? Yeah, sure, UUID is fine.

You get less entropy-per-character in UUID.toString() because it's formatted as base-16 and I think even type-4 UUIDs have at least a couple bits that aren't actually random, but I can't really defend the claim that those details are important to this use case.

String.format("for i in $( seq %s ) ; do echo $i ; sleep 1 ; done", seconds)
);
var proc = pb.start();
LoggerFactory.getLogger(SlowTicker.class).debug(" ⏲ Ticker PID {}", proc.pid());
Copy link
Member

Choose a reason for hiding this comment

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

Yep, I'm pretty sure my Windows complained about these nice little icons.... ⏲

Copy link
Member Author

Choose a reason for hiding this comment

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

Is that what it was! Okay. We should add that character encoding setting to build.gradle if that fixed it.

static final String GAME_DATA_DIR = "game_data";
static final JavaHeapSize HEAP_MIN = JavaHeapSize.NOT_USED;
static final JavaHeapSize HEAP_MAX = JavaHeapSize.GB_4;
static final LogLevel LOG_LEVEL = LogLevel.INFO;
Copy link
Member

Choose a reason for hiding this comment

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

We just removed LogLevel so this has to be adjusted to use slf4j's Level - should be an easy fix.


@Timeout(5)
@ExtendWith(ApplicationExtension.class)
public class TestRunGameTask {
Copy link
Member

Choose a reason for hiding this comment

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

Also not reviewing this in detail. I still think that testing the game log bridging and introducing complex dependency mangling for that is a bit of overkill, but I'm impressed you pulled this off. As talked about earlier, as long as we can keep these tests without too much maintenance effort and investment I'm fine with having them, but I don't want them to become a burden for other projects 🙃

Copy link
Member Author

@keturn keturn Oct 6, 2020

Choose a reason for hiding this comment

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

The dependency-configuration for slf4j testing did turn in to a complete clownshow, yes. I was hoping that by this point in the year, as Java 15 came out and whatnot, we'd see slf4j 2.0 stabilize and then we'd have better options, but... turns out that hoping people you don't know will do the work you want doesn't necessarily get results.

Testing log output seemed important at the time because that was really the only way that code communicated its outputs. That could be something to keep in mind for future iterations: "my slf4j logs in this TextArea" is currently the only user interface to some important information. But as Launcher develops a richer user interface to communicate about its status and troubleshoot failures, it'll also be developing APIs for that information that don't require going through the logger, and we can base tests on those instead.

Copy link
Member Author

Choose a reason for hiding this comment

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

Back to the present, though: I hope someone can confirm that TestRunGameTask is comprehensible, because this is where all the persnickity stuff about process state and inter-thread communication is. If things go wrong, or we discover other edge-cases on other platforms, this is where the work will be.

Copy link
Member

Choose a reason for hiding this comment

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

I can confirm that it looks comprehensible 😉 it's nicely structured, has comments, and so on. I think I should have put more emphasis on "in detail" rather than "not reviewing" somehow 🙃

skaldarnar
skaldarnar previously approved these changes Oct 9, 2020
Copy link
Member

@skaldarnar skaldarnar left a comment

Choose a reason for hiding this comment

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

Will double-check on Windows, but otherwise looks fine!

@lgtm-com
Copy link

lgtm-com bot commented Oct 9, 2020

This pull request introduces 1 alert when merging 6693419 into 24252ec - view on LGTM.com

new alerts:

  • 1 for Potential input resource leak

@lgtm-com
Copy link

lgtm-com bot commented Oct 9, 2020

This pull request introduces 1 alert when merging aa70a8b into 8065ef6 - view on LGTM.com

new alerts:

  • 1 for Potential input resource leak

@skaldarnar skaldarnar merged commit 81b566c into MovingBlocks:master Oct 9, 2020
@skaldarnar
Copy link
Member

skaldarnar commented Oct 9, 2020

gnarf, this introduces a flaky test... may need to revert this (or fix fast to not become a problem/annoying) for other PRs... retriggering seems to help, which is even more confusing 🙈

TestRunGameTask > testSuccessEvent() FAILED
    org.opentest4j.AssertionFailedError at TestRunGameTask.java:238

QuantumRenderer: shutdown
43 tests completed, 1 failed

See https://github.com/MovingBlocks/TerasologyLauncher/pull/592/checks?check_run_id=1235517318 for a CI run with failed test, test report attached as build artifact.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Topic: Documentation Documentation and technical writing. Type: Enhancement New features or noticable improvements.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants