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

Trim a spurious log message for plugins using RPC #186

Merged

Conversation

tbehling
Copy link
Contributor

@tbehling tbehling commented Jan 4, 2022

This PR trims a spurious log message for plugins using RPC.

When a plugin is shutting down, the plugin host's log will often report an error about accept unix / use of closed network connection . Essentially, an accept call is getting invoked on a socket that is already closed. This PR simply updates the RPC server's accept loop to avoid logging that error.

This PR makes an assumption that there are no legitimate debugging situations where this error indication is helpful.

As reported in #72, when using the "basic" example in this repo, the output is the following:

2022-01-04T15:36:16.041-0500 [DEBUG] plugin: starting plugin: path=./plugin/greeter args=[./plugin/greeter]
2022-01-04T15:36:16.041-0500 [DEBUG] plugin: plugin started: path=./plugin/greeter pid=10674
2022-01-04T15:36:16.041-0500 [DEBUG] plugin: waiting for RPC address: path=./plugin/greeter
2022-01-04T15:36:16.046-0500 [DEBUG] plugin.greeter: message from plugin: foo=bar timestamp=2022-01-04T15:36:16.046-0500
2022-01-04T15:36:16.046-0500 [DEBUG] plugin.greeter: plugin address: address=/tmp/plugin3230253060 network=unix timestamp=2022-01-04T15:36:16.046-0500
2022-01-04T15:36:16.046-0500 [DEBUG] plugin: using plugin: version=1
2022-01-04T15:36:16.047-0500 [DEBUG] plugin.greeter: message from GreeterHello.Greet: timestamp=2022-01-04T15:36:16.047-0500
Hello!
2022-01-04T15:36:16.047-0500 [DEBUG] plugin.greeter: 2022/01/04 15:36:16 [ERR] plugin: plugin server: accept unix /tmp/plugin3230253060: use of closed network connection
2022-01-04T15:36:16.047-0500 [DEBUG] plugin: plugin process exited: path=./plugin/greeter pid=10674
2022-01-04T15:36:16.047-0500 [DEBUG] plugin: plugin exited

With this patch, the line about use of closed network connection is absent.

Fixes #72
Fixes cloud-native-go/examples#2

@jbardin
Copy link
Member

jbardin commented Jan 19, 2022

Thanks @tbehling! I think it may still be useful to log the closed case as debug, so that there's an indication why the server exited if the caller wasn't expecting it.

The ErrClosed value was only recently added, so we will need to bump the go version for the module too.

(also make sure to run go fmt, there's an extra space in the if statement)

@tbehling tbehling requested a review from jbardin January 27, 2022 19:41
@tbehling
Copy link
Contributor Author

Hi @jbardin, thank you so much for giving this a review, and for our subsequent conversation.

Based on your comments, I've updated this PR to retain the log message, but print it with [DEBUG] instead of [ERR]. That should eliminate the pain of seeing false-positive errors in logs for these benign messages.

I see the go.mod here specifies Go 1.13. net.ErrClosed was added in Go 1.16 (and changed data types in 1.17!). The code here uses some Go tricks to ensure backward compatibility, while still using errors.Is().

I don't love the complexity, but the alternative is to compare the Go error text, which has been done by a lot of Go projects in the past, but is fragile, and the text has changed before.

@tbehling tbehling force-pushed the tbehling/closed-network-connection branch from 54ac37d to b21e7d8 Compare January 27, 2022 21:23
@tbehling
Copy link
Contributor Author

Hi again @jbardin, per our discussion, I have dropped the compatibility with old versions of Go, which simplifies this PR a lot.

If I now build the examples/basic plugin, the relevant line from the output of ./basic is:

2022-01-27T16:28:25.716-0500 [DEBUG] plugin.greeter: 2022/01/27 16:28:25 [DEBUG] plugin: plugin server: accept unix /tmp/plugin3304580809: use of closed network connection

The difference from the original is that second [DEBUG] used to be [ERR].

I also bumped go.mod to Go 1.17, and ran go fmt which made updates to 2 files.

This PR doesn't have Go CI tests, but locally, go test passes.

@tbehling tbehling merged commit 73def4e into hashicorp:master Jan 31, 2022
@tbehling tbehling deleted the tbehling/closed-network-connection branch January 31, 2022 14:17
@tbehling
Copy link
Contributor Author

For reference there is some discussion about Go's net.ErrClosed at golang/go#4373 .

bflad added a commit that referenced this pull request Mar 3, 2023
Reference: https://pkg.go.dev/golang.org/x/[email protected]/context
Reference: #186

Previously, the module was only using `golang.org/x/net/context` import. That package was deprecated with Go 1.7 when its functionality migrated into the standard library `context` package. This Go module already announces Go 1.17 minimum since version 1.4.4 and the `context` types are not exposed as part of any exported API.
bflad added a commit that referenced this pull request Mar 6, 2023
Reference: https://pkg.go.dev/golang.org/x/[email protected]/context
Reference: #186

Previously, the module was only using `golang.org/x/net/context` import. That package was deprecated with Go 1.7 when its functionality migrated into the standard library `context` package. This Go module already announces Go 1.17 minimum since version 1.4.4 and the `context` types are not exposed as part of any exported API.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Chapter 8: Use of Closed Network Connection Error Basic example seems to be broken (at least on Mac)
2 participants