The Wayback Machine - https://web.archive.org/web/20260314092849/https://github.com/moby/moby/pull/36492
Skip to content

36478 storage-drivers log format standardization#36492

Merged
vdemeester merged 1 commit intomoby:masterfrom
alejgh:36478-log-standardization
Apr 20, 2018
Merged

36478 storage-drivers log format standardization#36492
vdemeester merged 1 commit intomoby:masterfrom
alejgh:36478-log-standardization

Conversation

@alejgh
Copy link
Contributor

@alejgh alejgh commented Mar 5, 2018

closes #36478

- What I did
Unify the properties of the log messages from the different storage drivers.

- How I did it
There were 4 different formats proposed/used for logging messages in the drivers:

  • asdevicemapper used logrus.WithField("storage-driver", "devicemapper").
  • zfs used logrus.WithField("driver", "zfs").
  • aufs used
logrus.WithFields(logrus.Fields{
                "module": "graphdriver",
                "driver": "aufs",
        }) 
  • logrus.WithField("module", "graphdriver/devicemapper") was also proposed

I used the second format (logrus.WithField("storage-driver", "xxxxx") across all the storage drivers as it didn't seem to be a preference of one format over another, but I can change the format if needed.

Most of the log messages in the storage-drivers didn't have any property assigned, so I added it to all of them.

- How to verify it
Every test regarding the module is passing, although there didn't seem to be any test regarding the output of the log messages so I didn't make any change to the tests. I don't know if I missed them.

- Description for the changelog
Standardized the properties of storage-driver log messages.

- A picture of a cute animal (not mandatory but encouraged)
capybara

I apologise if there is something I did wrong, this is my first time contributing. Any help would be appreciated. Thank you and sorry for the inconveniences 😔

@alejgh alejgh requested a review from dmcgowan as a code owner March 5, 2018 19:37
@alejgh alejgh changed the title [WIP] 36478 log standardization [WIP] 36478 storage-drivers log format standardization Mar 5, 2018
@codecov
Copy link

codecov bot commented Mar 6, 2018

Codecov Report

❗ No coverage uploaded for pull request base (master@ed7b642). Click here to learn what that means.
The diff coverage is 40.23%.

@@            Coverage Diff            @@
##             master   #36492   +/-   ##
=========================================
  Coverage          ?   34.94%           
=========================================
  Files             ?      613           
  Lines             ?    45415           
  Branches          ?        0           
=========================================
  Hits              ?    15870           
  Misses            ?    27449           
  Partials          ?     2096

@alejgh alejgh changed the title [WIP] 36478 storage-drivers log format standardization 36478 storage-drivers log format standardization Mar 6, 2018
@tiborvass
Copy link
Contributor

@thaJeztah are we concerned about operators relying on the heterogenous keys when searching in their logging solutions?

@alejgh alejgh force-pushed the 36478-log-standardization branch from d073f51 to 73ad006 Compare March 27, 2018 12:34
@GordonTheTurtle GordonTheTurtle added the dco/no Automatically set by a bot when one of the commits lacks proper signature label Mar 27, 2018
@GordonTheTurtle
Copy link

Please sign your commits following these rules:
https://github.com/moby/moby/blob/master/CONTRIBUTING.md#sign-your-work
The easiest way to do this is to amend the last commit:

$ git clone -b "36478-log-standardization" git@github.com:alejgh/moby.git somewhere
$ cd somewhere
$ git rebase -i HEAD~842354205320
editor opens
change each 'pick' to 'edit'
save the file and quit
$ git commit --amend -s --no-edit
$ git rebase --continue # and repeat the amend for each commit
$ git push -f

Amending updates the existing PR. You DO NOT need to open a new one.

Now all of the storage drivers use the field "storage-driver" in their log
messages, which is set to name of the respective driver.
Storage drivers changed:
- Aufs
- Btrfs
- Devicemapper
- Overlay
- Overlay 2
- Zfs

Signed-off-by: Alejandro GonzÃlez Hevia <alejandrgh11@gmail.com>
@alejgh alejgh force-pushed the 36478-log-standardization branch from 23f3ebb to 9392838 Compare March 27, 2018 12:37
@GordonTheTurtle GordonTheTurtle removed the dco/no Automatically set by a bot when one of the commits lacks proper signature label Mar 27, 2018
@alejgh
Copy link
Contributor Author

alejgh commented Apr 10, 2018

@thaJeztah could you take a quick look, please? :)

@thaJeztah
Copy link
Member

Oh, sorry, this dropped off my radar: was discussing this with @tiborvass and looks like he's ok with the change.

Copy link
Member

@thaJeztah thaJeztah left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

restarting CI

Copy link
Member

@cpuguy83 cpuguy83 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@kolyshkin
Copy link
Contributor

Maybe each graph driver can have a logger instance and use it? This would eliminate the repetition of .WithField("storage-driver", ...) statements and make the code cleaner.

Something like this (for aufs):

diff --git a/daemon/graphdriver/aufs/aufs.go b/daemon/graphdriver/aufs/aufs.go
index a46cb31d3..3e94a2f3e 100644
--- a/daemon/graphdriver/aufs/aufs.go
+++ b/daemon/graphdriver/aufs/aufs.go
@@ -62,6 +62,7 @@ var (
 
        enableDirpermLock sync.Once
        enableDirperm     bool
+       logger            = logrus.WithField("storage-driver", "aufs")
 )
 
 func init() {
@@ -109,7 +110,7 @@ func Init(root string, options []string, uidMaps, gidMaps []idtools.IDMap) (grap
 
        switch fsMagic {
        case graphdriver.FsMagicAufs, graphdriver.FsMagicBtrfs, graphdriver.FsMagicEcryptfs:
-               logrus.Errorf("AUFS is not supported over %s", backingFs)
+               logger.Errorf("AUFS is not supported over %s", backingFs)
                return nil, graphdriver.ErrIncompatibleFS
        }
 
@@ -143,11 +144,6 @@ func Init(root string, options []string, uidMaps, gidMaps []idtools.IDMap) (grap
                        return nil, err
                }
        }
-       logger := logrus.WithFields(logrus.Fields{
-               "module": "graphdriver",
-               "driver": "aufs",
-       })
-
        for _, path := range []string{"mnt", "diff"} {
                p := filepath.Join(root, path)
                entries, err := ioutil.ReadDir(p)
@@ -309,11 +305,7 @@ func (a *Driver) Remove(id string) error {
                mountpoint = a.getMountpoint(id)
        }
 
-       logger := logrus.WithFields(logrus.Fields{
-               "module": "graphdriver",
-               "driver": "aufs",
-               "layer":  id,
-       })
+       logger := logger.WithField("layer", id)
 
        var retries int
        for {
diff --git a/daemon/graphdriver/aufs/mount.go b/daemon/graphdriver/aufs/mount.go
index 478198848..fbff1f147 100644
--- a/daemon/graphdriver/aufs/mount.go
+++ b/daemon/graphdriver/aufs/mount.go
@@ -5,14 +5,13 @@ package aufs // import "github.com/docker/docker/daemon/graphdriver/aufs"
 import (
        "os/exec"
 
-       "github.com/sirupsen/logrus"
        "golang.org/x/sys/unix"
 )
 
 // Unmount the target specified.
 func Unmount(target string) error {
        if err := exec.Command("auplink", target, "flush").Run(); err != nil {
-               logrus.Warnf("Couldn't run auplink before unmount %s: %s", target, err)
+               logger.Warnf("Couldn't run auplink before unmount %s: %s", target, err)
        }
        return unix.Unmount(target, 0)
 }

@kolyshkin
Copy link
Contributor

Optionally, rename logger to something shorter, say log. Or maybe not (keep the diff cleaner).

@cpuguy83
Copy link
Member

That's pretty much what I was thinking as well, but didn't want to make a huge diff to get this in.... but I guess then we'll just have two big diffs because all this will be re-written anyway.

@alejgh
Copy link
Contributor Author

alejgh commented Apr 13, 2018

Yes, I thought about adding the logger instance to each graph driver, but I didn't want to mess it up somehow so I followed the previous style. I agree that now it makes a lot more sense to have the logger instance to avoid code duplication or in case this format has to be changed someday.
I apologize if this has to be re-written.

@anusha-ragunathan
Copy link
Contributor

Experimental hits an unexpected error:

23:34:44 FAIL: docker_cli_logs_test.go:92: DockerSuite.TestLogsTail
23:34:44 
23:34:44 docker_cli_logs_test.go:113:
23:34:44     c.Assert(lines, checker.HasLen, testLen+1)
23:34:44 ... obtained []string = []string{"=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", "=", ""}
23:34:44 ... n int = 101

Length is only 41 and the array ends with an empty string.

@thaJeztah
Copy link
Member

PowerPC (https://jenkins.dockerproject.org/job/Docker-PRs-powerpc/9411/console) is failing on a test that's flaky (mentioned in #33041)

00:38:36 ----------------------------------------------------------------------
00:38:36 FAIL: docker_cli_swarm_test.go:1372: DockerSwarmSuite.TestSwarmClusterRotateUnlockKey
00:38:36 
00:38:36 [d493f54198a98] waiting for daemon to start
00:38:36 [d493f54198a98] daemon started
00:38:36 
00:38:36 [dc92fc5653d7a] waiting for daemon to start
00:38:36 [dc92fc5653d7a] daemon started
00:38:36 
00:38:36 [d8b4ef3bea178] waiting for daemon to start
00:38:36 [d8b4ef3bea178] daemon started
00:38:36 
00:38:36 [dc92fc5653d7a] exiting daemon
00:38:36 [dc92fc5653d7a] waiting for daemon to start
00:38:36 [dc92fc5653d7a] daemon started
00:38:36 
00:38:36 [d8b4ef3bea178] exiting daemon
00:38:36 [d8b4ef3bea178] waiting for daemon to start
00:38:36 [d8b4ef3bea178] daemon started
00:38:36 
00:38:36 docker_cli_swarm_test.go:1449:
00:38:36     c.Assert(err, checker.IsNil)
00:38:36 ... value *exec.ExitError = &exec.ExitError{ProcessState:(*os.ProcessState)(0xc4200f3320), Stderr:[]uint8(nil)} ("exit status 1")
00:38:36 
00:38:36 [d493f54198a98] exiting daemon
00:38:36 [dc92fc5653d7a] exiting daemon
00:38:36 [d8b4ef3bea178] exiting daemon
00:38:39 

Janky failure (https://jenkins.dockerproject.org/job/Docker-PRs/48959/console) also is a flaky test (tracked through #36501)

00:07:29 ----------------------------------------------------------------------
00:07:29 FAIL: docker_api_swarm_service_test.go:33: DockerSwarmSuite.TestAPIServiceUpdatePort
00:07:29 
00:07:29 [dca597a0c87c9] waiting for daemon to start
00:07:29 [dca597a0c87c9] daemon started
00:07:29 
00:07:29 docker_api_swarm_service_test.go:39:
00:07:29     waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
00:07:29 docker_utils_test.go:452:
00:07:29     c.Assert(v, checker, args...)
00:07:29 ... obtained int = 0
00:07:29 ... expected int = 1
00:07:29 
00:07:29 [dca597a0c87c9] exiting daemon
00:07:41

00:32:05 ----------------------------------------------------------------------
00:32:05 FAIL: docker_cli_swarm_test.go:1605: DockerSwarmSuite.TestSwarmPublishDuplicatePorts
00:32:05 
00:32:05 [da8a42e3e8a98] waiting for daemon to start
00:32:05 [da8a42e3e8a98] daemon started
00:32:05 
00:32:05 docker_cli_swarm_test.go:1613:
00:32:05     // make sure task has been deployed.
00:32:05     waitAndAssert(c, defaultReconciliationTimeout, d.CheckActiveContainerCount, checker.Equals, 1)
00:32:05 docker_utils_test.go:452:
00:32:05     c.Assert(v, checker, args...)
00:32:05 ... obtained int = 0
00:32:05 ... expected int = 1
00:32:05 
00:32:05 [da8a42e3e8a98] exiting daemon
00:32:07  

s390 actually passed

00:56:25 OK: 1488 passed, 80 skipped
00:56:25 PASS
03:55:56 Archiving artifacts
03:56:21 Notifying endpoint with url 'https://leeroy.dockerproject.org/notification/jenkins'
03:56:22 Finished: ABORTED

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Standardize format/properties of storage-driver log messages

9 participants