8255148: Confusing log output: SSLSocket duplex close failed #4354

evwhelan · 2021-06-04T10:44:32Z

Hi,

Please review my fix for JDK-8255148 which clarifies when an exception contains debug information only.

Regards,
Evan

Progress

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

Issue

JDK-8255148: Confusing log output: SSLSocket duplex close failed

Reviewers

Sean Mullan (@seanjmullan - Reviewer)

Reviewing

Using git

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

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

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 4354

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

Using diff file

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

bridgekeeper · 2021-06-04T10:44:41Z

👋 Welcome back ewhelan! 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 · 2021-06-04T10:47:11Z

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

security

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.

mlbridge · 2021-06-04T10:52:16Z

Webrevs

01: Full - Incremental (c4ad5abb)
00: Full (8bf9b687)

seanjmullan · 2021-06-04T14:08:58Z

src/java.base/share/classes/sun/security/ssl/SSLSocketImpl.java

@@ -587,7 +587,7 @@ public void close() throws IOException {
        } catch (IOException ioe) {
            // ignore the exception
            if (SSLLogger.isOn && SSLLogger.isOn("ssl")) {
-                SSLLogger.warning("SSLSocket duplex close failed", ioe);
+                SSLLogger.warning("SSLSocket duplex close failed. Debug info only. Exception details:", ioe);


If this is a debug message, shouldn't we just use SSLLogger.fine() instead of SSLLogger.warning(), with the same message "SSLSocket duplex close failed"? @coffeys what do you think?

@seanjmullan - It's the exception stacktrace printed after the message that's causing issue for some. Some are reading it as a JDK functionality issue (when it's not)

I've no strong preference whether this should be printed at warning() or fine() level. That granularity is largely broken since JDK 11 - people need to use -Djavax.net.debug=all to get any reasonable amount of data. It would be good to see https://bugs.openjdk.java.net/browse/JDK-8044609 worked on.

I think the patch looks ok as ie. Evan has fixed up some issues with the test - we should expect a new version shortly.

Hi @seanjmullan @coffeys

I also don't have a logging level preference, so if there's merit to changing it, I'll be happy to do so.
I've updated the test case and verified it passes on all platforms.

Looking forward to any further feedback :)

Ok, It sounds like whether it should be a different logging level (fine) or not can be handled separately as part of a more global effort across other SSL logging messages. So I am ok with the change as-is.

Thanks Sean!

openjdk · 2021-06-09T20:28:55Z

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

8255148: Confusing log output: SSLSocket duplex close failed

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

bbd0313: 8263203: jconsole Online User Guide has wrong URL
33d34c6: 8263323: Debug Agent help output includes invalid URL
79010f2: 8266835: Add a --validate option to the jar tool
db45ff0: 8268052: [JVMCI] non-default installed code must be marked as in_use
bb3d226: 8238213: Method resolution should stop on static error
81fdeb5: 8268417: Add test from JDK-8268360
caf7f49: 8268122: Add specific gc cause for G1 full collections
43e38a1: 8268377: Windows 32bit build fails after JDK-8268174
5fbb62c: 8268163: Change the order of fallback full GCs in G1
7b1e402: 8266598: Exception values for AnnotationTypeMismatchException are not always informative
... and 203 more: https://git.openjdk.java.net/jdk/compare/ef368b32bc8609bdc46cda628fa25e9bcad751e3...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.

As you do not have Committer status in this project an existing Committer must agree to sponsor your change. Possible candidates are the reviewers of this PR (@seanjmullan) but any other Committer may sponsor as well.

➡️ To flag this PR as ready for integration with the above commit message, type /integrate in a new comment. (Afterwards, your sponsor types /sponsor in a new comment to perform the integration).

evwhelan · 2021-06-09T20:30:22Z

/integrate

openjdk · 2021-06-09T20:31:33Z

@evwhelan
Your change (at version c4ad5ab) is now ready to be sponsored by a Committer.

seanjmullan · 2021-06-09T20:37:40Z

/sponsor

openjdk · 2021-06-09T20:39:22Z

@seanjmullan @evwhelan Since your change was applied there have been 213 commits pushed to the master branch:

bbd0313: 8263203: jconsole Online User Guide has wrong URL
33d34c6: 8263323: Debug Agent help output includes invalid URL
79010f2: 8266835: Add a --validate option to the jar tool
db45ff0: 8268052: [JVMCI] non-default installed code must be marked as in_use
bb3d226: 8238213: Method resolution should stop on static error
81fdeb5: 8268417: Add test from JDK-8268360
caf7f49: 8268122: Add specific gc cause for G1 full collections
43e38a1: 8268377: Windows 32bit build fails after JDK-8268174
5fbb62c: 8268163: Change the order of fallback full GCs in G1
7b1e402: 8266598: Exception values for AnnotationTypeMismatchException are not always informative
... and 203 more: https://git.openjdk.java.net/jdk/compare/ef368b32bc8609bdc46cda628fa25e9bcad751e3...master

Your commit was automatically rebased without conflicts.

Pushed as commit 408e0a9.

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

XueleiFan · 2021-06-09T20:56:32Z

src/java.base/share/classes/sun/security/ssl/SSLSocketImpl.java

@@ -1329,7 +1329,7 @@ public void close() throws IOException {
            } catch (IOException ioe) {
                // ignore the exception
                if (SSLLogger.isOn && SSLLogger.isOn("ssl")) {
-                    SSLLogger.warning("output stream close failed", ioe);
+                    SSLLogger.warning("output stream close failed. Debug info only. Exception details:", ioe);


I may look at this bug report different. It is a problem that the user does not understand the debug log properly. Debug log is for debug information only, and the debug log level indicates the level of the message.

It looks like there is too much duplicated information. A log message has already indicated that the message is debug information only. Otherwise, exception should has been thrown in application level. The adding of "Exception details:" adds unnecessary dependency of the exception logging format.

It may be fine to keep it unchanged, as if the users understand the logging message and logging levels. This kind of information normally means there is something that an application should take care of. That why we use a warning level log, rather than a fine level log message.

It we really want an update, may be we could have a documentation enhancement instead.

Similar comments for other update.

Sorry that I did not have my comment earlier, and while I was typing the comment the update was integrated. Please just ignore this comment.

evwhelan added 2 commits June 4, 2021 10:40

8255148: Confusing log output: SSLSocket duplex close failed

3d4eea4

Remove othervm mode

8bf9b68

openjdk bot added the rfr Pull request is ready for review label Jun 4, 2021

openjdk bot added the security security-dev@openjdk.org label Jun 4, 2021

seanjmullan reviewed Jun 4, 2021

View reviewed changes

evwhelan added 2 commits June 9, 2021 17:38

Cleaned up test case

258d3a9

Added new line at end of file

c4ad5ab

seanjmullan approved these changes Jun 9, 2021

View reviewed changes

openjdk bot added the ready Pull request is ready to be integrated label Jun 9, 2021

openjdk bot added the sponsor Pull request is ready to be sponsored label Jun 9, 2021

openjdk bot closed this Jun 9, 2021

openjdk bot added integrated Pull request has been integrated and removed sponsor Pull request is ready to be sponsored ready Pull request is ready to be integrated rfr Pull request is ready for review labels Jun 9, 2021

XueleiFan reviewed Jun 9, 2021

View reviewed changes

8255148: Confusing log output: SSLSocket duplex close failed #4354

8255148: Confusing log output: SSLSocket duplex close failed #4354

evwhelan commented Jun 4, 2021 •

edited by openjdk bot

bridgekeeper bot commented Jun 4, 2021

openjdk bot commented Jun 4, 2021

mlbridge bot commented Jun 4, 2021 •

edited

seanjmullan Jun 4, 2021

coffeys Jun 9, 2021

evwhelan Jun 9, 2021

seanjmullan Jun 9, 2021

evwhelan Jun 9, 2021

openjdk bot commented Jun 9, 2021 •

edited

evwhelan commented Jun 9, 2021

openjdk bot commented Jun 9, 2021

seanjmullan commented Jun 9, 2021

openjdk bot commented Jun 9, 2021

XueleiFan Jun 9, 2021

XueleiFan Jun 9, 2021

8255148: Confusing log output: SSLSocket duplex close failed #4354

8255148: Confusing log output: SSLSocket duplex close failed #4354

Conversation

evwhelan commented Jun 4, 2021 • edited by openjdk bot

Progress

Issue

Reviewers

Reviewing

bridgekeeper bot commented Jun 4, 2021

openjdk bot commented Jun 4, 2021

mlbridge bot commented Jun 4, 2021 • edited

Webrevs

seanjmullan Jun 4, 2021

Choose a reason for hiding this comment

coffeys Jun 9, 2021

Choose a reason for hiding this comment

evwhelan Jun 9, 2021

Choose a reason for hiding this comment

seanjmullan Jun 9, 2021

Choose a reason for hiding this comment

evwhelan Jun 9, 2021

Choose a reason for hiding this comment

openjdk bot commented Jun 9, 2021 • edited

evwhelan commented Jun 9, 2021

openjdk bot commented Jun 9, 2021

seanjmullan commented Jun 9, 2021

openjdk bot commented Jun 9, 2021

XueleiFan Jun 9, 2021

Choose a reason for hiding this comment

XueleiFan Jun 9, 2021

Choose a reason for hiding this comment

evwhelan commented Jun 4, 2021 •

edited by openjdk bot

mlbridge bot commented Jun 4, 2021 •

edited

openjdk bot commented Jun 9, 2021 •

edited