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

8303392: Runtime.exec and ProcessBuilder.start should use System logger #12862

Closed

Conversation

RogerRiggs
Copy link
Contributor

@RogerRiggs RogerRiggs commented Mar 3, 2023

Runtime.exec and ProcessBuilder.start methods create a new operating system process with the program and arguments. Many applications configure a logging subsystem to monitor application events. Logging a process start message with the program, arguments, and stack trace can identify the caller and purpose.
Logging the process start event is complementary to the process start event generated for JFR (Java Flight Recorder).


Progress

  • Change must be properly reviewed (1 review required, with at least 1 Reviewer)
  • Change must not contain extraneous whitespace
  • Change requires CSR request JDK-8303619 to be approved
  • Commit message must refer to an issue

Issues

  • JDK-8303392: Runtime.exec and ProcessBuilder.start should use System logger
  • JDK-8303619: Runtime.exec and ProcessBuilder.start should use System logger (CSR)

Reviewers

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.org/jdk.git pull/12862/head:pull/12862
$ git checkout pull/12862

Update a local copy of the PR:
$ git checkout pull/12862
$ git pull https://git.openjdk.org/jdk.git pull/12862/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 12862

View PR using the GUI difftool:
$ git pr show -t 12862

Using diff file

Download this PR as a diff file:
https://git.openjdk.org/jdk/pull/12862.diff

@bridgekeeper
Copy link

bridgekeeper bot commented Mar 3, 2023

👋 Welcome back rriggs! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

@openjdk openjdk bot added the rfr Pull request is ready for review label Mar 3, 2023
@openjdk
Copy link

openjdk bot commented Mar 3, 2023

@RogerRiggs The following label will be automatically applied to this pull request:

  • core-libs

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing list. If you would like to change these labels, use the /label pull request command.

@openjdk openjdk bot added the core-libs core-libs-dev@openjdk.org label Mar 3, 2023
@mlbridge
Copy link

mlbridge bot commented Mar 3, 2023

@openjdk openjdk bot added the csr Pull request needs approved CSR before integration label Mar 4, 2023
@tstuefe
Copy link
Member

tstuefe commented Mar 5, 2023

Hi Roger,

I think to be even more useful it could make sense to print the current directory the child is started in as well as the env var array, possibly only with a finer logging level.

Cheers, Thomas

Comment on lines 1142 to 1148
} catch (Throwable logEx) {
try {
System.err.println("Logging failed: " + logEx.getMessage() +
", ProcessBuilder.start(): " + Arrays.toString(cmdarray) +
", pid: " + process.pid());
} catch (Throwable thEx) {/* ignore */}
}
Copy link
Member

Choose a reason for hiding this comment

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

Is it really useful to try & catch a potential exception here, or wouldn't be better to let it propagate to the caller? An exception here would indicate a bug somewhere either in the logging backend or in the logging configuration - or possibly OOM or any other kind of VM error and maybe it would be better to just fail in that case, and let the VM exit (unless that exception is caught down the road by the caller?)

I understand why we would not want an exception in logging to prevent System.exit() from exiting, but surely the same constraint doesn't hold for ProcessBuilder::start?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Since adding logging injects additional code during start(), the idea was to handle exceptions to avoid breaking existing code.
And since the logger is cached during the static initialization of the ProcessBuilder class, a mis-configured logger would cause ExceptionInInitializer, exposing the cause early, though in a pretty ugly way. I may need to reconsider that.

@RogerRiggs
Copy link
Contributor Author

I think to be even more useful it could make sense to print the current directory the child is started in as well as the env var array, possibly only with a finer logging level.

There are concerns about exposing potentially sensitive information in exceptions and logs.
And it would need to apply to all process arguments, not just directory and environment.
For example, there is a property "jdk.includeInExceptions" that is used to only include detail information if it is set.
Unless specifically enabled, the information such as host names and file names are not exposed.
Restricting the detail to finer grained logging levels might be the/an answer.

…ging.

Revise the implNote to include a warning about logging security sensistive information.
DEBUG logs only the command, directory, stack trace, and pid.
TRACE additionally logs arguments.
@RogerRiggs
Copy link
Contributor Author

@tstuefe

I think to be even more useful it could make sense to print the current directory the child is started in as well as the env var array, possibly only with a finer logging level.

The environment is potentially bulky and may also contain sensitive information.
It is unlikely to change betwen calls to PB.start() so it doesn't add much to log it.
The logging should focus on the context and arguments of each call.

Copy link
Member

@tstuefe tstuefe left a comment

Choose a reason for hiding this comment

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

LGTM. This looks really useful. We had a similar trace at SAP, a bit more involved (with env vars), and solved a lot of issues quickly with it.

Small nits remain, up to you if you take my suggestions.

private static Stream<Arguments> logParamProvider() {
File nullDirectory = null;
File thisDirectory = new File(".");

Copy link
Member

Choose a reason for hiding this comment

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

I started to heavily use different @test sections with speaking names instead of running a bunch of test in sequence; the advantage is better parallelization of tests, that I can omit printing out the test name manually (if the test name itself is speaking), and the ability to start individual tests manually. It does come with lots of test sections though.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Speakable names can be a plus but I'll stick to the parameterized version for now.
Are you refering to JUnit sections or Jtreg sections?

Copy link
Member

Choose a reason for hiding this comment

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

jtreg sections, as in https://github.com/openjdk/jdk/blob/master/test/hotspot/jtreg/gtest/MetaspaceGtests.java. I find them very practical, I just wish there were a way to condense them.

src/java.base/share/classes/java/lang/ProcessBuilder.java Outdated Show resolved Hide resolved
Cleanup argument lists in tests.
@@ -1264,6 +1298,9 @@ private Process start(Redirect[] redirects) throws IOException {
* @throws UnsupportedOperationException
* If the operating system does not support the creation of processes
*
* @implNote
* Each created process is logged, see {@link ProcessBuilder#start()} for details.
Copy link
Member

Choose a reason for hiding this comment

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

This reads as if it is logged by default. Perhaps reword as "Logging of the created process can be enabled, see ..."

@RogerRiggs
Copy link
Contributor Author

RogerRiggs commented Mar 14, 2023

Please review the CSR: JDK-8303619

@openjdk openjdk bot removed the csr Pull request needs approved CSR before integration label Mar 28, 2023
@openjdk
Copy link

openjdk bot commented Mar 28, 2023

@RogerRiggs This change now passes all automated pre-integration checks.

ℹ️ This project also has non-automated pre-integration requirements. Please see the file CONTRIBUTING.md for details.

After integration, the commit message for the final commit will be:

8303392: Runtime.exec and ProcessBuilder.start should use System logger

Reviewed-by: stuefe, alanb, mullan

You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed.

At the time when this comment was updated there had been 328 new commits pushed to the master branch:

  • e56bcb0: 8305095: Update java/net/httpclient/CustomRequestPublisher.java to use new HttpTestServer factory methods
  • 0985288: 8304681: compiler/sharedstubs/SharedStubToInterpTest.java fails after JDK-8304387
  • ff368d5: 8304867: Explicitly disable dtrace for ppc builds
  • 96fa275: 8305112: RISC-V: Typo fix for RVC description
  • 7239150: 8305094: typo (missing *) in doc comment
  • 3fbbfd1: 8301995: Move invokedynamic resolution information out of ConstantPoolCacheEntry
  • 50a995f: 8304927: Update java/net/httpclient/BasicAuthTest.java to check basic auth over HTTP/2
  • ca745cb: 8291598: Matcher.appendReplacement should not create new StringBuilder instances
  • 1683a63: 8305098: [Backout] JDK-8303912 Clean up JavadocTokenizer
  • fab2357: 8304498: JShell does not switch to raw mode when there is no /bin/test
  • ... and 318 more: https://git.openjdk.org/jdk/compare/379f2061aa4c83388a1becd9661c1ee7b2907830...master

As there are no conflicts, your changes will automatically be rebased on top of these commits when integrating. If you prefer to avoid this automatic rebasing, please check the documentation for the /integrate command for further details.

➡️ To integrate this PR with the above commit message to the master branch, type /integrate in a new comment.

@openjdk openjdk bot added the ready Pull request is ready to be integrated label Mar 28, 2023
of the logging as recommended by the CSR review.
@RogerRiggs
Copy link
Contributor Author

/integrate

@openjdk
Copy link

openjdk bot commented Mar 29, 2023

Going to push as commit d063b89.
Since your change was applied there have been 336 commits pushed to the master branch:

Your commit was automatically rebased without conflicts.

@openjdk openjdk bot added the integrated Pull request has been integrated label Mar 29, 2023
@openjdk openjdk bot closed this Mar 29, 2023
@openjdk openjdk bot removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels Mar 29, 2023
@openjdk
Copy link

openjdk bot commented Mar 29, 2023

@RogerRiggs Pushed as commit d063b89.

💡 You may see a message that your pull request was closed with unmerged commits. This can be safely ignored.

@RogerRiggs RogerRiggs deleted the 8303392-processbuilder-log branch December 11, 2023 17:25
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
core-libs core-libs-dev@openjdk.org integrated Pull request has been integrated
5 participants