jdk
jdk copied to clipboard
openjdk
JDK-8292351: tty should always live
The default stream object tty is used in many places but its lifetime is limited. It gets born not-quite at the beginning of VM initialization and dies in DestroyVM. This leaves time windows before VM initialization and after VM cleanup where logging to tty crashes.
This has been bugging me in the past, especially when wanting to use tty in code that runs very early (NMT preinit system, for example), and also causes problems for code that runs post-cleanup. Mostly this affects logging and error logging.
tty should always be safe to write to, and that is trivial to do.
Progress
- [ ] Change must be properly reviewed (1 review required, with at least 1 Reviewer)
- [x] Change must not contain extraneous whitespace
- [x] Commit message must refer to an issue
Issue
- JDK-8292351: tty should always live
Reviewing
Using git
Checkout this PR locally:
$ git fetch https://git.openjdk.org/jdk pull/9874/head:pull/9874
$ git checkout pull/9874
Update a local copy of the PR:
$ git checkout pull/9874
$ git pull https://git.openjdk.org/jdk pull/9874/head
Using Skara CLI tools
Checkout this PR locally:
$ git pr checkout 9874
View PR using the GUI difftool:
$ git pr show -t 9874
Using diff file
Download this PR as a diff file:
https://git.openjdk.org/jdk/pull/9874.diff
:wave: Welcome back stuefe! 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.
![bridgekeeper[bot] avatar](https://avatars.githubusercontent.com/u/41768318?v=4 "Published by a pub.dev verified publisher"){kind=small}
@tstuefe The following label will be automatically applied to this pull request:
-
hotspot
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.
Webrevs
- 05: Full - Incremental (5c1f4caf)
- 04: Full - Incremental (9d6a9082)
- 03: Full - Incremental (f119efc6)
- 02: Full - Incremental (83359b4e)
- 01: Full - Incremental (30bf40f8)
- 00: Full (1dda2102)
So effectively this just introduces an alternate tty device for pre-init and post-shutdown. But if the tty is not stdout then you are now forcing use of stdout in an environment where someone may have taken steps to ensure stdout is not in fact used. Is that real concern? I don't know. We jump through a number of hoops in terms of controlling VM output and it seems somewhat excessive to me, but I have to assume there were valid reasons for the level of complexity that it exists.
Need to think more about this ...
So effectively this just introduces an alternate tty device for pre-init and post-shutdown. But if the tty is not stdout then you are now forcing use of stdout in an environment where someone may have taken steps to ensure stdout is not in fact used.
I don't force using stdout. I prevent the VM from crashing. Before my patch, the VM would have crashed. Now it prints the message it wanted to print, to stdout, which is in 99 % of all cases what users expect anyway since it's the default behavior.
Is that real concern?
Yes. So much that in our downstream VMs I have stopped using tty and instead use fdStream(1) or (2) as much as possible, unless I am absolutely sure that tty is valid whenever my code runs. But this is a style I cannot use in OpenJDK since the rule is "use tty".
I don't know. We jump through a number of hoops in terms of controlling VM output and it seems somewhat excessive to me, but I have to assume there were valid reasons for the level of complexity that it exists.
I don't particularly like defaultStream, especially its XML mode, and would be happy if it were simplified.
Need to think more about this ...
The goal should be to replace tty with UL in as many cases as possible. So to me this change is great, because in the far future we can reduce tty to only this in those rare cases where UL isn't available yet.
I don't force using stdout. I prevent the VM from crashing.
Yes by forcing the use of stdout. There are users who go to great lengths to ensure nothing from the VM appears on stdout and this change would allow for such output with no way at all for the user to control it.
Is that real concern? Yes.
My question was not directed to the PR issue but to my own comment about now forcing use of stdout when users have taken steps to prevent that, and whether this is really a concern. And I think the answer in the past has been yes - as I said there have been customers who have insisted on nothing from the VM being written to stdout.
The goal should be to replace tty with UL
UL has the same problems. UL is configured by argument parsing, so prior to that you can't log. And at some point UL is shutdown, and after that you can't log either.
There is no nice solution for the initialization problem. But for termination it should be possible to defer the tty/stream cleanup to an even later point (similarly for UL).
I don't force using stdout. I prevent the VM from crashing.
Yes by forcing the use of stdout. There are users who go to great lengths to ensure nothing from the VM appears on stdout and this change would allow for such output with no way at all for the user to control it.
Is that real concern? Yes.
My question was not directed to the PR issue but to my own comment about now forcing use of stdout when users have taken steps to prevent that, and whether this is really a concern. And I think the answer in the past has been yes - as I said there have been customers who have insisted on nothing from the VM being written to stdout.
I'm equally fine with using stderr, which would have been my preference. I only chose stdout to keep with the standard behavior of VM output.
Would it be possible to redirect to some dummy file instead of stdout? I mean if it is just to avoid crashes and nobody cares about lost logs?
Would it be possible to redirect to some dummy file instead of stdout? I mean if it is just to avoid crashes and nobody cares about lost logs?
Unfortunately, that does not help.
We very much want to see the output (see e.g. Discussion https://mail.openjdk.org/pipermail/hotspot-runtime-dev/2022-August/056826.html, where NMT detected a heap corruption but was unable to print out a meaningful report since tty was NULL and it crashed).
And people could object to random files popping up as well. Where would you write them?
No, the more I think about this the more I am convinced that printing to stderr is the right thing to do. That is what, for instance, the C-Runtime does if it detects a stack corruption. It is the typical Unix way too, so it does not violate the principle of least surprise.
The goal should be to replace tty with UL
UL has the same problems. UL is configured by argument parsing, so prior to that you can't log. And at some point UL is shutdown, and after that you can't log either.
UL has even more problems. You also cannot use it in signal handlers, and not in subsystems that UL itself uses unless you are really sure you know what you do. For instance, anything below os::malloc cannot use UL (including NMT).
In my eyes, UL is a bit too complex and uses too much VM infrastructure for it to be a use-everywhere logging system. If you use it, you have to think if it is okay. And if people want to expand it, you have to take a lot of care in PR discussions (remember the "lets trace over network" ideas).
I would love to have some sort of automatic mechanism for locally forbidding UL use. Similar to a NoHandleMark. Like a NoULMark. That way we could at least guard code sections that should not use UL, or that UL should not use.
If it were only the argument parsing problem, if UL had no dependencies into the rest of the VM, we could solve that by finding an alternate way to pass logging arguments. E.g. via environment variables. But you would have to move UL initialization up the initialization order, possibly into the C++ dynamic initialization phase, and I'm sure that would not work.
There is no nice solution for the initialization problem. But for termination it should be possible to defer the tty/stream cleanup to an even later point (similarly for UL).
I agree with that. I did not pursue this for tty in this patch since I did not want to make the patch more complex than it is, and easily down-portable.
One problem with UL is that it relies, I believe, on VM infrastructure. At least os::malloc and Thread::current, last time I looked. Not sure if it has more dependencies now. Prolonging UL life may therefore more difficult than just removing it from cleanup.
The goal should be to replace tty with UL
UL has the same problems. UL is configured by argument parsing, so prior to that you can't log. And at some point UL is shutdown, and after that you can't log either.
UL has even more problems. You also cannot use it in signal handlers, and not in subsystems that UL itself uses unless you are really sure you know what you do. For instance, anything below os::malloc cannot use UL (including NMT).
To be clear, I said:
The goal should be to replace tty with UL in as many cases as possible.
In other words, tty should be used when UL cannot be used. Therefore this change is good, because it makes tty viable in more places where UL is not viable.
@tstuefe 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:
8292351: tty should always live
Reviewed-by: clanger, coleenp, dholmes
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 102 new commits pushed to the master branch:
- 4da1745836550224306ca66201c35a5baaf30953: 8291118: [vectorapi] Optimize the implementation of lanewise FIRST_NONZERO
- 38a81913d33c856d64b7c26f934026815a482e43: 8290322: Optimize Vector.rearrange over byte vectors for AVX512BW targets.
- 27af0144ea57e86d9b81c2b328fad66e4a046f61: 8292743: Missing include resourceHash.hpp
- f58aaab4a40f09be03d77a8df8dfefa94e47b320: 8292262: adjust timeouts in several M&M tests
- ab6988599cded028ebfc4c958bc9e88d1b365ad7: 8292215: java/util/stream/boottest/java.base/java/util/stream/SpinedBufferTest.java times out with slowdebug
- 54843b700a463e75cd23a23df8ec5dc73b80f105: 8290211: jdk/internal/vm/Continuation/Fuzz.java failed with "AssertionError: Failed to compile int Fuzz.com_int(int,int) in 5000ms"
- 8a0c3e53d541395ac32d656ac64d20ca0b9a187c: 8292261: adjust timeouts in JLI GetObjectSizeIntrinsicsTest.java
- 8e8ee4b6f22657a7efba8d7998f3c309f334a086: 8292596: Make SymbolHashMap a ResourceHashtable
- aa9b8f04bf74d5fa00f2b27895e7369abea3a930: 8292043: Incorrect decoding near EOF for stateful decoders like UTF-16
- f95ee7960328410551a6948053d1ff0ec3d8c53d: 8292566: Add reference to the java.nio.file package in java.nio package documentation
- ... and 92 more: https://git.openjdk.org/jdk/compare/e89abb7d2d902c6e6b3c9953fc6663de10db77b9...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.
I only chose stdout to keep with the standard behavior of VM output.
And therein lies the problem of using stderr. How is this going to work with the flags that switch the VM output between stdout and stderr? Will it make any sense? And how it it going to be when the pre-init output goes to stderr, the regular goes to stdout, and then the termination goes to stderr again?
Really you are introducing a new logging destination only used pre-init and post-termination, but pretending it is the regular "tty" output when it isn't.
I think the better solution is to expand the usability window of the tty by deferring its shutdown as long as possible. There should be minimal stuff happening before argument processing so not really anything to "log" at that time.
I only chose stdout to keep with the standard behavior of VM output.
And therein lies the problem of using stderr. How is this going to work with the flags that switch the VM output between stdout and stderr? Will it make any sense? And how it it going to be when the pre-init output goes to stderr, the regular goes to stdout, and then the termination goes to stderr again?
Really you are introducing a new logging destination only used pre-init and post-termination, but pretending it is the regular "tty" output when it isn't.
Yes. Because that is still better than what we do now. We crash. Before VM init, depending on whether a signal handler is active (custom launchers) with more or less fanfare. In the standard java launcher accessing tty before VM init leads to a single taciturn "Code dumped", which will go to stderr. Or directly to tty, depending on the system.
VMs that crash without a trace are a plague, especially in cloud scenarios where you have little to none diagnostic possibilities.
Printing to stderr is better than crashing. It is the expected behavior. It is what the C-Runtime and other system libraries do when encountering errors. If we corrupt the stack, for instance.
I cannot think of a single scenario where a vanishing or core-ing JVM is better than one that prints its message to stderr.
And yes, I create a second "tty", since that allows us to use the same stream object all over the VM while being oblivious about the Life stage the VM is in. The alternative would be to create a second tty, "tty_safe" or similar, and sprinkle conditional coding all over the code base. That is not feasible, apart from being hideous.
I think the better solution is to expand the usability window of the tty by deferring its shutdown as long as possible.
There should be minimal stuff happening before argument processing so not really anything to "log" at that time.
Plain not true. At least not for me, otherwise I would not have bothered with this RFR. I know that I have been in situations where I needed tty and did not use it since it was not yet initialized. NMT preinit system is just one example.
The problem I have with extending tty's life to beyond VM destruction is that tty is defaultStream and defaultStream is not simple. Just look at defaultStream.write, I find it not easy to decide whether all of this is safe (e.g. using tty_lock) after the VM shut down. Then, you want the destructor of defaultStream to run during VM destruction, since we want the flush.
After VM destruction, I want simple unbuffered IO for any subsequent messages. Keep it simple and stupid.
If you think using stderr is such a problem for unplanned tty output, then we could just assign tty either 1 or 2 depending on the arguments that are now, at the end of VM life, available.
After looking at VMError::report_and_die, I see we redirect error output in case of a crash to hard-wired stdout, we don't use tty. Before this patch, if we accessed tty after VM destruction, we would have printed an error report to stdout. Therefore my initial patch, using stdout hard-wired, was correct and would not have broken compatibility. The only difference would have been that instead of writing a useless "SIGSEGV" crash report to stdout we would have written a useful message to stdout.
(I'm spending way to much time on this)
Here is the compatibility situation wrt tty=NULL before and after my patch.
-
Writing to tty before VM initialization:
- Before patch:
- Standard java launcher: results in a core dump. More or less silent VM death. We may see "Segmentation Fault" if parent process is a shell, on the shell's stderr; text may work its way via the shell's stderr stream into log files.
- If custom launcher, and custom launcher installed its own signal handlers, the SIGSEGV will be catched by that handler. All bets are open. But most handlers I have seen just abort the VM on SIGSEGV, finger-pointing to the "broken" Java VM.
- After patch: We see the message the calling code intended to send on stderr.
- Before patch:
-
Writing to tty after VM cleanup
- Before the patch: Will result in an error report written to stdout (not tty), and a hs-err file. The hs-err file will be broken in many places by secondary crashes since error handling also uses tty and does not check if it is valid. Highly likely we will exceed the max. number of secondary crashes and just abort the error handling.
- After the patch: We see the message the calling code intended to send on stderr.
Hi Thomas,
Yes this is consuming too much of our time - sorry about that but this does need to be aired. The compatibility issue is not "crash versus no crash", the issue is the ability to add new early/late logging that goes to a fixed destination that the user cannot control and which the existing control flags will not affect. Such logging should be extremely rare (as it by-passes the normal control mechanisms) so making it highly visible in the source code, e.g. by using tty_safe, may not be a bad thing. Code that runs during init, especially very early init, and during termination, is already special code. It has to be independent of all VM services that have not yet started, or may have already terminated. We have often been bitten by code that runs in a context the author had not expected or intended (especially static initializers and destructors) with implicit dependencies that only get exposed when another bug arises (as per the mallocTracker issue).
I agree there are issues with determining how far out you can push the stream destruction in the termination process but I still think it may be worth looking into in the context of the current failure. I also note that your code doesn't (and can't?) account for the possibility of races on the use of the tty during termination, so it is still not completely safe.
Early VM init could be considered as a separate issue. Really it is only things like NMT that have issues here because you want it enabled (potentially from the initial load of libjvm) but can't use any VM services at that time. We obviously need to have a backup plan for error/crash reporting (as all bets are off by then anyway!), but early logging should be a special case - how do you even turn it on when argument processing has not yet happened? Do we still have that hack to directly read a special environment variable for NMT?
So, sorry, but I don't see this as a simple "slam-dunk" issue. But at the end of the day I can only voice my concerns. If other's think this is okay and approve it then so be it.
Hi David,
Hi Thomas,
Yes this is consuming too much of our time - sorry about that but this does need to be aired.
Sorry for seeming impatient. If there are differences, we have to understand the needs of all and find a good compromise.
My experiences may differ from yours since my work revolve(d) a lot around the fringes of the VM - porting, app integration, observability - and in those areas you find yourself often outside the VM life span.
The compatibility issue is not "crash versus no crash"; the issue is the ability to add new early/late logging that goes to a fixed destination that the user cannot control and which the existing control flags will not affect. Such logging should be extremely rare (as it bypasses the normal control mechanisms) so making it highly visible in the source code, e.g. by using tty_safe, may not be a bad thing. Code that runs during init, especially very early init, and during termination, is already a special code. It has to be independent of all VM services that have not yet started or may have already terminated. We have often been bitten by code that runs in a context the author had not expected or intended (especially static initializers and destructors) with implicit dependencies that only get exposed when another bug arises (as per the mallocTracker issue).
I think the difference between us is what we consider worse. For us, vanishing VMs are really bad since we usually have no or no easy access to the situation, and log files are our only tool. That is why we were so intent on hardening out error reporting.
So I usually consider any output important and like to see it. That said, I can see that unimportant tty output getting stuck in the middle of log files can cause grief since parsers would get thrown off. We also have experienced that.
I agree there are issues with determining how far out you can push the stream destruction in the termination process but I still think it may be worth looking into in the context of the current failure. I also note that your code doesn't (and can't?) account for the possibility of races on the use of the tty during termination, so it is still not completely safe.
We can look into extending the lifespan of defaultStream, but before that, I'd like to check if this is even needed. defaultStream is surprisingly complex - it inherits from xmlStream for some reason and seems to have ties to the compiler, etc. I'm also worried about bitrot here, even if it is today safe to use, it may not be tomorrow if someone changes it. So we not only need to check, simplify, and potentially fix it, we also need guards against regressions.
For this patch, I'm aiming for a minimally invasive patch here that is also easy to downport.
About races, that one is true. If someone concurrently uses tty while it gets destroyed, we will crash. My patch does not help here.
Early VM init could be considered as a separate issue. Really it is only things like NMT that have issues here because you want it enabled (potentially from the initial load of libjvm) but can't use any VM services at that time.
You would be surprised how much code is running before VM initialization via C++ dynamic initialization. Mostly UL and Compiler-related. That was the reason why we needed NMT preinit - because there were a lot of calls to os::malloc before initialization. I really dislike this since it randomizes initialization order and makes debugging very complicated. But it is what it is.
We obviously need to have a backup plan for error/crash reporting (as all bets are off by then anyway!), but early logging should be a special case - how do you even turn it on when argument processing has not yet happened? Do we still have that hack to directly read a special environment variable for NMT?
Oh, no. That was the whole reason for the NMT rewrite https://bugs.openjdk.org/browse/JDK-8256844. It made NMT late-initializable and usable in custom launchers (e.g. also during gtests). But for that, it needs some early magic to deal with above mentioned early os::malloc calls.
So, sorry, but I don't see this as a simple "slam-dunk" issue. But at the end of the day, I can only voice my concerns. If others think this is okay and approve it then so be it.
How about a compromise then?
I consider post-VM-exit the more important part. And also the more likely to fail. Here the process has a "VM history" that may cause code to access tty. For example, the NMT C-Heap corruption checker you encountered. Or things like error handling: We don't disable the signal handlers so that we will handle crashes till the bitter end. And things like AGCT, which unfortunately exist.
So, how about
-
Pre init: We silently swallow all output to tty without crashing. But we give the user a way to switch output on via environment variable (that is really the only way before arg parsing), e.g. "VM_ENABLE_EARLY_TTY". If that is set, we set tty to stdout.
-
Post exit: We extend the lifespan of tty "in spirit": after exit, we assign tty either to stdout or stderr, depending on what option the user had set. We default to stdout, since that is where todays tty=NULL crashes would have been written to. That would preserve the final defaultStream flush and make sure any subsequent output is written immediately since its unbuffered.
In the future, we can clean up and simplify defaultStream, make it work beyond the VM lifespan, and add regression checks for this.
Cheers, Thomas
Hi Thomas,
I think for pre-init we would look at adding an env var (which would require a CSR request) when we actually have some logging we want to add. This PR could simply do the enabling for tty to be usable at that time ie set to stdout (as the default VM output destination).
Your suggestion for post-exit seems reasonable, though we may also have to consider the flag that requests VM output get logged to a file (which we probably can't do). I think it reasonable that error and warning output go to stdout/stderr in post-exit. If other more general logging needed to be added for post-exit then that would be evaluated at the time.
Thanks.
I think this is fine as a last chance handler. If we do need pre-init and post-exit logging, ie things come out to this output, we can re-evaluate and move the defaultStream destructor later or have some pre-init logging functionality. This seems good for reliably getting bug reports but should rarely be needed. If you find otherwise, please file an RFE.
Thank you Coleen.
Thanks for the approval! David wanted to have some changes though, therefore I need to reform the patch a bit.
In case you have not been following this really long review thread, this RFE has been triggered by an actual problem David had, where NMT found a C-heap corruption and tried to tell him but fell over tty=NULL during reporting.
Cheers, THomas
@dholmes-ora : I reformed the patch according to our compromise:
- pre-init output is swallowed, but we don't crash. We can add the envvar solution later if needed.
- post-exit output is taken over by a stream that attempts to mimic the defaultStream's behavior.
I did not find a VM flag to redirect defaultStream to a file. And we can still crash if concurrent threads attempt to use tty, but the window of opportunity is much smaller. I did not want to pull tty_lock though since I don't want to hold up VM shutdown in case of an error.
Going to push as commit a85a72341bd840b2c7b66ce32c8bbca920e519c8.
Since your change was applied there have been 102 commits pushed to the master branch:
- 4da1745836550224306ca66201c35a5baaf30953: 8291118: [vectorapi] Optimize the implementation of lanewise FIRST_NONZERO
- 38a81913d33c856d64b7c26f934026815a482e43: 8290322: Optimize Vector.rearrange over byte vectors for AVX512BW targets.
- 27af0144ea57e86d9b81c2b328fad66e4a046f61: 8292743: Missing include resourceHash.hpp
- f58aaab4a40f09be03d77a8df8dfefa94e47b320: 8292262: adjust timeouts in several M&M tests
- ab6988599cded028ebfc4c958bc9e88d1b365ad7: 8292215: java/util/stream/boottest/java.base/java/util/stream/SpinedBufferTest.java times out with slowdebug
- 54843b700a463e75cd23a23df8ec5dc73b80f105: 8290211: jdk/internal/vm/Continuation/Fuzz.java failed with "AssertionError: Failed to compile int Fuzz.com_int(int,int) in 5000ms"
- 8a0c3e53d541395ac32d656ac64d20ca0b9a187c: 8292261: adjust timeouts in JLI GetObjectSizeIntrinsicsTest.java
- 8e8ee4b6f22657a7efba8d7998f3c309f334a086: 8292596: Make SymbolHashMap a ResourceHashtable
- aa9b8f04bf74d5fa00f2b27895e7369abea3a930: 8292043: Incorrect decoding near EOF for stateful decoders like UTF-16
- f95ee7960328410551a6948053d1ff0ec3d8c53d: 8292566: Add reference to the java.nio.file package in java.nio package documentation
- ... and 92 more: https://git.openjdk.org/jdk/compare/e89abb7d2d902c6e6b3c9953fc6663de10db77b9...master
Your commit was automatically rebased without conflicts.