-
Notifications
You must be signed in to change notification settings - Fork 18.6k
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
devicemapper: rework logging and add --storage-opt dm.libdm_log_level #33845
Conversation
As an aside, I wanted to update the docs for /cc @thaJeztah ? |
This looks pretty much like a dup of #32541 |
I didn't see that change beforehand. However, this change actually does a lot more than #32541. In particular:
I do like some of the stuff in |
Maybe we can just pull those changes in here? (minus the logrus dep in the |
Sure, will do. I'm splitting up this patch now so it's more obvious what I'm doing (I squashed it pre-emptively because I was planning on backporting it). |
b0977e7
to
28e8422
Compare
Actually I just realised that most of the code in |
d9cb749
to
c410d20
Compare
I have not looked at this yet. But we very much require something like this as well. Recompiling source code does not work when debugging a system in production. Restarting docker with additional flag is much easier. So yes, we do need a knob to get fine control of logging by libdevmapper when used with docker. |
pkg/devicemapper/devmapper_log.go
Outdated
// through logrus. libdm uses logging *very* liberally and most people using | ||
// --debug [or Docker] aren't going to be debugging libdm bugs. You can enable | ||
// this by setting --storage-opt="dm.log_level=X". | ||
var dmLogLevel = LogLevelErr |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
So this changes default from fatal to level Err? When I had tested last time, even with this level libdm was spewing tons of messages. And it was made worse because we try device removal in a loop. Most of the time these messages are really not worth it.
How about keeping the current defaults and providing a knob to change that default.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I ran this a few times and it didn't seem to spam the logs too much (and I don't like ignoring _LOG_ERROR
because it causes you to ignore some _do_dm_ioctl
errors) but yeah, I'll change it back to the old default.
@@ -2761,6 +2761,14 @@ func NewDeviceSet(root string, doInit bool, options []string, uidMaps, gidMaps [ | |||
return nil, errors.New("dm.thinp_autoextend_threshold must be greater than 0 and less than 100") | |||
} | |||
lvmSetupConfig.AutoExtendThreshold = per | |||
case "dm.log_level": |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Will it make sense to call it dm.libdm_log_level
instead.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yeah, that sounds better.
BTW, I love the idea of breaking down patches in a series. That way one can focus on core bits first and then focus on less important bits later. And its much easier to review. |
The CLI docs were moved to the https://github.com/docker/cli repository (yes, |
@thaJeztah Alright, I'll match a PR there once this is merged. |
c410d20
to
5b1dbdf
Compare
case "dm.libdm_log_level": | ||
level, err := strconv.ParseUint(val, 10, 32) | ||
if err != nil { | ||
return nil, err |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Maybe, we should return a more expressive error here, as for instance case "dm.thinp_autoextend_threshold":
does.
@@ -2761,6 +2761,14 @@ func NewDeviceSet(root string, doInit bool, options []string, uidMaps, gidMaps [ | |||
return nil, errors.New("dm.thinp_autoextend_threshold must be greater than 0 and less than 100") | |||
} | |||
lvmSetupConfig.AutoExtendThreshold = per | |||
case "dm.libdm_log_level": | |||
level, err := strconv.ParseUint(val, 10, 32) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Considering that DmLogLevel(value int)
does bounds checking, we could just parse a 64bit integer here and defer bounds errors to DmLogLevel(value int)
.
5b1dbdf
to
95ae588
Compare
95ae588
to
d83f396
Compare
/cc @runcom You probably want to port this to containers/storage. Or if you prefer I can push this PR there as well. |
cc @nalind for c/storage (thanks for the ping!) |
vsnprintf(buffer, 256, f, ap); | ||
va_end(ap); | ||
va_start(ap, f); | ||
vasprintf(&buffer, f, ap); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I get following warning during compilation.
Building: bundles/17.06.0-dev/dynbinary-daemon/dockerd-17.06.0-dev
github.com/docker/docker/pkg/devicemapper
.gopath/src/github.com/docker/docker/pkg/devicemapper/devmapper_wrapper.go: In function ‘log_cb’:
.gopath/src/github.com/docker/docker/pkg/devicemapper/devmapper_wrapper.go:20:2: warning: implicit declaration of function ‘vasprintf’; did you mean ‘vsprintf’? [-Wimplicit-function-declaration]
vasprintf(&buffer, f, ap);
^~~~~~~~~
vsprintf
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Adding #define _GNU_SOURCE
seems to make it go away.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yup. For some reason I didn't get the same warning. Hmm.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Fixed.
439e40f
to
7e552bf
Compare
This limit is unecessary and can lead to the truncation of long libdm logs (which is quite annoying). Fixes: b440ec0 ("device-mapper: Move all devicemapper spew to log through utils.Debugf().") Signed-off-by: Aleksa Sarai <[email protected]>
e07d3cd ("devmapper: Fix libdm logging") removed all of the callers of DmLogInitVerbose, but we still kept around the wrapper. However, the libdm dm_log_init_verbose API changes the verbosity of the *default* libdm logger. Because pkg/devicemapper internally *relies* on using logging callbacks to understand what errors were encountered by libdm, this wrapper is useless (it only makes sense for the default logger which we do not user). Any user not inside Docker of this function almost certainly was not using this API correctly, because pkg/devicemapper will misbehave if our logging callbacks were not registered. Signed-off-by: Aleksa Sarai <[email protected]>
LogInit used to act as a manual way of registering the *necessary* pkg/devicemapper logging callbacks. In addition, it was used to split up the logic of pkg/devicemapper into daemon/graphdriver/devmapper (such that some things were logged from libdm). The manual aspect of this API was completely non-sensical and was just begging for incorrect usage of pkg/devicemapper, so remove that semantic and always register our own libdm callbacks. In addition, recombine the split out logging callbacks into pkg/devicemapper so that the default logger is local to the library and also shown to be the recommended logger. This makes the code substantially easier to read. Also the new DefaultLogger now has configurable upper-bound for the log level, which allows for dynamically changing the logging level. Signed-off-by: Aleksa Sarai <[email protected]>
Because we use our own logging callbacks in order to use libdm effectively, it is quite difficult to debug complicated devicemapper issues (because any warnings or notices from libdm are muted by our own callback function). e07d3cd ("devmapper: Fix libdm logging") further reduced the ability of this debugging by only allowing _LOG_FATAL errors to be passed to the output. Unfortunately libdm is very chatty, so in order to avoid making the logs even more crowded, add a dm.libdm_log_level storage option that allows people who are debugging the lovely world of libdm to be able to dive in without recompiling binaries. The valid values of dm.libdm_log_level map directly to the libdm logging levels, and are in the range [2,7] as of the time of writing with 7 being _LOG_DEBUG and 2 being _LOG_FATAL. The default is _LOG_FATAL. Signed-off-by: Aleksa Sarai <[email protected]>
7e552bf
to
198f83b
Compare
LGTM @cyphar thanks for implementing this knob. This is really required to be able to debug some docker issues without recompiling. Rest of the cleanup is also nice. Makes reading this code easier. |
I'm using this patchset to debug some production issues right now. 😉 |
/ping @cpuguy83 |
ping @cpuguy83 |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
LGTM
Tested, looks good.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
LGTM
thanks @cyphar ! |
This adds bash completion for moby/moby#33845. Signed-off-by: Harald Albers <[email protected]>
I am getting the following warning from gcc when compiling the daemon: > # github.com/docker/docker/pkg/devicemapper > pkg/devicemapper/devmapper_wrapper.go: In function ‘log_cb’: > pkg/devicemapper/devmapper_wrapper.go:20:2: warning: ignoring return > value of ‘vasprintf’, declared with attribute warn_unused_result > [-Wunused-result] > vasprintf(&buffer, f, ap); > ^ vasprintf(3) man page says if the function returns -1, the buffer is undefined, so we should not use it. In practice, I assume, this never happens so we just return. Introduced by moby#33845 that resulted in commit 63328c6 ("devicemapper: remove 256 character limit of libdm logs") Cc: Aleksa Sarai <[email protected]> Signed-off-by: Kir Kolyshkin <[email protected]>
I am getting the following warning from gcc when compiling the daemon: > # github.com/docker/docker/pkg/devicemapper > pkg/devicemapper/devmapper_wrapper.go: In function ‘log_cb’: > pkg/devicemapper/devmapper_wrapper.go:20:2: warning: ignoring return > value of ‘vasprintf’, declared with attribute warn_unused_result > [-Wunused-result] > vasprintf(&buffer, f, ap); > ^ vasprintf(3) man page says if the function returns -1, the buffer is undefined, so we should not use it. In practice, I assume, this never happens so we just return. Introduced by moby/moby#33845 that resulted in commit 63328c6 ("devicemapper: remove 256 character limit of libdm logs") Cc: Aleksa Sarai <[email protected]> Signed-off-by: Kir Kolyshkin <[email protected]> Upstream-commit: 7da12bc Component: engine
I am getting the following warning from gcc when compiling the daemon: > # github.com/docker/docker/pkg/devicemapper > pkg/devicemapper/devmapper_wrapper.go: In function ‘log_cb’: > pkg/devicemapper/devmapper_wrapper.go:20:2: warning: ignoring return > value of ‘vasprintf’, declared with attribute warn_unused_result > [-Wunused-result] > vasprintf(&buffer, f, ap); > ^ vasprintf(3) man page says if the function returns -1, the buffer is undefined, so we should not use it. In practice, I assume, this never happens so we just return. Introduced by moby#33845 that resulted in commit 63328c6 ("devicemapper: remove 256 character limit of libdm logs") Cc: Aleksa Sarai <[email protected]> Signed-off-by: Kir Kolyshkin <[email protected]>
This adds bash completion for moby/moby#33845. Signed-off-by: Harald Albers <[email protected]>
I am getting the following warning from gcc when compiling the daemon: > # github.com/docker/docker/pkg/devicemapper > pkg/devicemapper/devmapper_wrapper.go: In function ‘log_cb’: > pkg/devicemapper/devmapper_wrapper.go:20:2: warning: ignoring return > value of ‘vasprintf’, declared with attribute warn_unused_result > [-Wunused-result] > vasprintf(&buffer, f, ap); > ^ vasprintf(3) man page says if the function returns -1, the buffer is undefined, so we should not use it. In practice, I assume, this never happens so we just return. Introduced by moby/moby#33845 that resulted in commit 63328c6 ("devicemapper: remove 256 character limit of libdm logs") Cc: Aleksa Sarai <[email protected]> Signed-off-by: Kir Kolyshkin <[email protected]> Upstream-commit: 7da12bc Component: engine
Because libdm doesn't log anything if we have a logging callback
registered, we have to forward our logs to logrus. While this was done
previously in e2f8fbf ("devicemapper: split out devicemapper bindings"),
it was modified in e07d3cd ("devmapper: Fix libdm logging") to remove
the debugging information because it was too voluminous.
However, this has caused us several issues in debugging production
systems because libdm LOG{NOTICE,INFO,DEBUG} logs contain information
that cannot be obtained without recompiling the source.
In order to aid debugging while avoiding large amounts of logs, forward
LOG{NOTICE,INFO} into our debug logs and only output _LOG_DEBUG if an
additional storage-driver specific flag is specified. This respects the
fact that most users aren't going to be debugging devicemapper issues,
while also avoiding the source recompilation burden when debugging.
Cosy cat by David O'Hare, on Flickr.
Signed-off-by: Aleksa Sarai [email protected]
/cc @vbatts @rhvgoyal