Docker: Improve error messages around port-bound check #12477
Conversation
| ports=port_mappings, | ||
| remove=True, | ||
| ) | ||
| except Exception as e: | ||
| if "port is already allocated" not in str(e) and "address already in use" not in str(e): | ||
| if "address already in use" not in str(e): |
There was a problem hiding this comment.
The exact error message probably changed at some point, so if a port is already in use, it does not say port is already allocated.
The full message is:
Internal Server Error ("failed to set up container networking: driver failed programming external connectivity on endpoint zealous_mayer (...): failed to bind host port for 0.0.0.0:6443:172.17.0.4:6443/tcp: address already in use")
Simplifying the check should ensure that we only see this message when necessary
There was a problem hiding this comment.
The error message still exists in the docker source code: https://github.com/moby/moby/blob/11bf52e9e331daa235d23b6cf92298481083128d/libnetwork/portallocator/portallocator.go#L36 Not sure when either is called, but I think it might make sense to keep it here
There was a problem hiding this comment.
Yeah, you're right - it does make more sense to keep it. I've reverted that change 👍
| LOG.warning( | ||
| "Unexpected error when attempting to determine container port status: %s", e | ||
| "Unexpected error when attempting to determine container port status", exc_info=e |
There was a problem hiding this comment.
If we do see the message, it would be nice to see the full stacktrace to debug what's going on
| ) | ||
| return False | ||
| # TODO(srw): sometimes the command output from the docker container is "None", particularly when this function is | ||
| # invoked multiple times consecutively. Work out why. | ||
| if to_str(result[0] or "").strip() != "test123": | ||
| LOG.warning( | ||
| "Unexpected output when attempting to determine container port status: %s", result[0] |
There was a problem hiding this comment.
result is a tuple of (stdout, stderr) - it makes sense to log both if anything goes wrong
34e7415 to
d20190d
Compare
| ports=port_mappings, | ||
| remove=True, | ||
| ) | ||
| except Exception as e: | ||
| if "port is already allocated" not in str(e) and "address already in use" not in str(e): | ||
| if "address already in use" not in str(e): |
There was a problem hiding this comment.
The error message still exists in the docker source code: https://github.com/moby/moby/blob/11bf52e9e331daa235d23b6cf92298481083128d/libnetwork/portallocator/portallocator.go#L36 Not sure when either is called, but I think it might make sense to keep it here
| LOG.warning( | ||
| "Unexpected error when attempting to determine container port status: %s", e | ||
| "Unexpected error when attempting to determine container port status", exc_info=e |
There was a problem hiding this comment.
| "Unexpected error when attempting to determine container port status", exc_info=e | |
| "Unexpected error when attempting to determine container port status: e", exc_info=LOG.isEnabledFor(logging.DEBUG) |
This will only print the stack trace when debug logging is enabled, not for every call, which would reduce the logging in higher log levels. WDYT?
There was a problem hiding this comment.
If it was a regular scenario, then yes, it makes sense to only show this on Debug. But this is an unhandled exception, and something happened here that we didn't expect (or know how to handle). So IMO showing a stacktrace at any log level makes it clearer to the user that this is an actual error.
d20190d to
61f7ec0
Compare
Motivation
Minor improvements around the logging when checking if a port is available.
An ealier version of this PR also changed the image to use
bashinstead, but some benchmarks showed that using a smaller image does not improve the performance. This method always takes around35ms, regardless of the exact image used.For reference, this was the original description:
To check if a certain port is available, we currently start a second LocalStack instance with those ports reserved, and check if it fails. Starting LocalStack is quite resource-intensive - using a smaller image (likebash) is much faster. (This is especially important when calling this method multiple times in parallel.)