From 2d964bdc959d3d0c2f1b5ca457be7d264a80e3fd Mon Sep 17 00:00:00 2001 From: Matthias Radestock Date: Mon, 21 Mar 2016 18:07:42 +0000 Subject: [PATCH 1/5] don't log in cni; just return errors CNI is invoked from the command line; so there is no point in getting clever about logging. --- plugin/net/cni.go | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/plugin/net/cni.go b/plugin/net/cni.go index 95977e10..8d529b10 100644 --- a/plugin/net/cni.go +++ b/plugin/net/cni.go @@ -35,7 +35,7 @@ func loadNetConf(bytes []byte) (*NetConf, error) { BrName: "weave", } if err := json.Unmarshal(bytes, n); err != nil { - return nil, errorf("failed to load netconf: %v", err) + return nil, fmt.Errorf("failed to load netconf: %v", err) } return n, nil } @@ -47,10 +47,10 @@ func (c *CNIPlugin) CmdAdd(args *skel.CmdArgs) error { } if conf.IsGW { - return errorf("Gateway functionality not supported") + return fmt.Errorf("Gateway functionality not supported") } if conf.IPMasq { - return errorf("IP Masquerading functionality not supported") + return fmt.Errorf("IP Masquerading functionality not supported") } ns, err := netns.GetFromPath(args.Netns) @@ -83,11 +83,11 @@ func (c *CNIPlugin) CmdAdd(args *skel.CmdArgs) error { return cleanup(err) } if err = netlink.LinkSetNsFd(guest, int(ns)); err != nil { - return cleanup(errorf("failed to move veth to container netns: %s", err)) + return cleanup(fmt.Errorf("failed to move veth to container netns: %s", err)) } if err := netlink.LinkSetUp(local); err != nil { - return cleanup(errorf("unable to bring veth up: %s", err)) + return cleanup(fmt.Errorf("unable to bring veth up: %s", err)) } var result *types.Result @@ -98,10 +98,10 @@ func (c *CNIPlugin) CmdAdd(args *skel.CmdArgs) error { result, err = ipam.ExecAdd(conf.IPAM.Type, args.StdinData) } if err != nil { - return cleanup(errorf("unable to allocate IP address: %s", err)) + return cleanup(fmt.Errorf("unable to allocate IP address: %s", err)) } if result.IP4 == nil { - return cleanup(errorf("IPAM plugin failed to allocate IP address")) + return cleanup(fmt.Errorf("IPAM plugin failed to allocate IP address")) } // If config says nothing about routes or gateway, default one will be via the bridge @@ -117,7 +117,7 @@ func (c *CNIPlugin) CmdAdd(args *skel.CmdArgs) error { return setupGuestIP4(local.PeerName, args.IfName, result.IP4.IP, result.IP4.Gateway, result.IP4.Routes) }) if err != nil { - return cleanup(errorf("error setting up interface: %s", err)) + return cleanup(fmt.Errorf("error setting up interface: %s", err)) } result.DNS = conf.DNS @@ -216,7 +216,7 @@ func (c *CNIPlugin) CmdDel(args *skel.CmdArgs) error { return netlink.LinkDel(link) }) if err != nil { - return errorf("error removing interface: %s", err) + return fmt.Errorf("error removing interface: %s", err) } // Default IPAM is Weave's own @@ -226,7 +226,7 @@ func (c *CNIPlugin) CmdDel(args *skel.CmdArgs) error { err = ipam.ExecDel(conf.IPAM.Type, args.StdinData) } if err != nil { - return errorf("unable to release IP address: %s", err) + return fmt.Errorf("unable to release IP address: %s", err) } return nil } From de8c1d262fdd0338d6086ba213f4c1c2176c05ee Mon Sep 17 00:00:00 2001 From: Matthias Radestock Date: Thu, 24 Mar 2016 18:52:07 +0000 Subject: [PATCH 2/5] don't error log in 'createAndAttach' It is a library function, so logging of any errors should be left to the caller. We also get rid of a logged warning which contained the complete data structure returned by netlink.LinkByName. So this function now does no logging at all. Which is how it should be. --- plugin/net/driver.go | 17 ++++++++--------- 1 file changed, 8 insertions(+), 9 deletions(-) diff --git a/plugin/net/driver.go b/plugin/net/driver.go index 661a6b03..6f0cc4a2 100644 --- a/plugin/net/driver.go +++ b/plugin/net/driver.go @@ -109,7 +109,7 @@ func (driver *driver) EndpointInfo(req *api.EndpointInfoRequest) (*api.EndpointI func (driver *driver) JoinEndpoint(j *api.JoinRequest) (*api.JoinResponse, error) { local, err := createAndAttach(j.EndpointID, WeaveBridge, 0) if err != nil { - return nil, err + return nil, errorf("%s", err) } if err := netlink.LinkSetUp(local); err != nil { @@ -139,7 +139,7 @@ func (driver *driver) JoinEndpoint(j *api.JoinRequest) (*api.JoinResponse, error func createAndAttach(id, bridgeName string, mtu int) (*netlink.Veth, error) { maybeBridge, err := netlink.LinkByName(bridgeName) if err != nil { - return nil, errorf(`bridge "%s" not present; did you launch weave?`, bridgeName) + return nil, fmt.Errorf(`bridge "%s" not present; did you launch weave?`, bridgeName) } local := vethPair(id[:5]) @@ -149,29 +149,28 @@ func createAndAttach(id, bridgeName string, mtu int) (*netlink.Veth, error) { local.Attrs().MTU = mtu } if err := netlink.LinkAdd(local); err != nil { - return nil, errorf(`could not create veth pair %s-%s: %s`, local.Name, local.PeerName, err) + return nil, fmt.Errorf(`could not create veth pair %s-%s: %s`, local.Name, local.PeerName, err) } switch maybeBridge.(type) { case *netlink.Bridge: if err := netlink.LinkSetMasterByIndex(local, maybeBridge.Attrs().Index); err != nil { - return nil, errorf(`unable to set master of %s: %s`, local.Name, err) + return nil, fmt.Errorf(`unable to set master of %s: %s`, local.Name, err) } case *netlink.GenericLink: if maybeBridge.Type() != "openvswitch" { - return nil, errorf(`device "%s" is of type "%s"`, bridgeName, maybeBridge.Type()) + return nil, fmt.Errorf(`device "%s" is of type "%s"`, bridgeName, maybeBridge.Type()) } if err := odp.AddDatapathInterface(bridgeName, local.Name); err != nil { - return nil, errorf(`failed to attach %s to device "%s": %s`, local.Name, bridgeName, err) + return nil, fmt.Errorf(`failed to attach %s to device "%s": %s`, local.Name, bridgeName, err) } case *netlink.Device: - Log.Warnf("kernel does not report what kind of device %s is, just %+v", bridgeName, maybeBridge) // Assume it's our openvswitch device, and the kernel has not been updated to report the kind. if err := odp.AddDatapathInterface(bridgeName, local.Name); err != nil { - return nil, errorf(`failed to attach %s to device "%s": %s`, local.Name, bridgeName, err) + return nil, fmt.Errorf(`failed to attach %s to device "%s": %s`, local.Name, bridgeName, err) } default: - return nil, errorf(`device "%s" is not a bridge`, bridgeName) + return nil, fmt.Errorf(`device "%s" is not a bridge`, bridgeName) } return local, nil } From 984cad5b58cb9e1bcbe9eefe4256f020bc4ace1c Mon Sep 17 00:00:00 2001 From: Matthias Radestock Date: Thu, 24 Mar 2016 18:52:44 +0000 Subject: [PATCH 3/5] clean up network plugin logging Consistency, consistency, consistency: - prefix all log messages with "[net]" - important since the same process acts as both a network and ipam driver - include the API function name in all log messages - log request and response details at debug level - log request summary at info level - log ContainerStarted as a pseudo API function, but only at debug level (since it can be quite high volume) And eliminate some dot imports. --- plugin/net/driver.go | 76 +++++++++++++++++++++++++++---------------- plugin/net/watcher.go | 7 ++-- 2 files changed, 51 insertions(+), 32 deletions(-) diff --git a/plugin/net/driver.go b/plugin/net/driver.go index 6f0cc4a2..751e10ae 100644 --- a/plugin/net/driver.go +++ b/plugin/net/driver.go @@ -7,13 +7,12 @@ import ( "github.com/docker/libnetwork/drivers/remote/api" "github.com/docker/libnetwork/types" + "github.com/vishvananda/netlink" weaveapi "github.com/weaveworks/weave/api" - . "github.com/weaveworks/weave/common" + "github.com/weaveworks/weave/common" "github.com/weaveworks/weave/common/docker" "github.com/weaveworks/weave/common/odp" "github.com/weaveworks/weave/plugin/skel" - - "github.com/vishvananda/netlink" ) const ( @@ -41,52 +40,45 @@ func New(client *docker.Client, weave *weaveapi.Client, scope string, noMulticas return driver, nil } -func errorf(format string, a ...interface{}) error { - Log.Errorf(format, a...) - return fmt.Errorf(format, a...) -} - // === protocol handlers func (driver *driver) GetCapabilities() (*api.GetCapabilityResponse, error) { + driver.logReq("GetCapabilities", nil, "") var caps = &api.GetCapabilityResponse{ Scope: driver.scope, } - Log.Debugf("Get capabilities: responded with %+v", caps) + driver.logRes("GetCapabilities", caps) return caps, nil } func (driver *driver) CreateNetwork(create *api.CreateNetworkRequest) error { - Log.Debugf("Create network request %+v", create) - Log.Infof("Create network %s", create.NetworkID) + driver.logReq("CreateNetwork", create, create.NetworkID) return nil } func (driver *driver) DeleteNetwork(delete *api.DeleteNetworkRequest) error { - Log.Debugf("Delete network request: %+v", delete) - Log.Infof("Destroy network %s", delete.NetworkID) + driver.logReq("DeleteNetwork", delete, delete.NetworkID) return nil } func (driver *driver) CreateEndpoint(create *api.CreateEndpointRequest) (*api.CreateEndpointResponse, error) { - Log.Debugf("Create endpoint request %+v", create) + driver.logReq("CreateEndpoint", create, create.EndpointID) endID := create.EndpointID if create.Interface == nil { - return nil, fmt.Errorf("Not supported: creating an interface from within CreateEndpoint") + return nil, driver.error("CreateEndpoint", "Not supported: creating an interface from within CreateEndpoint") } driver.Lock() driver.endpoints[endID] = struct{}{} driver.Unlock() resp := &api.CreateEndpointResponse{} - Log.Infof("Create endpoint %s %+v", endID, resp) + driver.logRes("CreateEndpoint", resp) return resp, nil } func (driver *driver) DeleteEndpoint(deleteReq *api.DeleteEndpointRequest) error { - Log.Debugf("Delete endpoint request: %+v", deleteReq) - Log.Infof("Delete endpoint %s", deleteReq.EndpointID) + driver.logReq("DeleteEndpoint", deleteReq, deleteReq.EndpointID) driver.Lock() delete(driver.endpoints, deleteReq.EndpointID) driver.Unlock() @@ -101,19 +93,20 @@ func (driver *driver) HasEndpoint(endpointID string) bool { } func (driver *driver) EndpointInfo(req *api.EndpointInfoRequest) (*api.EndpointInfoResponse, error) { - Log.Debugf("Endpoint info request: %+v", req) - Log.Infof("Endpoint info %s", req.EndpointID) + driver.logReq("EndpointInfo", req, req.EndpointID) return &api.EndpointInfoResponse{Value: map[string]interface{}{}}, nil } func (driver *driver) JoinEndpoint(j *api.JoinRequest) (*api.JoinResponse, error) { + driver.logReq("JoinEndpoint", j, fmt.Sprintf("%s:%s to %s", j.NetworkID, j.EndpointID, j.SandboxKey)) + local, err := createAndAttach(j.EndpointID, WeaveBridge, 0) if err != nil { - return nil, errorf("%s", err) + return nil, driver.error("JoinEndpoint", "%s", err) } if err := netlink.LinkSetUp(local); err != nil { - return nil, errorf("unable to bring up veth %s-%s: %s", local.Name, local.PeerName, err) + return nil, driver.error("JoinEndpoint", "unable to bring up veth %s-%s: %s", local.Name, local.PeerName, err) } ifname := &api.InterfaceName{ @@ -131,7 +124,7 @@ func (driver *driver) JoinEndpoint(j *api.JoinRequest) (*api.JoinResponse, error } response.StaticRoutes = append(response.StaticRoutes, multicastRoute) } - Log.Infof("Join endpoint %s:%s to %s", j.NetworkID, j.EndpointID, j.SandboxKey) + driver.logRes("JoinEndpoint", response) return response, nil } @@ -176,23 +169,22 @@ func createAndAttach(id, bridgeName string, mtu int) (*netlink.Veth, error) { } func (driver *driver) LeaveEndpoint(leave *api.LeaveRequest) error { - Log.Debugf("Leave request: %+v", leave) + driver.logReq("LeaveEndpoint", leave, fmt.Sprintf("%s:%s", leave.NetworkID, leave.EndpointID)) local := vethPair(leave.EndpointID[:5]) if err := netlink.LinkDel(local); err != nil { - Log.Warningf("unable to delete veth on leave: %s", err) + driver.warn("LeaveEndpoint", "unable to delete veth: %s", err) } - Log.Infof("Leave %s:%s", leave.NetworkID, leave.EndpointID) return nil } func (driver *driver) DiscoverNew(disco *api.DiscoveryNotification) error { - Log.Debugf("Discovery new notification: %+v", disco) + driver.logReq("DiscoverNew", disco, "") return nil } func (driver *driver) DiscoverDelete(disco *api.DiscoveryNotification) error { - Log.Debugf("Discovery delete notification: %+v", disco) + driver.logReq("DiscoverDelete", disco, "") return nil } @@ -204,3 +196,31 @@ func vethPair(suffix string) *netlink.Veth { PeerName: "vethwg" + suffix, } } + +// logging + +func (driver *driver) logReq(fun string, req interface{}, short string) { + driver.log(common.Log.Debugf, " %+v", fun, req) + common.Log.Infof("[net] %s %s", fun, short) +} + +func (driver *driver) logRes(fun string, res interface{}) { + driver.log(common.Log.Debugf, " %+v", fun, res) +} + +func (driver *driver) warn(fun string, format string, a ...interface{}) { + driver.log(common.Log.Warnf, ": "+format, fun, a...) +} + +func (driver *driver) debug(fun string, format string, a ...interface{}) { + driver.log(common.Log.Debugf, ": "+format, fun, a...) +} + +func (driver *driver) error(fun string, format string, a ...interface{}) error { + driver.log(common.Log.Errorf, ": "+format, fun, a...) + return fmt.Errorf(format, a...) +} + +func (driver *driver) log(f func(string, ...interface{}), format string, fun string, a ...interface{}) { + f("[net] %s"+format, append([]interface{}{fun}, a...)...) +} diff --git a/plugin/net/watcher.go b/plugin/net/watcher.go index 4f8ec364..a3cfc4cd 100644 --- a/plugin/net/watcher.go +++ b/plugin/net/watcher.go @@ -4,7 +4,6 @@ import ( "fmt" weaveapi "github.com/weaveworks/weave/api" - . "github.com/weaveworks/weave/common" "github.com/weaveworks/weave/common/docker" ) @@ -27,10 +26,10 @@ func NewWatcher(client *docker.Client, weave *weaveapi.Client, driver *driver) ( } func (w *watcher) ContainerStarted(id string) { - Log.Debugf("Container %s started", id) + w.driver.debug("ContainerStarted", "%s", id) info, err := w.client.InspectContainer(id) if err != nil { - Log.Warningf("error inspecting container %s: %s", id, err) + w.driver.warn("ContainerStarted", "error inspecting container %s: %s", id, err) return } // check that it's on our network, via the endpointID @@ -38,7 +37,7 @@ func (w *watcher) ContainerStarted(id string) { if w.driver.HasEndpoint(net.EndpointID) { fqdn := fmt.Sprintf("%s.%s", info.Config.Hostname, info.Config.Domainname) if err := w.weave.RegisterWithDNS(id, fqdn, net.IPAddress); err != nil { - Log.Warningf("unable to register %s with weaveDNS: %s", id, err) + w.driver.warn("ContainerStarted", "unable to register %s with weaveDNS: %s", id, err) } } } From 5aa2a7a14ceea290bf6f504088d4cd04bc06dc82 Mon Sep 17 00:00:00 2001 From: Matthias Radestock Date: Mon, 21 Mar 2016 17:14:13 +0000 Subject: [PATCH 4/5] refactor(ish) of ipam plugin logging prefix all log entries with "[ipam]" Also eliminate a dot import. --- plugin/ipam/driver.go | 26 ++++++++++++++++++-------- 1 file changed, 18 insertions(+), 8 deletions(-) diff --git a/plugin/ipam/driver.go b/plugin/ipam/driver.go index 79ab1077..a4c0350e 100644 --- a/plugin/ipam/driver.go +++ b/plugin/ipam/driver.go @@ -8,7 +8,7 @@ import ( "github.com/docker/libnetwork/discoverapi" "github.com/docker/libnetwork/netlabel" "github.com/weaveworks/weave/api" - . "github.com/weaveworks/weave/common" + "github.com/weaveworks/weave/common" ) type Ipam struct { @@ -20,13 +20,13 @@ func NewIpam(weave *api.Client) *Ipam { } func (i *Ipam) GetDefaultAddressSpaces() (string, string, error) { - Log.Debugln("GetDefaultAddressSpaces") + i.logReq("GetDefaultAddressSpaces") return "weavelocal", "weaveglobal", nil } func (i *Ipam) RequestPool(addressSpace, pool, subPool string, options map[string]string, v6 bool) (poolname string, subnet *net.IPNet, data map[string]string, err error) { - Log.Debugln("RequestPool", addressSpace, pool, subPool, options) - defer func() { Log.Debugln("RequestPool returning", poolname, subnet, data, err) }() + i.logReq("RequestPool", addressSpace, pool, subPool, options) + defer func() { i.logRes("RequestPool", poolname, subnet, data, err) }() if pool == "" { subnet, err = i.weave.DefaultSubnet() } else { @@ -50,13 +50,13 @@ func (i *Ipam) RequestPool(addressSpace, pool, subPool string, options map[strin } func (i *Ipam) ReleasePool(poolID string) error { - Log.Debugln("ReleasePool", poolID) + i.logReq("ReleasePool", poolID) return nil } func (i *Ipam) RequestAddress(poolID string, address net.IP, options map[string]string) (ip *net.IPNet, _ map[string]string, err error) { - Log.Debugln("RequestAddress", poolID, address, options) - defer func() { Log.Debugln("allocateIP returned", ip, err) }() + i.logReq("RequestAddress", poolID, address, options) + defer func() { i.logRes("RequestAddress", ip, err) }() // If we pass magic string "_" to weave IPAM it stores the address under its own string if poolID == "weavepool" { // old-style ip, err = i.weave.AllocateIP("_") @@ -90,7 +90,7 @@ func (i *Ipam) RequestAddress(poolID string, address net.IP, options map[string] } func (i *Ipam) ReleaseAddress(poolID string, address net.IP) error { - Log.Debugln("ReleaseAddress", poolID, address) + i.logReq("ReleaseAddress", poolID, address) return i.weave.ReleaseIPsFor(address.String()) } @@ -103,3 +103,13 @@ func (i *Ipam) DiscoverNew(discoverapi.DiscoveryType, interface{}) error { func (i *Ipam) DiscoverDelete(discoverapi.DiscoveryType, interface{}) error { return nil } + +// logging + +func (i *Ipam) logReq(fun string, args ...interface{}) { + common.Log.Debugln(append([]interface{}{fmt.Sprintf("[ipam] %s", fun)}, args...)...) +} + +func (i *Ipam) logRes(fun string, args ...interface{}) { + common.Log.Debugln(append([]interface{}{fmt.Sprintf("[ipam] %s result", fun)}, args...)...) +} From 4482d307bf9f79c8d9c4c66864a7e2d35835247f Mon Sep 17 00:00:00 2001 From: Matthias Radestock Date: Mon, 21 Mar 2016 17:16:03 +0000 Subject: [PATCH 5/5] tweak ipam plugin logging - log requests at info level instead of debug level - log errors at error level instead of debug level --- plugin/ipam/driver.go | 14 +++++++++----- 1 file changed, 9 insertions(+), 5 deletions(-) diff --git a/plugin/ipam/driver.go b/plugin/ipam/driver.go index a4c0350e..60b25471 100644 --- a/plugin/ipam/driver.go +++ b/plugin/ipam/driver.go @@ -26,7 +26,7 @@ func (i *Ipam) GetDefaultAddressSpaces() (string, string, error) { func (i *Ipam) RequestPool(addressSpace, pool, subPool string, options map[string]string, v6 bool) (poolname string, subnet *net.IPNet, data map[string]string, err error) { i.logReq("RequestPool", addressSpace, pool, subPool, options) - defer func() { i.logRes("RequestPool", poolname, subnet, data, err) }() + defer func() { i.logRes("RequestPool", err, poolname, subnet, data) }() if pool == "" { subnet, err = i.weave.DefaultSubnet() } else { @@ -56,7 +56,7 @@ func (i *Ipam) ReleasePool(poolID string) error { func (i *Ipam) RequestAddress(poolID string, address net.IP, options map[string]string) (ip *net.IPNet, _ map[string]string, err error) { i.logReq("RequestAddress", poolID, address, options) - defer func() { i.logRes("RequestAddress", ip, err) }() + defer func() { i.logRes("RequestAddress", err, ip) }() // If we pass magic string "_" to weave IPAM it stores the address under its own string if poolID == "weavepool" { // old-style ip, err = i.weave.AllocateIP("_") @@ -107,9 +107,13 @@ func (i *Ipam) DiscoverDelete(discoverapi.DiscoveryType, interface{}) error { // logging func (i *Ipam) logReq(fun string, args ...interface{}) { - common.Log.Debugln(append([]interface{}{fmt.Sprintf("[ipam] %s", fun)}, args...)...) + common.Log.Infoln(append([]interface{}{fmt.Sprintf("[ipam] %s", fun)}, args...)...) } -func (i *Ipam) logRes(fun string, args ...interface{}) { - common.Log.Debugln(append([]interface{}{fmt.Sprintf("[ipam] %s result", fun)}, args...)...) +func (i *Ipam) logRes(fun string, err error, args ...interface{}) { + if err == nil { + common.Log.Debugln(append([]interface{}{fmt.Sprintf("[ipam] %s result", fun)}, args...)...) + return + } + common.Log.Errorf("[ipam] %s: %s", fun, err) }