devicemapper: rework logging and add --storage-opt dm.libdm_log_level #33845

cyphar · 2017-06-27T15:07:34Z

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 asarai@suse.de

/cc @vbatts @rhvgoyal

cyphar · 2017-06-27T15:11:05Z

As an aside, I wanted to update the docs for dockerd to include the new storagedriver option. I was trying to figure out where the man pages live and it looks like they're no longer in this repo? Where are they now?

/cc @thaJeztah ?

cpuguy83 · 2017-06-27T15:26:20Z

This looks pretty much like a dup of #32541

cyphar · 2017-06-27T15:35:07Z

I didn't see that change beforehand. However, this change actually does a lot more than #32541. In particular:

It cleans up the exposed callback code (which didn't make sense because we always needed to register a callback anyway).
Cleans up the C callback code to not be limited to 256 bytes.
Allows a user to specify what their choice of maximum logging is (which is the main point of this patch).
Removes some of the other old cruft from the logging code that Fine control of libdevmapper logging #32541 didn't touch.

I do like some of the stuff in p/d/log.go though, we might want to merge those changes as well. How would you like to go on from here?

cpuguy83 · 2017-06-27T15:53:09Z

Maybe we can just pull those changes in here? (minus the logrus dep in the p/d package).

cyphar · 2017-06-27T15:54:01Z

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).

cyphar · 2017-06-27T16:09:22Z

Actually I just realised that most of the code in pkg/devicemapper/log.go is not really useful if you don't want to have a logrus dependency inside that file (given the rest of my patchset). Effectively you just get a glorified Sprintf wrapper because you can't write a nice Logf without being able to log.

rhvgoyal · 2017-06-27T20:53:14Z

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.

rhvgoyal · 2017-06-27T21:11:23Z

pkg/devicemapper/devmapper_log.go

+// 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


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.

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.

rhvgoyal · 2017-06-27T21:15:36Z

daemon/graphdriver/devmapper/deviceset.go

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


Will it make sense to call it dm.libdm_log_level instead.

Yeah, that sounds better.

rhvgoyal · 2017-06-27T22:03:38Z

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.

thaJeztah · 2017-06-28T00:54:23Z

As an aside, I wanted to update the docs for dockerd to include the new storagedriver option. I was trying to figure out where the man pages live and it looks like they're no longer in this repo? Where are they now?

The CLI docs were moved to the https://github.com/docker/cli repository (yes, dockerd could have been left in this repository, but after debating the pros/cons we decided that it made things easier to have them in that repository 😅)

cyphar · 2017-06-28T03:27:24Z

@thaJeztah Alright, I'll match a PR there once this is merged.

cyphar · 2017-06-28T03:53:14Z

@rhvgoyal Fix'd. PTAL.

/cc @vbatts

vrothberg · 2017-06-28T08:14:54Z

daemon/graphdriver/devmapper/deviceset.go

+		case "dm.libdm_log_level":
+			level, err := strconv.ParseUint(val, 10, 32)
+			if err != nil {
+				return nil, err


Maybe, we should return a more expressive error here, as for instance case "dm.thinp_autoextend_threshold": does.

vrothberg · 2017-06-28T08:27:53Z

daemon/graphdriver/devmapper/deviceset.go

@@ -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)


Considering that DmLogLevel(value int) does bounds checking, we could just parse a 64bit integer here and defer bounds errors to DmLogLevel(value int).

cyphar · 2017-06-29T05:28:13Z

/cc @runcom You probably want to port this to containers/storage. Or if you prefer I can push this PR there as well.

runcom · 2017-06-29T07:14:50Z

cc @nalind for c/storage (thanks for the ping!)

cyphar · 2017-06-29T16:35:54Z

/ping @rhvgoyal @cpuguy83 ?

rhvgoyal · 2017-06-29T18:53:45Z

pkg/devicemapper/devmapper_wrapper.go

-  vsnprintf(buffer, 256, f, ap);
-  va_end(ap);
+	va_start(ap, f);
+	vasprintf(&buffer, f, ap);


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

Adding #define _GNU_SOURCE seems to make it go away.

Yup. For some reason I didn't get the same warning. Hmm.

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 <asarai@suse.de>

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 <asarai@suse.de>

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 <asarai@suse.de>

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 <asarai@suse.de>

rhvgoyal · 2017-07-03T17:12:24Z

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.

cyphar · 2017-07-03T17:17:01Z

I'm using this patchset to debug some production issues right now. 😉

cyphar · 2017-07-07T19:25:22Z

/ping @cpuguy83

coolljt0725 · 2017-07-12T02:00:44Z

ping @cpuguy83

cpuguy83

LGTM

Tested, looks good.

cyphar · 2017-07-12T17:32:45Z

/cc @vdemeester @coolljt0725

thaJeztah

LGTM

thaJeztah · 2017-07-13T00:46:38Z

thanks @cyphar !

This adds bash completion for moby/moby#33845. Signed-off-by: Harald Albers <github@albersweb.de>

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 <asarai@suse.de> Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>

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 <asarai@suse.de> Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com> 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 <asarai@suse.de> Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>

This adds bash completion for moby/moby#33845. Signed-off-by: Harald Albers <github@albersweb.de>

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 <asarai@suse.de> Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com> Upstream-commit: 7da12bc Component: engine

GordonTheTurtle added the status/0-triage label Jun 27, 2017

cyphar force-pushed the devicemapper-show-me-your-logs branch from b0977e7 to 28e8422 Compare June 27, 2017 15:58

cyphar mentioned this pull request Jun 27, 2017

Fine control of libdevmapper logging #32541

Closed

cyphar force-pushed the devicemapper-show-me-your-logs branch 2 times, most recently from d9cb749 to c410d20 Compare June 27, 2017 17:22

rhvgoyal reviewed Jun 27, 2017

View reviewed changes

thaJeztah added status/2-code-review and removed status/0-triage labels Jun 28, 2017

cyphar force-pushed the devicemapper-show-me-your-logs branch from c410d20 to 5b1dbdf Compare June 28, 2017 03:42

vrothberg reviewed Jun 28, 2017

View reviewed changes

cyphar force-pushed the devicemapper-show-me-your-logs branch from 5b1dbdf to 95ae588 Compare June 28, 2017 09:07

cyphar mentioned this pull request Jun 28, 2017

Use a retry loop for DeleteDevice in deleteTransaction #33846

Closed

cyphar changed the title ~~devicemapper: rework logging and add --storage-opt dm.log_debug~~ devicemapper: rework logging and add --storage-opt dm.libdm_log_level Jun 28, 2017

cyphar force-pushed the devicemapper-show-me-your-logs branch from 95ae588 to d83f396 Compare June 28, 2017 12:42

rhvgoyal reviewed Jun 29, 2017

View reviewed changes

cyphar force-pushed the devicemapper-show-me-your-logs branch from 439e40f to 7e552bf Compare June 30, 2017 20:09

cyphar added 4 commits July 4, 2017 02:04

cyphar force-pushed the devicemapper-show-me-your-logs branch from 7e552bf to 198f83b Compare July 3, 2017 16:04

thaJeztah requested a review from cpuguy83 July 8, 2017 00:36

GordonTheTurtle assigned coolljt0725 Jul 12, 2017

cpuguy83 approved these changes Jul 12, 2017

View reviewed changes

cyphar mentioned this pull request Jul 12, 2017

docs: add documentation for dm.libdm_log_level docker/cli#324

Merged

thaJeztah approved these changes Jul 13, 2017

View reviewed changes

thaJeztah merged commit 00b2182 into moby:master Jul 13, 2017

rhvgoyal mentioned this pull request Jul 13, 2017

Backport: dm.libdm_log_level knob for devicemapper projectatomic/docker#265

Closed

cyphar deleted the devicemapper-show-me-your-logs branch July 13, 2017 06:03

albers added a commit to albers/docker-cli that referenced this pull request Jul 14, 2017

Add bash completion for --storage-opt dm.libdm_log_level

b8710cc

This adds bash completion for moby/moby#33845. Signed-off-by: Harald Albers <github@albersweb.de>

albers mentioned this pull request Jul 14, 2017

Add bash completion for --storage-opt dm.libdm_log_level docker/cli#334

Merged

kolyshkin mentioned this pull request Jul 18, 2017

devmapper_wrapper.go: fix gcc warning #34146

Merged

riyazdf pushed a commit to riyazdf/cli that referenced this pull request Aug 2, 2017

Add bash completion for --storage-opt dm.libdm_log_level

77f1d48

This adds bash completion for moby/moby#33845. Signed-off-by: Harald Albers <github@albersweb.de>

thaJeztah added area/storage/devicemapper and removed area/storage/devicemapper labels Jul 3, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

devicemapper: rework logging and add --storage-opt dm.libdm_log_level #33845

devicemapper: rework logging and add --storage-opt dm.libdm_log_level #33845

cyphar commented Jun 27, 2017

cyphar commented Jun 27, 2017 •

edited

Loading

cpuguy83 commented Jun 27, 2017

cyphar commented Jun 27, 2017 •

edited

Loading

cpuguy83 commented Jun 27, 2017

cyphar commented Jun 27, 2017

cyphar commented Jun 27, 2017 •

edited

Loading

rhvgoyal commented Jun 27, 2017

rhvgoyal Jun 27, 2017

cyphar Jun 28, 2017 •

edited

Loading

rhvgoyal Jun 27, 2017

cyphar Jun 28, 2017

rhvgoyal commented Jun 27, 2017

thaJeztah commented Jun 28, 2017

cyphar commented Jun 28, 2017 •

edited

Loading

cyphar commented Jun 28, 2017

vrothberg Jun 28, 2017

vrothberg Jun 28, 2017 •

edited

Loading

cyphar commented Jun 29, 2017

runcom commented Jun 29, 2017

cyphar commented Jun 29, 2017

rhvgoyal Jun 29, 2017

rhvgoyal Jun 29, 2017

cyphar Jun 29, 2017

cyphar Jun 29, 2017

rhvgoyal commented Jul 3, 2017

cyphar commented Jul 3, 2017

cyphar commented Jul 7, 2017

coolljt0725 commented Jul 12, 2017

cpuguy83 left a comment

cyphar commented Jul 12, 2017

thaJeztah left a comment

thaJeztah commented Jul 13, 2017

devicemapper: rework logging and add --storage-opt dm.libdm_log_level #33845

devicemapper: rework logging and add --storage-opt dm.libdm_log_level #33845

Conversation

cyphar commented Jun 27, 2017

Cosy cat by David O'Hare, on Flickr.

cyphar commented Jun 27, 2017 • edited Loading

cpuguy83 commented Jun 27, 2017

cyphar commented Jun 27, 2017 • edited Loading

cpuguy83 commented Jun 27, 2017

cyphar commented Jun 27, 2017

cyphar commented Jun 27, 2017 • edited Loading

rhvgoyal commented Jun 27, 2017

Choose a reason for hiding this comment

cyphar Jun 28, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rhvgoyal commented Jun 27, 2017

thaJeztah commented Jun 28, 2017

cyphar commented Jun 28, 2017 • edited Loading

cyphar commented Jun 28, 2017

Choose a reason for hiding this comment

vrothberg Jun 28, 2017 • edited Loading

Choose a reason for hiding this comment

cyphar commented Jun 29, 2017

runcom commented Jun 29, 2017

cyphar commented Jun 29, 2017

Choose a reason for hiding this comment

github.com/docker/docker/pkg/devicemapper

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rhvgoyal commented Jul 3, 2017

cyphar commented Jul 3, 2017

cyphar commented Jul 7, 2017

coolljt0725 commented Jul 12, 2017

cpuguy83 left a comment

Choose a reason for hiding this comment

cyphar commented Jul 12, 2017

thaJeztah left a comment

Choose a reason for hiding this comment

thaJeztah commented Jul 13, 2017

cyphar commented Jun 27, 2017 •

edited

Loading

cyphar commented Jun 27, 2017 •

edited

Loading

cyphar commented Jun 27, 2017 •

edited

Loading

cyphar Jun 28, 2017 •

edited

Loading

cyphar commented Jun 28, 2017 •

edited

Loading

vrothberg Jun 28, 2017 •

edited

Loading