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

8271003: hs_err improvement: handle CLASSPATH env setting longer than O_BUFLEN #4947

Closed

Conversation

calvinccheung
Copy link
Member

@calvinccheung calvinccheung commented Jul 30, 2021

Please review this small enhancement for addressing the problem of the CLASSPATH env variable setting being truncated in a hs err log.

For printing a char string, it doesn't need to go through do_vsnprintf() which does the truncation based on the input buffer length. The change is local to the code path pertaining to hs err log.

Testing:

  • tiers 1, 2 (including the new test)

Progress

  • Change must not contain extraneous whitespace
  • Commit message must refer to an issue
  • Change must be properly reviewed

Issue

  • JDK-8271003: hs_err improvement: handle CLASSPATH env setting longer than O_BUFLEN

Reviewers

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.java.net/jdk pull/4947/head:pull/4947
$ git checkout pull/4947

Update a local copy of the PR:
$ git checkout pull/4947
$ git pull https://git.openjdk.java.net/jdk pull/4947/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 4947

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

Using diff file

Download this PR as a diff file:
https://git.openjdk.java.net/jdk/pull/4947.diff

@calvinccheung
Copy link
Member Author

/label add hotspot-runtime

@calvinccheung calvinccheung marked this pull request as ready for review July 30, 2021 18:23
@bridgekeeper
Copy link

bridgekeeper bot commented Jul 30, 2021

👋 Welcome back ccheung! 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 hotspot-runtime hotspot-runtime-dev@openjdk.org label Jul 30, 2021
@openjdk
Copy link

openjdk bot commented Jul 30, 2021

@calvinccheung
The hotspot-runtime label was successfully added.

@openjdk openjdk bot added the rfr Pull request is ready for review label Jul 30, 2021
@mlbridge
Copy link

mlbridge bot commented Jul 30, 2021

Webrevs

Copy link
Member

@dholmes-ora dholmes-ora left a comment

Choose a reason for hiding this comment

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

Hi Calvin,

Not sure about this ... still thinking.

In the meantime see couple of comments below.

Thanks,
David

// constant format string
str = format;
len = strlen(str);
} else if (format[0] == '%' && format[1] == 's' && format[2] == '\0') {
Copy link
Member

Choose a reason for hiding this comment

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

Why are you assuming the %s must be at the beginning rather than "blah blah %s blah" ?

Copy link
Member

Choose a reason for hiding this comment

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

Ah I see what you are doing now - the code just special cases the two cases of a string with no format specifiers, and a string that is only "%s". Anything else needs full handling.

private static final String cp_env = "CLASSPATH";
private static final String end_path = "end-path";

private static class Crasher {
Copy link
Member

Choose a reason for hiding this comment

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

Can't you just use one of the existing -XX:ErrorHandlerTest=n values to trigger the crash?

Copy link
Member Author

Choose a reason for hiding this comment

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

Yes, using -XX:ErrorHandlerTest=1 should trigger the crash. I was just reusing the Crasher from another test case.

@dholmes-ora
Copy link
Member

outputStream::do_vsnprintf already states that it uses the buffer "if necessary". In the two highlighted cases there is no need to use the buffer, so I would argue that we should just modify the existing outputStream::do_vsnprintf logic to not truncate in these two cases as it is not necessary.

David

@tstuefe
Copy link
Member

tstuefe commented Aug 2, 2021

outputStream::do_vsnprintf already states that it uses the buffer "if necessary". In the two highlighted cases there is no need to use the buffer, so I would argue that we should just modify the existing outputStream::do_vsnprintf logic to not truncate in these two cases as it is not necessary.

I think we already do almost that.

if (!strchr(format, '%')) {
// constant format string
result = format;
result_len = strlen(result);
if (add_cr && result_len >= buflen) result_len = buflen-1; // truncate
} else if (format[0] == '%' && format[1] == 's' && format[2] == '\0') {
// trivial copy-through format string
result = va_arg(ap, const char*);
result_len = strlen(result);
if (add_cr && result_len >= buflen) result_len = buflen-1; // truncate
} else {

Only thing, for print_cr() we still use the scratch buffer since we need to append \n. That could be done smarter.

Beyond that, I think the O_BUFLEN thing is seriously annoying and I would like to have a better solution. One where we start with a preallocated buffer as we do now, but expand it dynamically (using raw ::malloc()) if necessary. That should still be reasonably safe.

@calvinccheung
Copy link
Member Author

outputStream::do_vsnprintf already states that it uses the buffer "if necessary". In the two highlighted cases there is no need to use the buffer, so I would argue that we should just modify the existing outputStream::do_vsnprintf logic to not truncate in these two cases as it is not necessary.

David

I was thinking of changing outputStream::do_vsnprintf to make use of the handle_simple_format() as a separate RFE.

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.

Hi Calvin,

Sorry, I think we cannot do it the way you propose.

The problem is that the print_cr() functions are supposed to write the newline with the same write(2) call. That is not documented in do_vsnprintf(), it's an easy to miss a detail.

Writing with one single write(2) call guarantees some atomicity when writing concurrently from several threads. If you write the newline separately, you risk line tear - the newline appearing away from its line.

This means that print_cr("%s", s) should not write the newline separately and therefore would not benefit from your improvement. And print("%s", s) would already do exactly what you propose, since in do_vsnprintf() we already handle the two special cases.

I propose a specific fix for your problem in os::print_environment_variables() by replacing st->print_cr("%s", envvar); with either one of

st->print("%s", envvar);
st->cr()

or

st->print_raw(envvar);
st->cr()

The test is useful though. But you can simplify it:

  • as David said, use -XX:ErrorHandlerTest. For better realistic testing, I'd use an option which gives you a real signal, e.g. -XX:ErrorHandlerTest=14
  • just start the test with -XX:+ErrorFileToStdout. We added this option to pipe the error file to stdout. That way you can parse stdout directly, using OutputScanner methods and regex, no need to open and parse the hs-err file:
thomas@starfish$ CLASSPATH=abcabc ./images/jdk/bin/java -XX:ErrorHandlerTest=14 -XX:+ErrorFileToStdout | grep CLASSPATH
CLASSPATH=abcabc

Cheers, Thomas

@calvinccheung
Copy link
Member Author

Hi Thomas,

Thanks for your review.

Hi Calvin,

Sorry, I think we cannot do it the way you propose.

The problem is that the print_cr() functions are supposed to write the newline with the same write(2) call. That is not documented in do_vsnprintf(), it's an easy to miss a detail.

Writing with one single write(2) call guarantees some atomicity when writing concurrently from several threads. If you write the newline separately, you risk line tear - the newline appearing away from its line.

This means that print_cr("%s", s) should not write the newline separately and therefore would not benefit from your improvement. And print("%s", s) would already do exactly what you propose, since in do_vsnprintf() we already handle the two special cases.

I propose a specific fix for your problem in os::print_environment_variables() by replacing st->print_cr("%s", envvar); with either one of

st->print("%s", envvar);
st->cr()

I picked the above since it is more consistent with another st->print() in the same loop.

or

st->print_raw(envvar);
st->cr()

The test is useful though. But you can simplify it:

  • as David said, use -XX:ErrorHandlerTest. For better realistic testing, I'd use an option which gives you a real signal, e.g. -XX:ErrorHandlerTest=14
  • just start the test with -XX:+ErrorFileToStdout. We added this option to pipe the error file to stdout. That way you can parse stdout directly, using OutputScanner methods and regex, no need to open and parse the hs-err file:

I've updated the test and using OutputAnalyzer.firstMatch() to parse the stdout.

Thanks,
Calvin

thomas@starfish$ CLASSPATH=abcabc ./images/jdk/bin/java -XX:ErrorHandlerTest=14 -XX:+ErrorFileToStdout | grep CLASSPATH
CLASSPATH=abcabc


Cheers, Thomas

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.

Looks good, Calvin. Your more general approach would have been nice, but thanks for considering my log tearing worries and for taking my suggestion.

Cheers, Thomas

@openjdk
Copy link

openjdk bot commented Aug 3, 2021

@calvinccheung 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:

8271003: hs_err improvement: handle CLASSPATH env setting longer than O_BUFLEN

Reviewed-by: dholmes, stuefe, iklam, minqi

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 39 new commits pushed to the master branch:

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 Aug 3, 2021
Copy link
Member

@iklam iklam left a comment

Choose a reason for hiding this comment

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

LGTM

Copy link
Contributor

@yminqi yminqi left a comment

Choose a reason for hiding this comment

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

LGTM.

Copy link
Member

@dholmes-ora dholmes-ora left a comment

Choose a reason for hiding this comment

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

Looks good.

One comment request.

Thanks,
David

@@ -989,7 +989,8 @@ void os::print_environment_variables(outputStream* st, const char** env_list) {
if (envvar != NULL) {
st->print("%s", env_list[i]);
st->print("=");
st->print_cr("%s", envvar);
st->print("%s", envvar);
Copy link
Member

Choose a reason for hiding this comment

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

I suggest adding a comment like:
// Use separate cr() printing to avoid unnecessary buffer operations that might cause truncation

Copy link
Member Author

Choose a reason for hiding this comment

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

Thanks for taking another look.
I've added the comment.

@calvinccheung
Copy link
Member Author

@dholmes-ora, @tstuefe, @iklam, @yminqi Thanks for the review.

@calvinccheung
Copy link
Member Author

/integrate

@openjdk
Copy link

openjdk bot commented Aug 4, 2021

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

Your commit was automatically rebased without conflicts.

@openjdk openjdk bot closed this Aug 4, 2021
@openjdk openjdk bot added integrated Pull request has been integrated and removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels Aug 4, 2021
@openjdk
Copy link

openjdk bot commented Aug 4, 2021

@calvinccheung Pushed as commit 3435d29.

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

@calvinccheung calvinccheung deleted the 8271003-hs-err-CLASSPATH branch August 4, 2021 01:47
@mlbridge
Copy link

mlbridge bot commented Sep 1, 2021

Mailing list message from David Holmes on hotspot-runtime-dev:

On 2/08/2021 6:26 pm, Thomas Stuefe wrote:

On Mon, 2 Aug 2021 07:02:35 GMT, David Holmes <dholmes at openjdk.org> wrote:

`outputStream::do_vsnprintf` already states that it uses the buffer "if necessary". In the two highlighted cases there is no need to use the buffer, so I would argue that we should just modify the existing `outputStream::do_vsnprintf` logic to not truncate in these two cases as it is not necessary.

I think we already do almost that.

https://github.com/openjdk/jdk/blob/95f0fd6c4dfaea9c3e065485dd201decf2be98ba/src/hotspot/share/utilities/ostream.cpp#L94-L104

Only thing, for print_cr() we still use the scratch buffer since we need to append \n. That could be done smarter.

Right I missed that bit - but I guess we can do that as a separate
write() call.

Beyond that, I think the O_BUFLEN thing is seriously annoying and I would like to have a better solution. One where we start with a preallocated buffer as we do now, but expand it dynamically (using raw ::malloc()) if necessary. That should still be reasonably safe.

Raw malloc in the error handler is not safe if we're processing a
signal. The malloc/signal deadlock is already seen with some of our
abort tests.

Cheers,
David

@mlbridge
Copy link

mlbridge bot commented Sep 1, 2021

Mailing list message from Thomas Stüfe on hotspot-runtime-dev:

On Mon, Aug 2, 2021 at 11:59 AM David Holmes <david.holmes at oracle.com>
wrote:

On 2/08/2021 6:26 pm, Thomas Stuefe wrote:

On Mon, 2 Aug 2021 07:02:35 GMT, David Holmes <dholmes at openjdk.org>
wrote:

`outputStream::do_vsnprintf` already states that it uses the buffer "if
necessary". In the two highlighted cases there is no need to use the
buffer, so I would argue that we should just modify the existing
`outputStream::do_vsnprintf` logic to not truncate in these two cases as it
is not necessary.

I think we already do almost that.

https://github.com/openjdk/jdk/blob/95f0fd6c4dfaea9c3e065485dd201decf2be98ba/src/hotspot/share/utilities/ostream.cpp#L94-L104

Only thing, for print_cr() we still use the scratch buffer since we need
to append \n. That could be done smarter.

Right I missed that bit - but I guess we can do that as a separate
write() call.

Beyond that, I think the O_BUFLEN thing is seriously annoying and I
would like to have a better solution. One where we start with a
preallocated buffer as we do now, but expand it dynamically (using raw
::malloc()) if necessary. That should still be reasonably safe.

Raw malloc in the error handler is not safe if we're processing a
signal. The malloc/signal deadlock is already seen with some of our
abort tests.

I thought it would be a calculated risk. You only run into problems if
1) the output length is longer than the default static buffer, and we
allocate dynamically
2) we crash recursively in malloc or the C-heap is corrupted

Cheers, Thomas

Cheers,
David

@mlbridge
Copy link

mlbridge bot commented Sep 1, 2021

Mailing list message from David Holmes on hotspot-runtime-dev:

On 3/08/2021 3:40 am, Calvin Cheung wrote:

On Mon, 2 Aug 2021 07:02:35 GMT, David Holmes <dholmes at openjdk.org> wrote:

`outputStream::do_vsnprintf` already states that it uses the buffer "if necessary". In the two highlighted cases there is no need to use the buffer, so I would argue that we should just modify the existing `outputStream::do_vsnprintf` logic to not truncate in these two cases as it is not necessary.

David

I was thinking of changing `outputStream::do_vsnprintf` to make use of the `handle_simple_format()` as a separate RFE.

Sorry Calvin but I'd rather see a single complete solution in one step.

IIUC the only time we have a problem with truncation is when we have
add_cr==true. So it seems to me that a simple solution for this is to
not handle the cr in those low-level routine at all but simply change:

void outputStream::vprint_cr(const char* format, va_list argptr) {
do_vsnprintf_and_write(format, argptr, true);
}

to

void outputStream::vprint_cr(const char* format, va_list argptr) {
do_vsnprintf_and_write(format, argptr);
cr();
}

or add the "add_cr" to the write() method and let it handle it without a
need for intermediate buffering.

Thanks,
David

@mlbridge
Copy link

mlbridge bot commented Sep 1, 2021

Mailing list message from Thomas Stüfe on hotspot-runtime-dev:

On Tue, Aug 3, 2021 at 12:53 AM David Holmes <david.holmes at oracle.com>
wrote:

On 3/08/2021 3:40 am, Calvin Cheung wrote:

On Mon, 2 Aug 2021 07:02:35 GMT, David Holmes <dholmes at openjdk.org>
wrote:

`outputStream::do_vsnprintf` already states that it uses the buffer "if
necessary". In the two highlighted cases there is no need to use the
buffer, so I would argue that we should just modify the existing
`outputStream::do_vsnprintf` logic to not truncate in these two cases as it
is not necessary.

David

I was thinking of changing `outputStream::do_vsnprintf` to make use of
the `handle_simple_format()` as a separate RFE.

Sorry Calvin but I'd rather see a single complete solution in one step.

IIUC the only time we have a problem with truncation is when we have
add_cr==true. So it seems to me that a simple solution for this is to
not handle the cr in those low-level routine at all but simply change:

void outputStream::vprint_cr(const char* format, va_list argptr) {
do_vsnprintf_and_write(format, argptr, true);
}

to

void outputStream::vprint_cr(const char* format, va_list argptr) {
do_vsnprintf_and_write(format, argptr);
cr();
}

or add the "add_cr" to the write() method and let it handle it without a
need for intermediate buffering.

Thanks,
David

Missed your mail since the duplication of ML mails into github
conversations still does not work :(

See my answer to Calvin, I think we want to write the output with a single
call to write(2) to reduce tear. That includes the newline. I think
including it in write(2) was intentional.

..Thomas

@mlbridge
Copy link

mlbridge bot commented Sep 1, 2021

Mailing list message from David Holmes on hotspot-runtime-dev:

Hi Thomas,

On 3/08/2021 2:00 pm, Thomas Stuefe wrote:

On Fri, 30 Jul 2021 18:17:54 GMT, Calvin Cheung <ccheung at openjdk.org> wrote:

Please review this small enhancement for addressing the problem of the CLASSPATH env variable setting being truncated in a hs err log.

For printing a char string, it doesn't need to go through `do_vsnprintf()` which does the truncation based on the input buffer length. The change is local to the code path pertaining to hs err log.

Testing:

- [x] tiers 1, 2 (including the new test)

Hi Calvin,

Sorry, I think your patch is not a good solution.

The problem is that the print_cr() functions are supposed to write the newline *with the same `write(2)` call*. That is not documented in do_vsnprintf(), but maybe we should do that since its an easy to miss a detail.

Writing with one single `write(2)` call guarantees some atomicity when writing concurrently from several threads. If you write the newline separately, you risk line tear - the newline appearing away from its line.

Do we really rely on the write(2) call for atomicity? The defaultStream
uses a lock and we could pass `add_cr` through to defaultStream::write
so that the cr is added under the lock.

Cheers,
David
-----

@mlbridge
Copy link

mlbridge bot commented Sep 1, 2021

Mailing list message from Thomas Stüfe on hotspot-runtime-dev:

Hi David,

The problem is that the print_cr() functions are supposed to write the
newline *with the same `write(2)` call*. That is not documented in
do_vsnprintf(), but maybe we should do that since its an easy to miss a
detail.

Writing with one single `write(2)` call guarantees some atomicity when
writing concurrently from several threads. If you write the newline
separately, you risk line tear - the newline appearing away from its line.

Do we really rely on the write(2) call for atomicity? The defaultStream
uses a lock and we could pass `add_cr` through to defaultStream::write
so that the cr is added under the lock.

That would only work for the defaultStream, no? What about other streams?

Cheers,

David

..Thomas

@mlbridge
Copy link

mlbridge bot commented Sep 1, 2021

Mailing list message from David Holmes on hotspot-runtime-dev:

On 3/08/2021 2:38 pm, Thomas St?fe wrote:

Hi David,
>
> The problem is that the print_cr() functions are supposed to
write the newline *with the same `write(2)` call*. That is not
documented in do_vsnprintf(), but maybe we should do that since its
an easy to miss a detail.
>
> Writing with one single `write(2)` call guarantees some atomicity
when writing concurrently from several threads. If you write the
newline separately, you risk line tear - the newline appearing away
from its line.

Do we really rely on the write\(2\) call for atomicity\? The defaultStream
uses a lock and we could pass \`add\_cr\` through to defaultStream\:\:write
so that the cr is added under the lock\.

That would only work for the defaultStream, no? What about other streams?

Do the other streams have atomicity in the first place? It's not an
issue for stringStream as they aren't shared.

David

Cheers\,
David

..Thomas

@mlbridge
Copy link

mlbridge bot commented Sep 1, 2021

Mailing list message from Thomas Stüfe on hotspot-runtime-dev:

On Tue, Aug 3, 2021 at 7:32 AM David Holmes <david.holmes at oracle.com> wrote:

On 3/08/2021 2:38 pm, Thomas St?fe wrote:

Hi David,
>
> The problem is that the print_cr() functions are supposed to
write the newline *with the same `write(2)` call*. That is not
documented in do_vsnprintf(), but maybe we should do that since its
an easy to miss a detail.
>
> Writing with one single `write(2)` call guarantees some atomicity
when writing concurrently from several threads. If you write the
newline separately, you risk line tear - the newline appearing away
from its line.

Do we really rely on the write\(2\) call for atomicity\? The

defaultStream

uses a lock and we could pass \`add\_cr\` through to

defaultStream::write

so that the cr is added under the lock\.

That would only work for the defaultStream, no? What about other streams?

Do the other streams have atomicity in the first place? It's not an
issue for stringStream as they aren't shared.

David

We have fdStream and fileStream. Both are calling write(2) resp. fwrite(3)
directly. Yes, separate print invocations are not guaranteed to be atomic,
but today at least individual print_cr() calls are.

..Thomas

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
hotspot-runtime hotspot-runtime-dev@openjdk.org integrated Pull request has been integrated
5 participants