diff --git a/.gitignore b/.gitignore index 6c9406eb..609b440f 100644 --- a/.gitignore +++ b/.gitignore @@ -39,9 +39,10 @@ prog/netcheck/netcheck tools/bin tools/build releases +.weaver.uptodate +.weavedns.uptodate +.weaveexec.uptodate weave.tar -weavedns.tar -weaveexec.tar prog/weaveexec/weave prog/weaveexec/weaveproxy prog/weaveexec/weavewait diff --git a/Makefile b/Makefile index bfd649ee..37c7871c 100644 --- a/Makefile +++ b/Makefile @@ -18,27 +18,29 @@ NETCHECK_EXE=prog/netcheck/netcheck EXES=$(WEAVER_EXE) $(WEAVEDNS_EXE) $(SIGPROXY_EXE) $(WEAVEPROXY_EXE) $(WEAVEWAIT_EXE) $(NETCHECK_EXE) +WEAVER_UPTODATE=.weaver.uptodate +WEAVEDNS_UPTODATE=.weavedns.uptodate +WEAVEEXEC_UPTODATE=.weaveexec.uptodate + +IMAGES_UPTODATE=$(WEAVER_UPTODATE) $(WEAVEDNS_UPTODATE) $(WEAVEEXEC_UPTODATE) + WEAVER_IMAGE=$(DOCKERHUB_USER)/weave WEAVEDNS_IMAGE=$(DOCKERHUB_USER)/weavedns WEAVEEXEC_IMAGE=$(DOCKERHUB_USER)/weaveexec IMAGES=$(WEAVER_IMAGE) $(WEAVEDNS_IMAGE) $(WEAVEEXEC_IMAGE) -WEAVER_EXPORT=weave.tar -WEAVEDNS_EXPORT=weavedns.tar -WEAVEEXEC_EXPORT=weaveexec.tar - -EXPORTS=$(WEAVER_EXPORT) $(WEAVEDNS_EXPORT) $(WEAVEEXEC_EXPORT) +WEAVE_EXPORT=weave.tar WEAVEEXEC_DOCKER_VERSION=1.3.1 DOCKER_DISTRIB=prog/weaveexec/docker-$(WEAVEEXEC_DOCKER_VERSION).tgz DOCKER_DISTRIB_URL=https://get.docker.com/builds/Linux/x86_64/docker-$(WEAVEEXEC_DOCKER_VERSION).tgz -all: $(EXPORTS) +all: $(WEAVE_EXPORT) travis: $(EXES) -update: $(EXES) +update: go get -u -f -v -tags -netgo $(addprefix ./,$(dir $(EXES))) $(WEAVER_EXE) $(WEAVEDNS_EXE) $(WEAVEPROXY_EXE) $(NETCHECK_EXE): common/*.go common/*/*.go net/*.go @@ -56,6 +58,7 @@ $(WEAVER_EXE) $(WEAVEDNS_EXE) $(WEAVEPROXY_EXE) $(NETCHECK_EXE): common/*.go com $(WEAVER_EXE): router/*.go ipam/*.go ipam/*/*.go prog/weaver/main.go $(WEAVEDNS_EXE): nameserver/*.go prog/weavedns/main.go $(WEAVEPROXY_EXE): proxy/*.go prog/weaveproxy/main.go +$(NETCHECK_EXE): prog/netcheck/netcheck.go # Sigproxy and weavewait need separate rules as they fail the netgo check in # the main build stanza due to not importing net package @@ -66,15 +69,15 @@ $(SIGPROXY_EXE): prog/sigproxy/main.go $(WEAVEWAIT_EXE): prog/weavewait/main.go go build -o $@ ./$(@D) -$(WEAVER_EXPORT): prog/weaver/Dockerfile $(WEAVER_EXE) +$(WEAVER_UPTODATE): prog/weaver/Dockerfile $(WEAVER_EXE) $(SUDO) docker build -t $(WEAVER_IMAGE) prog/weaver - $(SUDO) docker save $(WEAVER_IMAGE):latest > $@ + touch $@ -$(WEAVEDNS_EXPORT): prog/weavedns/Dockerfile $(WEAVEDNS_EXE) +$(WEAVEDNS_UPTODATE): prog/weavedns/Dockerfile $(WEAVEDNS_EXE) $(SUDO) docker build -t $(WEAVEDNS_IMAGE) prog/weavedns - $(SUDO) docker save $(WEAVEDNS_IMAGE):latest > $@ + touch $@ -$(WEAVEEXEC_EXPORT): prog/weaveexec/Dockerfile $(DOCKER_DISTRIB) weave $(SIGPROXY_EXE) $(WEAVEPROXY_EXE) $(WEAVEWAIT_EXE) $(NETCHECK_EXE) +$(WEAVEEXEC_UPTODATE): prog/weaveexec/Dockerfile $(DOCKER_DISTRIB) weave $(SIGPROXY_EXE) $(WEAVEPROXY_EXE) $(WEAVEWAIT_EXE) $(NETCHECK_EXE) cp weave prog/weaveexec/weave cp $(SIGPROXY_EXE) prog/weaveexec/sigproxy cp $(WEAVEPROXY_EXE) prog/weaveexec/weaveproxy @@ -82,24 +85,29 @@ $(WEAVEEXEC_EXPORT): prog/weaveexec/Dockerfile $(DOCKER_DISTRIB) weave $(SIGPROX cp $(NETCHECK_EXE) prog/weaveexec/netcheck cp $(DOCKER_DISTRIB) prog/weaveexec/docker.tgz $(SUDO) docker build -t $(WEAVEEXEC_IMAGE) prog/weaveexec - $(SUDO) docker save $(WEAVEEXEC_IMAGE):latest > $@ + touch $@ + +$(WEAVE_EXPORT): $(IMAGES_UPTODATE) + $(SUDO) docker save $(addsuffix :latest,$(IMAGES)) > $@ $(DOCKER_DISTRIB): curl -o $(DOCKER_DISTRIB) $(DOCKER_DISTRIB_URL) tests: echo "mode: count" > profile.cov - fail=0 ; \ - for dir in $$(find . -type f -name '*_test.go' | xargs -n1 dirname | sort -u); do \ - output=$$(mktemp cover.XXXXXXXXXX) ; \ - if ! go test -cpu 4 -tags netgo -covermode=count -coverprofile=$$output $$dir ; then \ - fail=1 ; \ - fi ; \ - if [ -f $$output ]; then \ - tail -n +2 <$$output >>profile.cov; \ - rm $$output; \ - fi \ - done ; \ + fail=0 ; \ + for dir in $$(find . -type f -name '*_test.go' | xargs -n1 dirname | sort -u); do \ + go get -t -tags netgo $$dir ; \ + output=$$(mktemp cover.XXXXXXXXXX) ; \ + if ! go test -cpu 4 -tags netgo \ + -covermode=count -coverprofile=$$output $$dir ; then \ + fail=1 ; \ + fi ; \ + if [ -f $$output ]; then \ + tail -n +2 <$$output >>profile.cov; \ + rm $$output; \ + fi \ + done ; \ exit $$fail go tool cover -html=profile.cov -o=coverage.html @@ -112,7 +120,7 @@ publish: $(PUBLISH) clean: -$(SUDO) docker rmi $(IMAGES) - rm -f $(EXES) $(EXPORTS) + rm -f $(EXES) $(IMAGES_UPTODATE) $(WEAVE_EXPORT) rm -f test/tls/*.pem build: diff --git a/README.md b/README.md index 5ac4884d..418986b2 100644 --- a/README.md +++ b/README.md @@ -4,9 +4,14 @@ # About Weaveworks -[Come meet Weaveworks at Dockercon](http://weave.works/dockercon) - -[Weaveworks](http://weave.works) is the company that develops Weave - the most productive way for developers to connect, observe and control Docker containers. To learn about our products, including getting started tutorials, visit our [website](http://weave.works), read about the [1.0 release of Weave](http://blog.weave.works/2015/06/18/weave-1-0-is-out-and-it-is-good/), visit our [documentation](http://docs.weave.works) or continue to read about some of the more technical aspects of Weave in this readme. +[Weaveworks](http://weave.works) is the company that develops Weave - +the most productive way for developers to connect, observe and control +Docker containers. To learn about our products, including getting +started tutorials, visit our [website](http://weave.works), read about +the +[1.0 release of Weave](http://blog.weave.works/2015/06/18/weave-1-0-is-out-and-it-is-good/), +visit our [documentation](http://docs.weave.works) or continue to read +about some of the more technical aspects of Weave in this readme. # Weave diff --git a/build/Dockerfile b/build/Dockerfile index 562673c8..23861bdf 100644 --- a/build/Dockerfile +++ b/build/Dockerfile @@ -1,6 +1,9 @@ FROM ubuntu -RUN apt-get -y update && apt-get -y install --no-install-recommends build-essential git ca-certificates docker.io mercurial libpcap-dev curl make pkg-config gcc bison flex +RUN apt-get -y update && apt-get -y install --no-install-recommends ca-certificates apt-transport-https +RUN apt-key adv --keyserver hkp://keyserver.ubuntu.com:80 --recv-keys 36A1D7869245C8950F966E92D8576A8BA88D21E9 +RUN echo deb https://get.docker.io/ubuntu docker main > /etc/apt/sources.list.d/docker.list +RUN apt-get -y update && apt-get -y install --no-install-recommends build-essential git lxc-docker-1.3.1 mercurial libpcap-dev curl make pkg-config gcc bison flex # When doing a build in a container, "apt-get update" happens twice, # which can be a very significant overhead for incremental builds. diff --git a/common/docker/client.go b/common/docker/client.go index bb96cf29..71cdf316 100644 --- a/common/docker/client.go +++ b/common/docker/client.go @@ -36,7 +36,7 @@ func NewClient(apiPath string) (*Client, error) { if err != nil { return nil, err } - Info.Printf("[docker] Using Docker API on %s: %v", apiPath, env) + Log.Infof("[docker] Using Docker API on %s: %v", apiPath, env) return client, nil } @@ -44,7 +44,7 @@ func NewClient(apiPath string) (*Client, error) { func (c *Client) AddObserver(ob ContainerObserver) error { events := make(chan *docker.APIEvents) if err := c.AddEventListener(events); err != nil { - Error.Printf("[docker] Unable to add listener to Docker API: %s", err) + Log.Errorf("[docker] Unable to add listener to Docker API: %s", err) return err } @@ -63,7 +63,7 @@ func (c *Client) AddObserver(ob ContainerObserver) error { // IsContainerNotRunning returns true if we have checked with Docker that the ID is not running func (c *Client) IsContainerNotRunning(idStr string) bool { if !IsContainerID(idStr) { - Debug.Printf("[docker] '%s' does not seem to be a container id", idStr) + Log.Debugf("[docker] '%s' does not seem to be a container id", idStr) return false } @@ -75,6 +75,6 @@ func (c *Client) IsContainerNotRunning(idStr string) bool { if _, notThere := err.(*docker.NoSuchContainer); notThere { return true } - Error.Printf("[docker] Could not check container status: %s", err) + Log.Errorf("[docker] Could not check container status: %s", err) return false } diff --git a/common/errors.go b/common/errors.go index a0a9cc96..ea6fed41 100644 --- a/common/errors.go +++ b/common/errors.go @@ -2,13 +2,13 @@ package common func CheckFatal(e error) { if e != nil { - Error.Fatal(e) + Log.Fatal(e) } } func CheckWarn(e error) { if e != nil { - Warning.Println(e) + Log.Warningln(e) } } diff --git a/common/init.go b/common/init.go index 0e1968f7..297a339e 100644 --- a/common/init.go +++ b/common/init.go @@ -1,10 +1,5 @@ package common -import ( - "io/ioutil" - "os" -) - func init() { - InitLogging(ioutil.Discard, os.Stdout, os.Stdout, os.Stderr) + InitDefaultLogging(false) } diff --git a/common/logging.go b/common/logging.go index 8def1602..e2ef9d1a 100644 --- a/common/logging.go +++ b/common/logging.go @@ -1,46 +1,62 @@ package common import ( - "io" - "io/ioutil" - "log" + "bytes" + "fmt" "os" + "strings" + + "github.com/Sirupsen/logrus" ) -const ( - standardLogFlags = log.Ldate | log.Ltime | log.Lmicroseconds -) +type textFormatter struct { +} -// Largely taken from -// http://www.goinggo.net/2013/11/using-log-package-in-go.html +// Based off logrus.TextFormatter, which behaves completely +// differently when you don't want colored output +func (f *textFormatter) Format(entry *logrus.Entry) ([]byte, error) { + b := &bytes.Buffer{} + + levelText := strings.ToUpper(entry.Level.String())[0:4] + timeStamp := entry.Time.Format("2006/01/02 15:04:05.000000") + if len(entry.Data) > 0 { + fmt.Fprintf(b, "%s: %s %-44s ", levelText, timeStamp, entry.Message) + for k, v := range entry.Data { + fmt.Fprintf(b, " %s=%v", k, v) + } + } else { + // No padding when there's no fields + fmt.Fprintf(b, "%s: %s %s", levelText, timeStamp, entry.Message) + } + + b.WriteByte('\n') + return b.Bytes(), nil +} var ( - Debug *log.Logger - Info *log.Logger - Warning *log.Logger - Error *log.Logger - debugF bool + standardTextFormatter = &textFormatter{} ) -func InitLogging(debugHandle io.Writer, - infoHandle io.Writer, - warningHandle io.Writer, - errorHandle io.Writer) { +var ( + Log *logrus.Logger +) - Debug = log.New(debugHandle, "DEBUG: ", standardLogFlags) - Info = log.New(infoHandle, "INFO: ", standardLogFlags) - Warning = log.New(warningHandle, "WARNING: ", standardLogFlags) - Error = log.New(errorHandle, "ERROR: ", standardLogFlags) +func InitLogging(level logrus.Level) { + if Log == nil { + Log = &logrus.Logger{ + Out: os.Stderr, + Formatter: standardTextFormatter, + Hooks: make(logrus.LevelHooks), + Level: level, + } + } + Log.Level = level } func InitDefaultLogging(debug bool) { - if debug == debugF { - return - } - debugF = debug - debugOut := ioutil.Discard + level := logrus.InfoLevel if debug { - debugOut = os.Stderr + level = logrus.DebugLevel } - InitLogging(debugOut, os.Stdout, os.Stdout, os.Stderr) + InitLogging(level) } diff --git a/common/sched_queue.go b/common/sched_queue.go index 26e7bd49..cbfc9eb3 100644 --- a/common/sched_queue.go +++ b/common/sched_queue.go @@ -76,7 +76,7 @@ func NewSchedQueue(clock clock.Clock) *SchedQueue { // Start starts the scheduled queue func (cq *SchedQueue) Start() { go func() { - defer func() { Debug.Printf("[sched-q] Quitting (%d calls pending)", len(cq.callablesH)) }() + defer func() { Log.Debugf("[sched-q] Quitting (%d calls pending)", len(cq.callablesH)) }() var now time.Time timer := cq.clock.Timer(time.Duration(math.MaxInt64)) @@ -116,14 +116,14 @@ func (cq *SchedQueue) Start() { // Stop stops the scheduled queue func (cq *SchedQueue) Stop() { - Debug.Printf("[sched-q] Stopping...") + Log.Debugf("[sched-q] Stopping...") cq.closeChan <- true } // Add schedules a call. // The callable should not modify the scheduled queue in any way. func (cq *SchedQueue) Add(c callable, t time.Time) { - Debug.Printf("[sched-q] Adding call at %s", t) + Log.Debugf("[sched-q] Adding call at %s", t) ce := schedCall{c: c, t: t} cq.schedChan <- &ce } diff --git a/common/sched_queue_test.go b/common/sched_queue_test.go index 54a89430..5c733355 100644 --- a/common/sched_queue_test.go +++ b/common/sched_queue_test.go @@ -11,7 +11,7 @@ import ( // Ensure we can add new calls while forwarding the clock func TestSchedCallsBasic(t *testing.T) { InitDefaultLogging(testing.Verbose()) - Info.Println("TestSchedCallsBasic starting") + Log.Infoln("TestSchedCallsBasic starting") const testSecs = 1000 clk := clock.NewMock() @@ -37,7 +37,7 @@ func TestSchedCallsBasic(t *testing.T) { // Ensure we can create a 100 seconds gap in the middle of the time travel func TestSchedCallsGap(t *testing.T) { InitDefaultLogging(testing.Verbose()) - Info.Println("TestSchedCallsGap starting") + Log.Infoln("TestSchedCallsGap starting") const testSecs = 1000 clk := clock.NewMock() @@ -65,7 +65,7 @@ func TestSchedCallsGap(t *testing.T) { func TestSchedCallsStop(t *testing.T) { InitDefaultLogging(testing.Verbose()) - Info.Println("TestSchedCallsStop starting") + Log.Infoln("TestSchedCallsStop starting") const testSecs = 1000 clk := clock.NewMock() diff --git a/common/signals.go b/common/signals.go index f92f3f60..e750a8ea 100644 --- a/common/signals.go +++ b/common/signals.go @@ -20,17 +20,17 @@ func SignalHandlerLoop(ss ...SignalReceiver) { for { switch <-sigs { case syscall.SIGINT: - Info.Printf("=== received SIGINT ===\n*** exiting\n") + Log.Infof("=== received SIGINT ===\n*** exiting\n") for _, subsystem := range ss { subsystem.Stop() } return case syscall.SIGQUIT: stacklen := runtime.Stack(buf, true) - Info.Printf("=== received SIGQUIT ===\n*** goroutine dump...\n%s\n*** end\n", buf[:stacklen]) + Log.Infof("=== received SIGQUIT ===\n*** goroutine dump...\n%s\n*** end\n", buf[:stacklen]) case syscall.SIGUSR1: for _, subsystem := range ss { - Info.Printf("=== received SIGUSR1 ===\n*** status...\n%s\n*** end\n", subsystem.Status()) + Log.Infof("=== received SIGUSR1 ===\n*** status...\n%s\n*** end\n", subsystem.Status()) } } } diff --git a/ipam/allocate.go b/ipam/allocate.go index 79fe45dc..0e4a9e4b 100644 --- a/ipam/allocate.go +++ b/ipam/allocate.go @@ -43,9 +43,14 @@ func (g *allocate) Try(alloc *Allocator) bool { } // out of space - if donor, err := alloc.ring.ChoosePeerToAskForSpace(g.r.Start, g.r.End); err == nil { - alloc.debugln("Decided to ask peer", donor, "for space in range", g.r) - alloc.sendSpaceRequest(donor, g.r) + donors := alloc.ring.ChoosePeersToAskForSpace(g.r.Start, g.r.End) + for _, donor := range donors { + if err := alloc.sendSpaceRequest(donor, g.r); err != nil { + alloc.debugln("Problem asking peer", donor, "for space:", err) + } else { + alloc.debugln("Decided to ask peer", donor, "for space in range", g.r) + break + } } return false diff --git a/ipam/allocator.go b/ipam/allocator.go index 8b609b96..a63ecb5b 100644 --- a/ipam/allocator.go +++ b/ipam/allocator.go @@ -575,14 +575,14 @@ func (alloc *Allocator) propose() { alloc.gossip.GossipBroadcast(alloc.Gossip()) } -func (alloc *Allocator) sendSpaceRequest(dest router.PeerName, r address.Range) { +func (alloc *Allocator) sendSpaceRequest(dest router.PeerName, r address.Range) error { buf := new(bytes.Buffer) enc := gob.NewEncoder(buf) if err := enc.Encode(r); err != nil { panic(err) } msg := router.Concat([]byte{msgSpaceRequest}, buf.Bytes()) - alloc.gossip.GossipUnicast(dest, msg) + return alloc.gossip.GossipUnicast(dest, msg) } func (alloc *Allocator) sendRingUpdate(dest router.PeerName) { @@ -718,11 +718,11 @@ func (alloc *Allocator) findOwner(addr address.Address) string { // Logging func (alloc *Allocator) infof(fmt string, args ...interface{}) { - common.Info.Printf("[allocator %s] "+fmt, append([]interface{}{alloc.ourName}, args...)...) + common.Log.Infof("[allocator %s] "+fmt, append([]interface{}{alloc.ourName}, args...)...) } func (alloc *Allocator) debugln(args ...interface{}) { - common.Debug.Println(append([]interface{}{fmt.Sprintf("[allocator %s]:", alloc.ourName)}, args...)...) + common.Log.Debugln(append([]interface{}{fmt.Sprintf("[allocator %s]:", alloc.ourName)}, args...)...) } func (alloc *Allocator) debugf(fmt string, args ...interface{}) { - common.Debug.Printf("[allocator %s] "+fmt, append([]interface{}{alloc.ourName}, args...)...) + common.Log.Debugf("[allocator %s] "+fmt, append([]interface{}{alloc.ourName}, args...)...) } diff --git a/ipam/allocator_test.go b/ipam/allocator_test.go index a8b1a782..fcd3027a 100644 --- a/ipam/allocator_test.go +++ b/ipam/allocator_test.go @@ -168,7 +168,7 @@ func TestCancel(t *testing.T) { CIDR = "10.0.1.7/26" ) - router := TestGossipRouter{make(map[router.PeerName]chan gossipMessage), 0.0} + router := TestGossipRouter{make(map[router.PeerName]chan interface{}), 0.0} alloc1, subnet := makeAllocator("01:00:00:02:00:00", CIDR, 2) alloc1.SetInterfaces(router.connect(alloc1.ourName, alloc1)) @@ -186,9 +186,9 @@ func TestCancel(t *testing.T) { // Get some IPs, so each allocator has some space res1, _ := alloc1.Allocate("foo", subnet, nil) - common.Debug.Printf("res1 = %s", res1.String()) + common.Log.Debugf("res1 = %s", res1.String()) res2, _ := alloc2.Allocate("bar", subnet, nil) - common.Debug.Printf("res2 = %s", res2.String()) + common.Log.Debugf("res2 = %s", res2.String()) if res1 == res2 { require.FailNow(t, "Error: got same ips!") } @@ -256,13 +256,17 @@ func TestTransfer(t *testing.T) { require.True(t, err == nil, "Failed to get address") router.GossipBroadcast(alloc2.Gossip()) + router.flush() router.GossipBroadcast(alloc3.Gossip()) + router.flush() router.removePeer(alloc2.ourName) router.removePeer(alloc3.ourName) alloc2.Stop() alloc3.Stop() + router.flush() require.NoError(t, alloc1.AdminTakeoverRanges(alloc2.ourName.String())) require.NoError(t, alloc1.AdminTakeoverRanges(alloc3.ourName.String())) + router.flush() require.Equal(t, address.Offset(1022), alloc1.NumFreeAddresses(subnet)) @@ -282,7 +286,8 @@ func TestFakeRouterSimple(t *testing.T) { alloc1 := allocs[0] //alloc2 := allocs[1] - alloc1.Allocate("foo", subnet, nil) + _, err := alloc1.Allocate("foo", subnet, nil) + require.NoError(t, err, "Failed to get address") } func TestAllocatorFuzz(t *testing.T) { @@ -338,14 +343,14 @@ func TestAllocatorFuzz(t *testing.T) { allocIndex := rand.Int31n(nodes) alloc := allocs[allocIndex] - //common.Info.Printf("Allocate: asking allocator %d", allocIndex) + //common.Log.Infof("Allocate: asking allocator %d", allocIndex) addr, err := alloc.Allocate(name, subnet, nil) if err != nil { panic(fmt.Sprintf("Could not allocate addr")) } - //common.Info.Printf("Allocate: got address %s for name %s", addr, name) + //common.Log.Infof("Allocate: got address %s for name %s", addr, name) addrStr := addr.String() stateLock.Lock() @@ -382,7 +387,7 @@ func TestAllocatorFuzz(t *testing.T) { stateLock.Unlock() alloc := allocs[res.alloc] - //common.Info.Printf("Freeing %s (%s) on allocator %d", res.name, addr, res.alloc) + //common.Log.Infof("Freeing %s (%s) on allocator %d", res.name, addr, res.alloc) oldAddr, err := address.ParseIP(addr) if err != nil { @@ -407,7 +412,7 @@ func TestAllocatorFuzz(t *testing.T) { stateLock.Unlock() alloc := allocs[res.alloc] - //common.Info.Printf("Asking for %s (%s) on allocator %d again", res.name, addr, res.alloc) + //common.Log.Infof("Asking for %s (%s) on allocator %d again", res.name, addr, res.alloc) newAddr, _ := alloc.Allocate(res.name, subnet, nil) oldAddr, _ := address.ParseIP(addr) diff --git a/ipam/http.go b/ipam/http.go index 8164d8c8..0b665385 100644 --- a/ipam/http.go +++ b/ipam/http.go @@ -13,7 +13,7 @@ import ( func badRequest(w http.ResponseWriter, err error) { http.Error(w, err.Error(), http.StatusBadRequest) - common.Warning.Println("[allocator]:", err.Error()) + common.Log.Warningln("[allocator]:", err.Error()) } // HandleHTTP wires up ipams HTTP endpoints to the provided mux. @@ -79,7 +79,7 @@ func (alloc *Allocator) HandleHTTP(router *mux.Router, defaultSubnet address.CID return } if dockerCli != nil && dockerCli.IsContainerNotRunning(ident) { - common.Info.Printf("[allocator] '%s' is not running: freeing %s", ident, addr) + common.Log.Infof("[allocator] '%s' is not running: freeing %s", ident, addr) alloc.Free(ident, addr) return } @@ -96,7 +96,7 @@ func (alloc *Allocator) HandleHTTP(router *mux.Router, defaultSubnet address.CID return } if dockerCli != nil && dockerCli.IsContainerNotRunning(ident) { - common.Info.Printf("[allocator] '%s' is not running: freeing %s", ident, newAddr) + common.Log.Infof("[allocator] '%s' is not running: freeing %s", ident, newAddr) alloc.Free(ident, newAddr) return } diff --git a/ipam/http_test.go b/ipam/http_test.go index 63c4dbab..f00ea0b2 100644 --- a/ipam/http_test.go +++ b/ipam/http_test.go @@ -48,13 +48,13 @@ func listenHTTP(alloc *Allocator, subnet address.CIDR) int { httpListener, err := net.Listen("tcp", ":0") if err != nil { - common.Error.Fatal("Unable to create http listener: ", err) + common.Log.Fatal("Unable to create http listener: ", err) } go func() { srv := &http.Server{Handler: router} if err := srv.Serve(httpListener); err != nil { - common.Error.Fatal("Unable to serve http: ", err) + common.Log.Fatal("Unable to serve http: ", err) } }() return httpListener.Addr().(*net.TCPAddr).Port diff --git a/ipam/ring/ring.go b/ipam/ring/ring.go index fcdb362e..1d55219e 100644 --- a/ipam/ring/ring.go +++ b/ipam/ring/ring.go @@ -217,7 +217,7 @@ func (r *Ring) Merge(gossip Ring) error { switch { case mine.Version >= theirs.Version: if mine.Version == theirs.Version && !mine.Equal(theirs) { - common.Debug.Printf("Error merging entries at %s - %v != %v\n", mine.Token, mine, theirs) + common.Log.Debugf("Error merging entries at %s - %v != %v\n", mine.Token, mine, theirs) return ErrInvalidEntry } addToResult(*mine) @@ -348,9 +348,9 @@ func (r *Ring) String() string { return buffer.String() } -// ReportFree is used by the allocator to tell the ring -// how many free ips are in a given range, so that ChoosePeerToAskForSpace -// can make more intelligent decisions. +// ReportFree is used by the allocator to tell the ring how many free +// ips are in a given range, so that ChoosePeersToAskForSpace can make +// more intelligent decisions. func (r *Ring) ReportFree(freespace map[address.Address]address.Offset) { r.assertInvariants() defer r.assertInvariants() @@ -392,9 +392,20 @@ func (r *Ring) ReportFree(freespace map[address.Address]address.Offset) { } } -// ChoosePeerToAskForSpace chooses a weighted-random peer to ask -// for space in the range [start, end). Assumes start so that bigger weights sort earlier +func (ws weightedPeers) Less(i, j int) bool { return ws[i].weight > ws[j].weight } +func (ws weightedPeers) Len() int { return len(ws) } +func (ws weightedPeers) Swap(i, j int) { ws[i], ws[j] = ws[j], ws[i] } + +// ChoosePeersToAskForSpace returns all peers we can ask for space in +// the range [start, end), in weighted-random order. Assumes start (1.0 - grouter.loss) { continue } + if err := gossiper.OnGossipUnicast(message.sender, message.buf); err != nil { + panic(fmt.Sprintf("Error doing gossip unicast to %s: %s", message.sender, err)) + } - if message.isUnicast { - if err := gossiper.OnGossipUnicast(*message.sender, message.buf); err != nil { - panic(fmt.Sprintf("Error doing gossip unicast to %s: %s", sender, err)) - } - } else { - for _, msg := range message.data.Encode() { - if _, err := gossiper.OnGossipBroadcast(msg); err != nil { - panic(fmt.Sprintf("Error doing gossip broadcast to %s: %s", sender, err)) - } + case broadcastMessage: + if rand.Float32() > (1.0 - grouter.loss) { + continue + } + for _, msg := range message.data.Encode() { + if _, err := gossiper.OnGossipBroadcast(msg); err != nil { + panic(fmt.Sprintf("Error doing gossip broadcast: %s", err)) } } - case <-gossipTimer: - grouter.GossipBroadcast(gossiper.Gossip()) } + case <-gossipTimer: + grouter.GossipBroadcast(gossiper.Gossip()) } - }() + } +} + +func (grouter *TestGossipRouter) connect(sender router.PeerName, gossiper router.Gossiper) router.Gossip { + gossipChan := make(chan interface{}, 100) + + go grouter.run(gossiper, gossipChan) grouter.gossipChans[sender] = gossipChan return TestGossipRouterClient{grouter, sender} @@ -271,9 +293,9 @@ func (grouter *TestGossipRouter) connect(sender router.PeerName, gossiper router func (client TestGossipRouterClient) GossipUnicast(dstPeerName router.PeerName, buf []byte) error { select { - case client.router.gossipChans[dstPeerName] <- gossipMessage{isUnicast: true, sender: &client.sender, buf: buf}: + case client.router.gossipChans[dstPeerName] <- unicastMessage{sender: client.sender, buf: buf}: default: // drop the message if we cannot send it - common.Error.Printf("Dropping message") + common.Log.Errorf("Dropping message") } return nil } @@ -284,7 +306,7 @@ func (client TestGossipRouterClient) GossipBroadcast(update router.GossipData) e func makeNetworkOfAllocators(size int, cidr string) ([]*Allocator, TestGossipRouter, address.Range) { - gossipRouter := TestGossipRouter{make(map[router.PeerName]chan gossipMessage), 0.0} + gossipRouter := TestGossipRouter{make(map[router.PeerName]chan interface{}), 0.0} allocs := make([]*Allocator, size) var subnet address.Range @@ -298,7 +320,7 @@ func makeNetworkOfAllocators(size int, cidr string) ([]*Allocator, TestGossipRou } gossipRouter.GossipBroadcast(allocs[size-1].Gossip()) - time.Sleep(1000 * time.Millisecond) + gossipRouter.flush() return allocs, gossipRouter, subnet } diff --git a/nameserver/addrs.go b/nameserver/addrs.go index bb4ac27c..fb3deb66 100644 --- a/nameserver/addrs.go +++ b/nameserver/addrs.go @@ -7,9 +7,11 @@ import ( ) // A zone record -// Note: we will try to keep all the zone records information is concentrated here. Maybe not all queries will -// use things like priorities or weights, but we do not want to create a hierarchy for dealing with all -// possible queries... +// +// Note: all the zone records information is concentrated here. Maybe +// not all queries will use things like priorities or weights, but we +// do not want to create a hierarchy for dealing with all possible +// queries... type ZoneRecord interface { Name() string // The name for this IP IP() net.IP // The IP (v4) address diff --git a/nameserver/addrs_test.go b/nameserver/addrs_test.go index 81392cdc..2118832b 100644 --- a/nameserver/addrs_test.go +++ b/nameserver/addrs_test.go @@ -10,7 +10,7 @@ import ( func TestAddrs(t *testing.T) { InitDefaultLogging(testing.Verbose()) - Info.Println("TestAddrs starting") + Log.Infoln("TestAddrs starting") ip, err := addrToIPv4("10.13.12.11") require.NoError(t, err) diff --git a/nameserver/cache.go b/nameserver/cache.go index 4af548c8..fd0be604 100644 --- a/nameserver/cache.go +++ b/nameserver/cache.go @@ -86,7 +86,7 @@ func (e *cacheEntry) getReply(request *dns.Msg, maxLen int, now time.Time) (*dns } if e.ReplyLen >= maxLen { - Debug.Printf("[cache msgid %d] returning truncated reponse: %d > %d", request.MsgHdr.Id, e.ReplyLen, maxLen) + Log.Debugf("[cache msgid %d] returning truncated reponse: %d > %d", request.MsgHdr.Id, e.ReplyLen, maxLen) return makeTruncatedReply(request), nil } @@ -122,7 +122,7 @@ func (e *cacheEntry) setReply(reply *dns.Msg, ttl int, flags uint8, now time.Tim var prevValidUntil time.Time if e.Status == stResolved { if reply != nil { - Debug.Printf("[cache msgid %d] replacing response in cache", reply.MsgHdr.Id) + Log.Debugf("[cache msgid %d] replacing response in cache", reply.MsgHdr.Id) } prevValidUntil = e.validUntil } @@ -147,7 +147,7 @@ func (e *cacheEntry) setReply(reply *dns.Msg, ttl int, flags uint8, now time.Tim } e.validUntil = now.Add(time.Second * time.Duration(minTTL)) } else { - Warning.Printf("[cache] no valid TTL could be calculated") + Log.Warningf("[cache] no valid TTL could be calculated") } e.Status = stResolved @@ -323,7 +323,7 @@ func (c *Cache) Get(request *dns.Msg, maxLen int) (reply *dns.Msg, err error) { if ent, found := c.entries[key]; found { reply, err = ent.getReply(request, maxLen, now) if ent.hasExpired(now) { - Debug.Printf("[cache msgid %d] expired: removing", request.MsgHdr.Id) + Log.Debugf("[cache msgid %d] expired: removing", request.MsgHdr.Id) if ent.index > 0 { heap.Remove(&c.entriesH, ent.index) } @@ -332,7 +332,7 @@ func (c *Cache) Get(request *dns.Msg, maxLen int) (reply *dns.Msg, err error) { } } else { // we are the first asking for this name: create an entry with no reply... the caller must wait - Debug.Printf("[cache msgid %d] addind in pending state", request.MsgHdr.Id) + Log.Debugf("[cache msgid %d] addind in pending state", request.MsgHdr.Id) c.entries[key] = newCacheEntry(&question, now) } return @@ -345,7 +345,7 @@ func (c *Cache) Remove(question *dns.Question) { key := cacheKey(*question) if entry, found := c.entries[key]; found { - Debug.Printf("[cache] removing %s-response for '%s'", dns.TypeToString[question.Qtype], question.Name) + Log.Debugf("[cache] removing %s-response for '%s'", dns.TypeToString[question.Qtype], question.Name) if entry.index > 0 { heap.Remove(&c.entriesH, entry.index) } diff --git a/nameserver/cache_test.go b/nameserver/cache_test.go index 8f230368..f3a14cb0 100644 --- a/nameserver/cache_test.go +++ b/nameserver/cache_test.go @@ -15,7 +15,7 @@ import ( // Check that the cache keeps its intended capacity constant func TestCacheLength(t *testing.T) { InitDefaultLogging(testing.Verbose()) - Info.Println("TestCacheLength starting") + Log.Infoln("TestCacheLength starting") const cacheLen = 128 @@ -56,9 +56,9 @@ func TestCacheLength(t *testing.T) { // Check that the cache entries are ok func TestCacheEntries(t *testing.T) { InitDefaultLogging(testing.Verbose()) - Info.Println("TestCacheEntries starting") + Log.Infoln("TestCacheEntries starting") - Info.Println("Checking cache consistency") + Log.Infoln("Checking cache consistency") const cacheLen = 128 clk := clock.NewMock() @@ -213,7 +213,7 @@ func TestCacheEntries(t *testing.T) { require.True(t, err == errNoLocalReplies, "Get() error with CacheNoLocalReplies") clk.Add(time.Duration(DefaultLocalTTL/2) * time.Second) - t.Logf("Checking that we get an expired response after %f seconds", DefaultLocalTTL) + t.Logf("Checking that we get an expired response after %d seconds", DefaultLocalTTL) clk.Add(time.Second * time.Duration(DefaultLocalTTL+1)) t.Logf("Checking that we get an expired response after %d seconds", DefaultLocalTTL) resp, err = l.Get(questionMsg3, minUDPSize) diff --git a/nameserver/dns_test.go b/nameserver/dns_test.go index 3c46da41..1ec25147 100644 --- a/nameserver/dns_test.go +++ b/nameserver/dns_test.go @@ -12,7 +12,7 @@ import ( // Check that we can prune an answer func TestPrune(t *testing.T) { InitDefaultLogging(testing.Verbose()) - Info.Println("TestPrune starting") + Log.Infoln("TestPrune starting") questionMsg := new(dns.Msg) questionMsg.SetQuestion("name", dns.TypeA) diff --git a/nameserver/http.go b/nameserver/http.go index 20753a98..42dd3231 100644 --- a/nameserver/http.go +++ b/nameserver/http.go @@ -2,7 +2,6 @@ package nameserver import ( "fmt" - "log" "net" "net/http" @@ -12,10 +11,10 @@ import ( "github.com/weaveworks/weave/common/docker" ) -func httpErrorAndLog(level *log.Logger, w http.ResponseWriter, msg string, +func httpErrorAndLog(w http.ResponseWriter, msg string, status int, logmsg string, logargs ...interface{}) { http.Error(w, msg, status) - level.Printf("[http] "+logmsg, logargs...) + Log.Warningf("[http] "+logmsg, logargs...) } func extractFQDN(r *http.Request) (string, string) { @@ -41,7 +40,7 @@ func ServeHTTP(listener net.Listener, version string, server *DNSServer, dockerC muxRouter.Methods("PUT").Path("/name/{id:.+}/{ip:.+}").HandlerFunc(func(w http.ResponseWriter, r *http.Request) { reqError := func(msg string, logmsg string, logargs ...interface{}) { - httpErrorAndLog(Warning, w, msg, http.StatusBadRequest, logmsg, logargs...) + httpErrorAndLog(w, msg, http.StatusBadRequest, logmsg, logargs...) } vars := mux.Vars(r) @@ -62,21 +61,21 @@ func ServeHTTP(listener net.Listener, version string, server *DNSServer, dockerC domain := server.Zone.Domain() if !dns.IsSubDomain(domain, name) { - Info.Printf("[http] Ignoring name %s, not in %s", name, domain) + Log.Infof("[http] Ignoring name %s, not in %s", name, domain) return } - Info.Printf("[http] Adding %s -> %s", name, ipStr) + Log.Infof("[http] Adding %s -> %s", name, ipStr) if err := server.Zone.AddRecord(idStr, name, ip); err != nil { if _, ok := err.(DuplicateError); !ok { httpErrorAndLog( - Error, w, "Internal error", http.StatusInternalServerError, + w, "Internal error", http.StatusInternalServerError, "Unexpected error from DB: %s", err) return } // oh, I already know this. whatever. } if dockerCli != nil && dockerCli.IsContainerNotRunning(idStr) { - Info.Printf("[http] '%s' is not running: removing", idStr) + Log.Infof("[http] '%s' is not running: removing", idStr) server.Zone.DeleteRecords(idStr, name, ip) } }) @@ -89,14 +88,14 @@ func ServeHTTP(listener net.Listener, version string, server *DNSServer, dockerC ip := net.ParseIP(ipStr) if ip == nil { httpErrorAndLog( - Warning, w, "Invalid IP in request", http.StatusBadRequest, + w, "Invalid IP in request", http.StatusBadRequest, "Invalid IP in request: %s", ipStr) return } fqdnStr, fqdn := extractFQDN(r) - Info.Printf("[http] Deleting ID %s, IP %s, FQDN %s", idStr, ipStr, fqdnStr) + Log.Infof("[http] Deleting ID %s, IP %s, FQDN %s", idStr, ipStr, fqdnStr) server.Zone.DeleteRecords(idStr, fqdn, ip) }) @@ -106,20 +105,20 @@ func ServeHTTP(listener net.Listener, version string, server *DNSServer, dockerC fqdnStr, fqdn := extractFQDN(r) - Info.Printf("[http] Deleting ID %s, IP *, FQDN %s", idStr, fqdnStr) + Log.Infof("[http] Deleting ID %s, IP *, FQDN %s", idStr, fqdnStr) server.Zone.DeleteRecords(idStr, fqdn, net.IP{}) }) muxRouter.Methods("DELETE").Path("/name").HandlerFunc(func(w http.ResponseWriter, r *http.Request) { fqdnStr, fqdn := extractFQDN(r) - Info.Printf("[http] Deleting ID *, IP *, FQDN %s", fqdnStr) + Log.Infof("[http] Deleting ID *, IP *, FQDN %s", fqdnStr) server.Zone.DeleteRecords("", fqdn, net.IP{}) }) http.Handle("/", muxRouter) if err := http.Serve(listener, nil); err != nil { - Error.Fatal("[http] Unable to serve http: ", err) + Log.Fatal("[http] Unable to serve http: ", err) } } diff --git a/nameserver/mdns_lookup.go b/nameserver/mdns_lookup.go index 05619367..db051bb4 100644 --- a/nameserver/mdns_lookup.go +++ b/nameserver/mdns_lookup.go @@ -12,10 +12,10 @@ func mdnsLookup(client *MDNSClient, name string, qtype uint16, insistent bool) ( for resp := range channel { if err := resp.err; err != nil { - Debug.Printf("[mdns] Error for query type %s name %s: %s", dns.TypeToString[qtype], name, err) + Log.Debugf("[mdns] Error for query type %s name %s: %s", dns.TypeToString[qtype], name, err) return nil, err } - Debug.Printf("[mdns] Got response name for %s-query about name '%s': name '%s', addr '%s'", + Log.Debugf("[mdns] Got response name for %s-query about name '%s': name '%s', addr '%s'", dns.TypeToString[qtype], name, resp.name, resp.addr) if !insistent { diff --git a/nameserver/mdns_server.go b/nameserver/mdns_server.go index 4a013a4f..df51f6f8 100644 --- a/nameserver/mdns_server.go +++ b/nameserver/mdns_server.go @@ -113,7 +113,7 @@ func (s *MDNSServer) makeHandler(qtype uint16, lookup LookupFunc) dns.HandlerFun // answer. remoteAddr := rw.RemoteAddr() if s.addrIsLocal(remoteAddr) && !s.allowLocal { - Debug.Printf("[mdns] srv: mDNS query from local host ('%s'): ignored", remoteAddr) + Log.Debugf("[mdns] srv: mDNS query from local host ('%s'): ignored", remoteAddr) return } @@ -121,16 +121,16 @@ func (s *MDNSServer) makeHandler(qtype uint16, lookup LookupFunc) dns.HandlerFun if len(r.Answer) == 0 && len(r.Question) > 0 { q := &r.Question[0] if q.Qtype == qtype { - Debug.Printf("[mdns msgid %d] srv: trying to answer to mDNS query '%s'", r.MsgHdr.Id, q.Name) + Log.Debugf("[mdns msgid %d] srv: trying to answer to mDNS query '%s'", r.MsgHdr.Id, q.Name) if m := lookup(s.zone, r, q); m != nil { - Debug.Printf("[mdns msgid %d] srv: found local answer to mDNS query '%s'", r.MsgHdr.Id, q.Name) + Log.Debugf("[mdns msgid %d] srv: found local answer to mDNS query '%s'", r.MsgHdr.Id, q.Name) if err := s.sendResponse(m); err != nil { - Warning.Printf("[mdns msgid %d] srv: error writing mDNS response to %v", r.MsgHdr.Id, s.sendconn) + Log.Warningf("[mdns msgid %d] srv: error writing mDNS response to %v", r.MsgHdr.Id, s.sendconn) } else { - Debug.Printf("[mdns msgid %d] srv: response sent: %d answers", r.MsgHdr.Id, len(m.Answer)) + Log.Debugf("[mdns msgid %d] srv: response sent: %d answers", r.MsgHdr.Id, len(m.Answer)) } } else { - Debug.Printf("[mdns msgid %d] srv: no local answer for answering mDNS query '%s'", + Log.Debugf("[mdns msgid %d] srv: no local answer for answering mDNS query '%s'", r.MsgHdr.Id, q.Name) } } diff --git a/nameserver/mdns_server_test.go b/nameserver/mdns_server_test.go index ecfd2681..3fe89fe0 100644 --- a/nameserver/mdns_server_test.go +++ b/nameserver/mdns_server_test.go @@ -18,7 +18,7 @@ func TestServerSimpleQuery(t *testing.T) { ) InitDefaultLogging(testing.Verbose()) - Info.Println("TestServerSimpleQuery starting") + Log.Infoln("TestServerSimpleQuery starting") mzone := newMockedZoneWithRecords([]ZoneRecord{testRecord1, testRecord2}) mdnsServer, err := NewMDNSServer(mzone, true, DefaultLocalTTL) @@ -59,11 +59,11 @@ func TestServerSimpleQuery(t *testing.T) { require.NoError(t, err) conn, err := net.ListenUDP("udp4", &net.UDPAddr{IP: net.IPv4zero, Port: 0}) require.NoError(t, err) - Debug.Printf("Sending UDP packet to %s", ipv4Addr) + Log.Debugf("Sending UDP packet to %s", ipv4Addr) _, err = conn.WriteTo(buf, ipv4Addr) require.NoError(t, err) - Debug.Printf("Waiting for response") + Log.Debugf("Waiting for response") for { select { case x := <-recvChan: @@ -80,7 +80,7 @@ func TestServerSimpleQuery(t *testing.T) { return } case <-time.After(100 * time.Millisecond): - Debug.Printf("Timeout while waiting for response") + Log.Debugf("Timeout while waiting for response") return } } @@ -96,7 +96,7 @@ func TestServerSimpleQuery(t *testing.T) { time.Sleep(100 * time.Millisecond) // Allow for server to get going - Debug.Printf("Checking that we get 2 IPs fo name '%s' [A]", testRecord1.Name()) + Log.Debugf("Checking that we get 2 IPs fo name '%s' [A]", testRecord1.Name()) sendQuery(testRecord1.Name(), dns.TypeA) if receivedCount != 2 { t.Fatalf("Unexpected result count %d for %s", receivedCount, testRecord1.Name()) @@ -108,13 +108,13 @@ func TestServerSimpleQuery(t *testing.T) { t.Fatalf("Unexpected result %s for %s", receivedAddrs, testRecord1.Name()) } - Debug.Printf("Checking that 'testfail.weave.' [A] gets no answers") + Log.Debugf("Checking that 'testfail.weave.' [A] gets no answers") sendQuery("testfail.weave.", dns.TypeA) if receivedCount != 0 { t.Fatalf("Unexpected result count %d for testfail.weave", receivedCount) } - Debug.Printf("Checking that '%s' [PTR] gets one name", testInAddr1) + Log.Debugf("Checking that '%s' [PTR] gets one name", testInAddr1) sendQuery(testInAddr1, dns.TypePTR) if receivedCount != 1 { t.Fatalf("Expected an answer to %s, got %d answers", testInAddr1, receivedCount) diff --git a/nameserver/mdns_test.go b/nameserver/mdns_test.go index 4cdae430..867eedec 100644 --- a/nameserver/mdns_test.go +++ b/nameserver/mdns_test.go @@ -37,7 +37,7 @@ func TestClientServerSimpleQuery(t *testing.T) { receivedAddr = nil receivedName = "" receivedCount = 0 - Debug.Printf("Sending query...") + Log.Debugf("Sending query...") switch querytype { case dns.TypeA: r, err := mdnsCli.LookupName(name) @@ -60,7 +60,7 @@ func TestClientServerSimpleQuery(t *testing.T) { time.Sleep(100 * time.Millisecond) // Allow for server to get going - Debug.Printf("Query: %s dns.TypeA", testRecord1.Name()) + Log.Debugf("Query: %s dns.TypeA", testRecord1.Name()) sendQuery(testRecord1.Name(), dns.TypeA) if receivedCount != 1 { t.Fatalf("Unexpected result count %d for %s", receivedCount, testRecord1.Name()) @@ -69,13 +69,13 @@ func TestClientServerSimpleQuery(t *testing.T) { t.Fatalf("Unexpected result %s for %s", receivedAddr, testRecord1.Name()) } - Debug.Printf("Query: testfail.weave. dns.TypeA") + Log.Debugf("Query: testfail.weave. dns.TypeA") sendQuery("testfail.weave.", dns.TypeA) if receivedCount != 0 { t.Fatalf("Unexpected result count %d for testfail.weave", receivedCount) } - Debug.Printf("Query: %s dns.TypePTR", testInAddr1) + Log.Debugf("Query: %s dns.TypePTR", testInAddr1) sendQuery(testInAddr1, dns.TypePTR) if receivedCount != 1 { t.Fatalf("Expected an answer to %s, got %d answers", testInAddr1, receivedCount) @@ -127,7 +127,7 @@ func TestClientServerInsistentQuery(t *testing.T) { receivedAddrs = nil receivedNames = nil receivedCount = 0 - Debug.Printf("Sending query...") + Log.Debugf("Sending query...") switch querytype { case dns.TypeA: receivedAddrs, err = mdnsCli.InsistentLookupName(name) @@ -144,25 +144,25 @@ func TestClientServerInsistentQuery(t *testing.T) { time.Sleep(100 * time.Millisecond) // Allow for server to get going - Debug.Printf("Query: %s dns.TypeA", testRecord1.Name()) + Log.Debugf("Query: %s dns.TypeA", testRecord1.Name()) sendQuery(testRecord1.Name(), dns.TypeA) if receivedCount != 2 { t.Fatalf("Unexpected result count %d for %s", receivedCount, testRecord1.Name()) } - Debug.Printf("Query: testfail.weave. dns.TypeA") + Log.Debugf("Query: testfail.weave. dns.TypeA") sendQuery("testfail.weave.", dns.TypeA) if receivedCount != 0 { t.Fatalf("Unexpected result count %d for testfail.weave", receivedCount) } - Debug.Printf("Query: %s dns.TypePTR", testInAddr1) + Log.Debugf("Query: %s dns.TypePTR", testInAddr1) sendQuery(testInAddr1, dns.TypePTR) if receivedCount != 1 { t.Fatalf("Expected an answer to %s, got %d answers", testInAddr1, receivedCount) } - Debug.Printf("Query: %s dns.TypePTR", testInAddr2) + Log.Debugf("Query: %s dns.TypePTR", testInAddr2) sendQuery(testInAddr2, dns.TypePTR) if receivedCount != 1 { t.Fatalf("Expected an answer to %s, got %d answers", testInAddr2, receivedCount) diff --git a/nameserver/mocks_test.go b/nameserver/mocks_test.go index 397dbc02..58bb5e04 100644 --- a/nameserver/mocks_test.go +++ b/nameserver/mocks_test.go @@ -19,7 +19,7 @@ const ( ) // Warn about some methods that some day should be implemented... -func notImplWarn() { Warning.Printf("Mocked method. Not implemented.") } +func notImplWarn() { Log.Warningf("Mocked method. Not implemented.") } // A mocked Zone that always returns the same records // * it does not send/receive any mDNS query @@ -38,7 +38,7 @@ func newMockedZoneWithRecords(zr []ZoneRecord) *mockedZoneWithRecords { } func (mz *mockedZoneWithRecords) Domain() string { return DefaultLocalDomain } func (mz *mockedZoneWithRecords) LookupName(name string) ([]ZoneRecord, error) { - Debug.Printf("[mocked zone]: LookupName: returning records %s", mz.records) + Log.Debugf("[mocked zone]: LookupName: returning records %s", mz.records) mz.Lock() defer mz.Unlock() @@ -53,7 +53,7 @@ func (mz *mockedZoneWithRecords) LookupName(name string) ([]ZoneRecord, error) { } func (mz *mockedZoneWithRecords) LookupInaddr(inaddr string) ([]ZoneRecord, error) { - Debug.Printf("[mocked zone]: LookupInaddr: returning records %s", mz.records) + Log.Debugf("[mocked zone]: LookupInaddr: returning records %s", mz.records) mz.Lock() defer mz.Unlock() @@ -243,17 +243,17 @@ func newZoneDbsWithMockedMDns(num int, config ZoneConfig) zoneDbsWithMockedMDns for i := 0; i < num; i++ { res[i] = new(zbmEntry) - Debug.Printf("[test] Creating mocked mDNS server #%d", i) + Log.Debugf("[test] Creating mocked mDNS server #%d", i) res[i].Server = newMockedMDNSServer(nil) - Debug.Printf("[test] Creating mocked mDNS client #%d", i) + Log.Debugf("[test] Creating mocked mDNS client #%d", i) res[i].Client = newMockedMDNSClient([]*mockedMDNSServer{}) cfg := config cfg.MDNSClient = res[i].Client cfg.MDNSServer = res[i].Server - Debug.Printf("[test] Creating ZoneDb #%d", i) + Log.Debugf("[test] Creating ZoneDb #%d", i) res[i].Zone, _ = NewZoneDb(cfg) // link the mDNS server to its zone @@ -270,7 +270,7 @@ func newZoneDbsWithMockedMDns(num int, config ZoneConfig) zoneDbsWithMockedMDns // this is not what we currently do, but can be convenient in some cases // for finding some bugs... if i != j { - Debug.Printf("[test] Linking mocked mDNS client #%d to server #%d", i, j) + Log.Debugf("[test] Linking mocked mDNS client #%d to server #%d", i, j) res[i].Client.AddServer(res[j].Server) } } @@ -389,7 +389,7 @@ func (mf *mockedFallback) Stop() error { // Run a UDP fallback server func runLocalUDPServer(laddr string, handler dns.HandlerFunc) (*dns.Server, string, error) { - Debug.Printf("[mocked fallback] Starting fallback UDP server at %s", laddr) + Log.Debugf("[mocked fallback] Starting fallback UDP server at %s", laddr) pc, err := net.ListenPacket("udp", laddr) if err != nil { return nil, "", err @@ -401,13 +401,13 @@ func runLocalUDPServer(laddr string, handler dns.HandlerFunc) (*dns.Server, stri pc.Close() }() - Debug.Printf("[mocked fallback] Fallback UDP server listening at %s", pc.LocalAddr()) + Log.Debugf("[mocked fallback] Fallback UDP server listening at %s", pc.LocalAddr()) return server, pc.LocalAddr().String(), nil } // Run a TCP fallback server func runLocalTCPServer(laddr string, handler dns.HandlerFunc) (*dns.Server, string, error) { - Debug.Printf("[mocked fallback] Starting fallback TCP server at %s", laddr) + Log.Debugf("[mocked fallback] Starting fallback TCP server at %s", laddr) laddrTCP, err := net.ResolveTCPAddr("tcp", laddr) if err != nil { return nil, "", err @@ -424,7 +424,7 @@ func runLocalTCPServer(laddr string, handler dns.HandlerFunc) (*dns.Server, stri l.Close() }() - Debug.Printf("[mocked fallback] Fallback TCP server listening at %s", l.Addr().String()) + Log.Debugf("[mocked fallback] Fallback TCP server listening at %s", l.Addr().String()) return server, l.Addr().String(), nil } @@ -442,9 +442,9 @@ func newMockedClock() *mockedClock { // be waiting in channels. So your code should not depend on the channels // for creating new timers. Otherwise, time travelling will not be reliable... func (clk *mockedClock) Forward(secs int) { - Debug.Printf(">>>>>>> Moving clock forward %d seconds - Time traveling >>>>>>>", secs) + Log.Debugf(">>>>>>> Moving clock forward %d seconds - Time traveling >>>>>>>", secs) clk.Add(time.Duration(secs) * time.Second) - Debug.Printf("<<<<<<< Time travel finished! We are at %s <<<<<<<", clk.Now()) + Log.Debugf("<<<<<<< Time travel finished! We are at %s <<<<<<<", clk.Now()) } ////////////////////////////////////////////////////////////////// diff --git a/nameserver/server.go b/nameserver/server.go index a7b84bc7..6f36aaf4 100644 --- a/nameserver/server.go +++ b/nameserver/server.go @@ -74,7 +74,7 @@ func (proto dnsProtocol) String() string { // get a new dns.Client for a protocol func (proto dnsProtocol) GetNewClient(bufsize int, timeout time.Duration) *dns.Client { - Debug.Printf("[dns] Creating %s DNS client with %s timeout", proto, timeout) + Log.Debugf("[dns] Creating %s DNS client with %s timeout", proto, timeout) switch proto { case protTCP: return &dns.Client{Net: "tcp", ReadTimeout: timeout} @@ -188,11 +188,11 @@ func NewDNSServer(config DNSServerConfig) (s *DNSServer, err error) { // Start the DNS server func (s *DNSServer) Start() error { - Info.Printf("[dns] Upstream server(s): %+v", s.Upstream) + Log.Infof("[dns] Upstream server(s): %+v", s.Upstream) if s.cacheDisabled { - Info.Printf("[dns] Cache: disabled") + Log.Infof("[dns] Cache: disabled") } else { - Info.Printf("[dns] Cache: %d entries", s.cache.Capacity()) + Log.Infof("[dns] Cache: %d entries", s.cache.Capacity()) } pc, err := net.ListenPacket("udp", s.ListenAddr) @@ -225,25 +225,25 @@ func (s *DNSServer) ActivateAndServe() { go func() { defer s.listenersWg.Done() - Info.Printf("[dns] Listening for DNS on %s (UDP)", s.ListenAddr) + Log.Infof("[dns] Listening for DNS on %s (UDP)", s.ListenAddr) err := s.udpSrv.ActivateAndServe() CheckFatal(err) - Debug.Printf("[dns] DNS UDP server exiting...") + Log.Debugf("[dns] DNS UDP server exiting...") }() go func() { defer s.listenersWg.Done() - Info.Printf("[dns] Listening for DNS on %s (TCP)", s.ListenAddr) + Log.Infof("[dns] Listening for DNS on %s (TCP)", s.ListenAddr) err := s.tcpSrv.ActivateAndServe() CheckFatal(err) - Debug.Printf("[dns] DNS TCP server exiting...") + Log.Debugf("[dns] DNS TCP server exiting...") }() // Waiting for all goroutines to finish (otherwise they die as main routine dies) s.listenersWg.Wait() - Info.Printf("[dns] Server exiting...") + Log.Infof("[dns] Server exiting...") } // Return status string @@ -284,7 +284,7 @@ func (s *DNSServer) createMux(proto dnsProtocol) *dns.ServeMux { } notUsHandler := s.notUsHandler(proto) notUsFallback := func(w dns.ResponseWriter, r *dns.Msg) { - Info.Printf("[dns msgid %d] -> sending to fallback server", r.MsgHdr.Id) + Log.Infof("[dns msgid %d] -> sending to fallback server", r.MsgHdr.Id) notUsHandler(w, r) } @@ -305,7 +305,7 @@ func (s *DNSServer) localHandler(proto dnsProtocol, kind string, qtype uint16, return func(w dns.ResponseWriter, r *dns.Msg) { q := r.Question[0] - Debug.Printf("[dns msgid %d] %s: %+v", r.MsgHdr.Id, kind, q) + Log.Debugf("[dns msgid %d] %s: %+v", r.MsgHdr.Id, kind, q) maxLen := getMaxReplyLen(r, proto) // cache a response if the cache is enabled, and observe the name/IP @@ -324,17 +324,17 @@ func (s *DNSServer) localHandler(proto dnsProtocol, kind string, qtype uint16, reply, err := s.cache.Get(r, maxLen) if err != nil { if err == errNoLocalReplies { - Debug.Printf("[dns msgid %d] Cached no-local-replies", r.MsgHdr.Id) + Log.Debugf("[dns msgid %d] Cached no-local-replies", r.MsgHdr.Id) fallback(w, r) } else { - Debug.Printf("[dns msgid %d] Error from cache: %s", r.MsgHdr.Id, err) + Log.Debugf("[dns msgid %d] Error from cache: %s", r.MsgHdr.Id, err) w.WriteMsg(makeDNSFailResponse(r)) } return } if reply != nil { reply.Answer = pruneAnswers(shuffleAnswers(reply.Answer), s.maxAnswers) - Debug.Printf("[dns msgid %d] Returning reply from cache: %s/%d answers", + Log.Debugf("[dns msgid %d] Returning reply from cache: %s/%d answers", r.MsgHdr.Id, dns.RcodeToString[reply.MsgHdr.Rcode], len(reply.Answer)) w.WriteMsg(reply) return @@ -343,7 +343,7 @@ func (s *DNSServer) localHandler(proto dnsProtocol, kind string, qtype uint16, // catch unsupported queries if q.Qtype != qtype { - Debug.Printf("[dns msgid %d] Unsupported query type %s", r.MsgHdr.Id, dns.TypeToString[q.Qtype]) + Log.Debugf("[dns msgid %d] Unsupported query type %s", r.MsgHdr.Id, dns.TypeToString[q.Qtype]) m := makeDNSFailResponse(r) maybeCache(m, s.negLocalTTL, 0) w.WriteMsg(m) @@ -351,8 +351,9 @@ func (s *DNSServer) localHandler(proto dnsProtocol, kind string, qtype uint16, } if answers, err := lookup(q.Name); err != nil { - Info.Printf("[dns msgid %d] No results for type %s query for '%s' [caching no-local]", + Log.Infof("[dns msgid %d] No results for type %s query for '%s' [caching no-local]", r.MsgHdr.Id, dns.TypeToString[q.Qtype], q.Name) + maybeCache(nil, s.negLocalTTL, CacheNoLocalReplies) fallback(w, r) } else { @@ -360,7 +361,7 @@ func (s *DNSServer) localHandler(proto dnsProtocol, kind string, qtype uint16, m.Authoritative = true maybeCache(m, nullTTL, 0) m.Answer = pruneAnswers(shuffleAnswers(m.Answer), s.maxAnswers) - Debug.Printf("[dns msgid %d] Sending response: %s/%d answers [code:%s]", + Log.Debugf("[dns msgid %d] Sending response: %s/%d answers [code:%s]", m.MsgHdr.Id, dns.TypeToString[q.Qtype], len(m.Answer), dns.RcodeToString[m.Rcode]) w.WriteMsg(m) } @@ -380,25 +381,25 @@ func (s *DNSServer) notUsHandler(proto dnsProtocol) dns.HandlerFunc { rcopy := r rcopy.SetEdns0(uint16(maxLen), false) - Debug.Printf("[dns msgid %d] Fallback query: %+v [%s, max:%d bytes]", rcopy.MsgHdr.Id, q, proto, maxLen) + Log.Debugf("[dns msgid %d] Fallback query: %+v [%s, max:%d bytes]", rcopy.MsgHdr.Id, q, proto, maxLen) for _, server := range s.Upstream.Servers { reply, _, err := dnsClient.Exchange(rcopy, fmt.Sprintf("%s:%s", server, s.Upstream.Port)) if err != nil { - Debug.Printf("[dns msgid %d] Network error trying %s (%s)", + Log.Debugf("[dns msgid %d] Network error trying %s (%s)", r.MsgHdr.Id, server, err) continue } if reply != nil && reply.Rcode != dns.RcodeSuccess { - Debug.Printf("[dns msgid %d] Failure reported by %s for query %s", + Log.Debugf("[dns msgid %d] Failure reported by %s for query %s", r.MsgHdr.Id, server, q.Name) continue } - Debug.Printf("[dns msgid %d] Given answer by %s for query %s", + Log.Debugf("[dns msgid %d] Given answer by %s for query %s", r.MsgHdr.Id, server, q.Name) w.WriteMsg(reply) return } - Warning.Printf("[dns msgid %d] Failed lookup for external name %s", r.MsgHdr.Id, q.Name) + Log.Warningf("[dns msgid %d] Failed lookup for external name %s", r.MsgHdr.Id, q.Name) w.WriteMsg(makeDNSFailResponse(r)) } } diff --git a/nameserver/server_cache_test.go b/nameserver/server_cache_test.go index 31200d72..35f3dc82 100644 --- a/nameserver/server_cache_test.go +++ b/nameserver/server_cache_test.go @@ -20,15 +20,15 @@ func TestServerDbCacheInvalidation(t *testing.T) { ) InitDefaultLogging(testing.Verbose()) - Info.Println("TestServerDbCacheInvalidation starting") + Log.Infoln("TestServerDbCacheInvalidation starting") clk := newMockedClock() - Debug.Printf("Creating mocked mDNS client and server") + Log.Debugf("Creating mocked mDNS client and server") mdnsServer1 := newMockedMDNSServerWithRecord(Record{testName1, net.ParseIP("10.2.2.9"), 0, 0, 0}) mdnsCli1 := newMockedMDNSClient([]*mockedMDNSServer{mdnsServer1}) - Debug.Printf("Creating zone database with the mocked mDNS client and server") + Log.Debugf("Creating zone database with the mocked mDNS client and server") zoneConfig := ZoneConfig{ MDNSServer: mdnsServer1, MDNSClient: mdnsCli1, @@ -40,7 +40,7 @@ func TestServerDbCacheInvalidation(t *testing.T) { require.NoError(t, err) defer zone.Stop() - Debug.Printf("Creating a cache") + Log.Debugf("Creating a cache") cache, err := NewCache(1024, clk) require.NoError(t, err) @@ -59,7 +59,7 @@ func TestServerDbCacheInvalidation(t *testing.T) { fallback.Start() defer fallback.Stop() - Debug.Printf("Creating a real DNS server with a mocked cache") + Log.Debugf("Creating a real DNS server with a mocked cache") srv, err := NewDNSServer(DNSServerConfig{ Zone: zone, Cache: cache, @@ -79,7 +79,7 @@ func TestServerDbCacheInvalidation(t *testing.T) { require.NoError(t, err) require.NotEqual(t, 0, testPort, "invalid listen port") - Debug.Printf("Adding two IPs to %s", testName1) + Log.Debugf("Adding two IPs to %s", testName1) zone.AddRecord(containerID, testName1, net.ParseIP("10.2.2.1")) zone.AddRecord(containerID, testName1, net.ParseIP("10.2.2.2")) q, _ := assertExchange(t, testName1, dns.TypeA, testPort, 2, 2, 0) @@ -93,7 +93,7 @@ func TestServerDbCacheInvalidation(t *testing.T) { // we should have an entry in the cache for this query // if we add another IP, that cache entry should be removed - Debug.Printf("Adding a new IP to %s: the cache entry should be removed", testName1) + Log.Debugf("Adding a new IP to %s: the cache entry should be removed", testName1) zone.AddRecord(containerID, testName1, net.ParseIP("10.2.2.3")) assertNotInCache(t, cache, q, fmt.Sprintf("after adding a new IP for %s", testName1)) @@ -101,10 +101,10 @@ func TestServerDbCacheInvalidation(t *testing.T) { // first.weave.local = 10.2.2.1 10.2.2.2 10.2.2.3 // second.weave.local = 10.9.9.1 - Debug.Printf("Querying again (so a cache entry will be created)") + Log.Debugf("Querying again (so a cache entry will be created)") q, _ = assertExchange(t, testName1, dns.TypeA, testPort, 3, 4, 0) assertInCache(t, cache, q, "after asking about the name") - Debug.Printf("... and removing one of the IP addresses") + Log.Debugf("... and removing one of the IP addresses") zone.DeleteRecords(containerID, "", net.ParseIP("10.2.2.2")) assertNotInCache(t, cache, q, "after deleting IP for 10.2.2.2") @@ -113,7 +113,7 @@ func TestServerDbCacheInvalidation(t *testing.T) { // second.weave.local = 10.9.9.1 // generate cache responses - Debug.Printf("Querying for a raddr") + Log.Debugf("Querying for a raddr") qname, _ := assertExchange(t, testName1, dns.TypeA, testPort, 2, 2, 0) qptr, _ := assertExchange(t, "1.2.2.10.in-addr.arpa.", dns.TypePTR, testPort, 1, 1, 0) qotherName, _ := assertExchange(t, testName2, dns.TypeA, testPort, 1, 1, 0) @@ -126,7 +126,7 @@ func TestServerDbCacheInvalidation(t *testing.T) { assertNotLocalInCache(t, cache, qwrongName, "after asking for a wrong name") // now we will check if a removal affects all the responses - Debug.Printf("... and removing an IP should invalidate both the cached responses for name and raddr") + Log.Debugf("... and removing an IP should invalidate both the cached responses for name and raddr") zone.DeleteRecords(containerID, "", net.ParseIP("10.2.2.1")) assertNotInCache(t, cache, qptr, "after deleting record") assertNotInCache(t, cache, qname, "after deleting record") @@ -137,7 +137,7 @@ func TestServerDbCacheInvalidation(t *testing.T) { // second.weave.local = 10.9.9.1 // generate cache responses - Debug.Printf("Querying for a raddr") + Log.Debugf("Querying for a raddr") qptr, _ = assertExchange(t, "3.2.2.10.in-addr.arpa.", dns.TypePTR, testPort, 1, 1, 0) qname, _ = assertExchange(t, testName1, dns.TypeA, testPort, 1, 1, 0) qotherName, _ = assertExchange(t, testName2, dns.TypeA, testPort, 1, 1, 0) @@ -148,7 +148,7 @@ func TestServerDbCacheInvalidation(t *testing.T) { assertInCache(t, cache, qotherPtr, "after asking for second address") // let's repeat this, but adding an IP - Debug.Printf("... and adding a new IP should invalidate both the cached responses for the name") + Log.Debugf("... and adding a new IP should invalidate both the cached responses for the name") zone.AddRecord(containerID, testName1, net.ParseIP("10.2.2.7")) assertNotInCache(t, cache, qname, "after adding a new IP") assertInCache(t, cache, qotherName, "after adding a new IP") @@ -178,11 +178,11 @@ func TestServerCacheExpiration(t *testing.T) { ) InitDefaultLogging(testing.Verbose()) - Info.Println("TestServerCacheExpiration starting") + Log.Infoln("TestServerCacheExpiration starting") clk := newMockedClock() - Debug.Printf("Creating 2 zone databases") + Log.Debugf("Creating 2 zone databases") zoneConfig := ZoneConfig{ RefreshInterval: 0, // no name updates Clock: clk, @@ -191,11 +191,11 @@ func TestServerCacheExpiration(t *testing.T) { dbs.Start() defer dbs.Stop() - Debug.Printf("Creating a cache") + Log.Debugf("Creating a cache") cache, err := NewCache(1024, clk) require.NoError(t, err) - Debug.Printf("Creating a real DNS server for the first zone database and with the cache") + Log.Debugf("Creating a real DNS server for the first zone database and with the cache") srv, err := NewDNSServer(DNSServerConfig{ Zone: dbs[0].Zone, Cache: cache, @@ -225,7 +225,7 @@ func TestServerCacheExpiration(t *testing.T) { assertNotInCache(t, cache, qName1, fmt.Sprintf("after asking for %s", testName1)) // We add the IP in the second peer right after - Debug.Printf("Adding an IPs to %s in database #2", testName1) + Log.Debugf("Adding an IPs to %s in database #2", testName1) dbs[1].Zone.AddRecord(containerID, testName1, net.ParseIP("10.2.2.1")) t.Logf("Zone database #2:\n%s", dbs[1].Zone) @@ -241,7 +241,7 @@ func TestServerCacheExpiration(t *testing.T) { assertNotInCache(t, cache, qName1, fmt.Sprintf("after asking for %s", testName1)) // We delete the IP in the second peer right after - Debug.Printf("Removing the IPs from %s in database #2", testName1) + Log.Debugf("Removing the IPs from %s in database #2", testName1) dbs[1].Zone.DeleteRecords(containerID, "", net.ParseIP("10.2.2.1")) // Check that we return to the initial state: a neg-local entry in the cache @@ -266,10 +266,10 @@ func TestServerCacheRefresh(t *testing.T) { ) InitDefaultLogging(testing.Verbose()) - Info.Println("TestServerCacheRefresh starting") + Log.Infoln("TestServerCacheRefresh starting") clk := newMockedClock() - Debug.Printf("Creating 2 zone databases") + Log.Debugf("Creating 2 zone databases") zoneConfig := ZoneConfig{ RefreshInterval: refreshInterval, Clock: clk, @@ -278,11 +278,11 @@ func TestServerCacheRefresh(t *testing.T) { dbs.Start() defer dbs.Stop() - Debug.Printf("Creating a cache") + Log.Debugf("Creating a cache") cache, err := NewCache(1024, clk) require.NoError(t, err) - Debug.Printf("Creating a real DNS server for the first zone database and with the cache") + Log.Debugf("Creating a real DNS server for the first zone database and with the cache") srv, err := NewDNSServer(DNSServerConfig{ Zone: dbs[0].Zone, Cache: cache, @@ -301,7 +301,7 @@ func TestServerCacheRefresh(t *testing.T) { require.NoError(t, err) require.NotEqual(t, 0, testPort, "listen port") - Debug.Printf("Adding an IPs to %s", testName1) + Log.Debugf("Adding an IPs to %s", testName1) dbs[1].Zone.AddRecord(containerID, testName1, net.ParseIP("10.2.2.1")) dbs.Flush() // ensure the immediate refresh is done @@ -317,7 +317,7 @@ func TestServerCacheRefresh(t *testing.T) { clk.Forward(refreshInterval / 2) dbs.Flush() - Debug.Printf("Adding an IP to %s and to %s", testName1, testName2) + Log.Debugf("Adding an IP to %s and to %s", testName1, testName2) dbs[1].Zone.AddRecord(containerID, testName1, net.ParseIP("10.2.2.2")) dbs[1].Zone.AddRecord(containerID, testName2, net.ParseIP("10.9.9.2")) diff --git a/nameserver/server_test.go b/nameserver/server_test.go index ce1d4a4c..ab19362b 100644 --- a/nameserver/server_test.go +++ b/nameserver/server_test.go @@ -41,7 +41,7 @@ func TestUDPDNSServer(t *testing.T) { testCIDR1 := testAddr1 + "/24" InitDefaultLogging(testing.Verbose()) - Info.Println("TestUDPDNSServer starting") + Log.Infoln("TestUDPDNSServer starting") zone, err := NewZoneDb(ZoneConfig{}) require.NoError(t, err) @@ -138,7 +138,7 @@ func TestTCPDNSServer(t *testing.T) { ) InitDefaultLogging(testing.Verbose()) - Info.Println("TestTCPDNSServer starting") + Log.Infoln("TestTCPDNSServer starting") zone, err := NewZoneDb(ZoneConfig{}) require.NoError(t, err) diff --git a/nameserver/zone.go b/nameserver/zone.go index fc75e612..e6598932 100644 --- a/nameserver/zone.go +++ b/nameserver/zone.go @@ -111,7 +111,7 @@ func (re *recordEntry) addIPObserver(zro ZoneRecordObserver) { func (re *recordEntry) notifyIPObservers() { numObservers := len(re.observers) if numObservers > 0 { - Debug.Printf("[zonedb] Notifying %d observers of '%s'", numObservers, re.ip) + Log.Debugf("[zonedb] Notifying %d observers of '%s'", numObservers, re.ip) for _, observer := range re.observers { observer() } @@ -257,7 +257,7 @@ func (n *name) addNameObserver(observer ZoneRecordObserver) { func (n *name) notifyNameObservers() { numObservers := len(n.observers) if numObservers > 0 { - Debug.Printf("[zonedb] Notifying %d observers of '%s'", numObservers, n.name) + Log.Debugf("[zonedb] Notifying %d observers of '%s'", numObservers, n.name) for _, observer := range n.observers { observer() } @@ -373,7 +373,7 @@ func (ns *nameSet) getNameLastAccess(n string) time.Time { // The access time is saved only for locally-introduced records (otherwise it could // be lost when names are irrelevant...) func (ns *nameSet) touchName(name string, now time.Time) { - Debug.Printf("[zonedb] Touching name %s", name) + Log.Debugf("[zonedb] Touching name %s", name) n := ns.getName(name, false) if n != nil { n.lastAccessTime = now @@ -506,9 +506,9 @@ func NewZoneDb(config ZoneConfig) (zone *ZoneDb, err error) { // Start the zone database func (zone *ZoneDb) Start() (err error) { if zone.iface != nil { - Info.Printf("[zonedb] Using mDNS on %+v", zone.iface) + Log.Infof("[zonedb] Using mDNS on %+v", zone.iface) } else { - Info.Printf("[zonedb] Using mDNS on all interfaces") + Log.Infof("[zonedb] Using mDNS on all interfaces") } if err = zone.mdnsCli.Start(zone.iface); err != nil { @@ -527,11 +527,11 @@ func (zone *ZoneDb) Start() (err error) { // Perform a graceful shutdown of the zone database func (zone *ZoneDb) Stop() error { if zone.refreshInterval > 0 { - Debug.Printf("[zonedb] Closing background updaters...") + Log.Debugf("[zonedb] Closing background updaters...") zone.refreshScheds.Stop() } - Debug.Printf("[zonedb] Exiting mDNS client and server...") + Log.Debugf("[zonedb] Exiting mDNS client and server...") zone.mdnsCli.Stop() zone.mdnsSrv.Stop() return nil @@ -555,7 +555,7 @@ func (zone *ZoneDb) Status() string { func (zone *ZoneDb) AddRecord(ident string, name string, ip net.IP) (err error) { zone.mx.Lock() defer zone.mx.Unlock() - Debug.Printf("[zonedb] Adding record: '%s'/'%s'[%s]", ident, name, ip) + Log.Debugf("[zonedb] Adding record: '%s'/'%s'[%s]", ident, name, ip) record := Record{dns.Fqdn(name), ip, 0, 0, 0} _, err = zone.getNameSet(ident).addIPToName(record, zone.clock.Now()) return @@ -638,7 +638,7 @@ func (zone *ZoneDb) String() string { // Notify that a container has died func (zone *ZoneDb) ContainerDied(ident string) error { - Info.Printf("[zonedb] Container %s down. Removing records", ident) + Log.Infof("[zonedb] Container %s down. Removing records", ident) zone.DeleteRecords(ident, "", net.IP{}) return nil } diff --git a/nameserver/zone_lookup.go b/nameserver/zone_lookup.go index 5c5aacd6..6e515b62 100644 --- a/nameserver/zone_lookup.go +++ b/nameserver/zone_lookup.go @@ -63,7 +63,7 @@ func (zone *ZoneDb) LookupName(name string) (res []ZoneRecord, err error) { // note: LookupName() is usually called from the mDNS server, so we do not touch the name name = dns.Fqdn(name) - Debug.Printf("[zonedb] Looking for name '%s' in local database", name) + Log.Debugf("[zonedb] Looking for name '%s' in local database", name) return zone.lookup(name, func(ns *nameSet) []*recordEntry { return ns.getEntriesForName(name) }) } @@ -78,23 +78,23 @@ func (zone *ZoneDb) LookupInaddr(inaddr string) (res []ZoneRecord, err error) { if err != nil { return nil, newParseError("lookup address", inaddr) } - Debug.Printf("[zonedb] Looking for address in local database: '%s' (%s)", revIPv4, inaddr) + Log.Debugf("[zonedb] Looking for address in local database: '%s' (%s)", revIPv4, inaddr) return zone.lookup(inaddr, func(ns *nameSet) []*recordEntry { return ns.getEntriesForIP(revIPv4) }) } // Perform a domain lookup with mDNS func (zone *ZoneDb) domainLookup(target string, lfun ZoneLookupFunc) (res []ZoneRecord, err error) { // no local results have been obtained in the local database: try with a mDNS query - Debug.Printf("[zonedb] '%s' not in local database... trying with mDNS", target) + Log.Debugf("[zonedb] '%s' not in local database... trying with mDNS", target) lanswers, err := lfun(target) if err != nil { - Debug.Printf("[zonedb] mDNS lookup error for '%s': %s", target, err) + Log.Debugf("[zonedb] mDNS lookup error for '%s': %s", target, err) return nil, err } // if the request has been successful, save the IP in the local database and return the corresponding ZoneRecord // (we do not get the remote ident in the mDNS reply, so we save it in a "remote" ident) - Debug.Printf("[zonedb] adding '%s' (obtained with mDNS) to '%s'", lanswers, target) + Log.Debugf("[zonedb] adding '%s' (obtained with mDNS) to '%s'", lanswers, target) res = make([]ZoneRecord, len(lanswers)) zone.mx.Lock() now := zone.clock.Now() @@ -104,7 +104,7 @@ func (zone *ZoneDb) domainLookup(target string, lfun ZoneLookupFunc) (res []Zone r, err := remoteIdent.addIPToName(answer, now) if err != nil { zone.mx.Unlock() - Warning.Printf("[zonedb] '%s' insertion for %s failed: %s", answer, target, err) + Log.Warningf("[zonedb] '%s' insertion for %s failed: %s", answer, target, err) return nil, err } uniq.add(r) @@ -118,7 +118,7 @@ func (zone *ZoneDb) domainLookup(target string, lfun ZoneLookupFunc) (res []Zone // The name can be resolved locally with the local database or with some other resolution method (eg, a mDNS query) func (zone *ZoneDb) DomainLookupName(name string) (res []ZoneRecord, err error) { name = dns.Fqdn(name) - Debug.Printf("[zonedb] Looking for name '%s' in local(&remote) database", name) + Log.Debugf("[zonedb] Looking for name '%s' in local(&remote) database", name) zone.mx.Lock() now := zone.clock.Now() @@ -128,7 +128,7 @@ func (zone *ZoneDb) DomainLookupName(name string) (res []ZoneRecord, err error) // filter the entries with expired TTL // locally introduced entries are never expired: they always have TTL=0 if ze.hasExpired(now) { - Debug.Printf("[zonedb] '%s': expired entry '%s' ignored: removing", name, ze) + Log.Debugf("[zonedb] '%s': expired entry '%s' ignored: removing", name, ze) nameset.deleteNameIP(name, net.IP{}) } else { uniq.add(ze) @@ -141,7 +141,7 @@ func (zone *ZoneDb) DomainLookupName(name string) (res []ZoneRecord, err error) zone.mx.Unlock() if len(uniq) > 0 { - Debug.Printf("[zonedb] '%s' resolved in local database", name) + Log.Debugf("[zonedb] '%s' resolved in local database", name) res = uniq.toSlice() } else { res, err = zone.domainLookup(name, zone.mdnsCli.LookupName) @@ -163,7 +163,7 @@ func (zone *ZoneDb) DomainLookupInaddr(inaddr string) (res []ZoneRecord, err err return nil, newParseError("lookup address", inaddr) } - Debug.Printf("[zonedb] Looking for address in local(&remote) database: '%s' (%s)", revIPv4, inaddr) + Log.Debugf("[zonedb] Looking for address in local(&remote) database: '%s' (%s)", revIPv4, inaddr) zone.mx.Lock() now := zone.clock.Now() @@ -173,7 +173,7 @@ func (zone *ZoneDb) DomainLookupInaddr(inaddr string) (res []ZoneRecord, err err // filter the entries with expired TTL // locally introduced entries are never expired: they always have TTL=0 if ze.hasExpired(now) { - Debug.Printf("[zonedb] '%s': expired entry '%s' ignored: removing", revIPv4, ze) + Log.Debugf("[zonedb] '%s': expired entry '%s' ignored: removing", revIPv4, ze) nameset.deleteNameIP("", revIPv4.toNetIP()) } else { uniq.add(ze) @@ -186,7 +186,7 @@ func (zone *ZoneDb) DomainLookupInaddr(inaddr string) (res []ZoneRecord, err err zone.mx.Unlock() if len(uniq) > 0 { - Debug.Printf("[zonedb] '%s' resolved in local database", inaddr) + Log.Debugf("[zonedb] '%s' resolved in local database", inaddr) res = uniq.toSlice() } else { res, err = zone.domainLookup(inaddr, zone.mdnsCli.LookupInaddr) @@ -243,7 +243,7 @@ func (zone *ZoneDb) startUpdatingName(name string) { n.lastRefreshTime = now zone.mx.Unlock() - Debug.Printf("[zonedb] Creating new immediate refresh request for '%s'", name) + Log.Debugf("[zonedb] Creating new immediate refresh request for '%s'", name) zone.refreshScheds.Add(func() time.Time { return zone.updater(name) }, now) } else { zone.mx.Unlock() @@ -261,7 +261,7 @@ func (zone *ZoneDb) updater(name string) (nextTime time.Time) { // if nobody has asked for this name for long time, just forget about it... if !zone.IsNameRelevant(name) || zone.IsNameExpired(name) { - Debug.Printf("[zonedb] '%s' seem to be irrelevant now: removing any remote information", name) + Log.Debugf("[zonedb] '%s' seem to be irrelevant now: removing any remote information", name) deleteRemoteInfo() return } @@ -269,7 +269,7 @@ func (zone *ZoneDb) updater(name string) (nextTime time.Time) { // perform the refresh for this name fullName := dns.Fqdn(name) startTime := zone.clock.Now() - Debug.Printf("[zonedb] Refreshing name '%s' with mDNS...", fullName) + Log.Debugf("[zonedb] Refreshing name '%s' with mDNS...", fullName) res, _ := zone.mdnsCli.InsistentLookupName(fullName) if res != nil && len(res) > 0 { numIps := len(res) @@ -277,14 +277,14 @@ func (zone *ZoneDb) updater(name string) (nextTime time.Time) { now := zone.clock.Now() added, removed := zone.getNameSet(defaultRemoteIdent).getName(name, true).updateIPs(res, now) zone.mx.Unlock() - Debug.Printf("[zonedb] Obtained %d IPs for name '%s' with mDNS: %d added, %d removed", + Log.Debugf("[zonedb] Obtained %d IPs for name '%s' with mDNS: %d added, %d removed", numIps, name, added, removed) // once the name has been updated, we re-schedule the update nextTime = startTime.Add(zone.refreshInterval) - Debug.Printf("[zonedb] Rescheduling update for '%s' in %s", name, nextTime.Sub(zone.clock.Now())) + Log.Debugf("[zonedb] Rescheduling update for '%s' in %s", name, nextTime.Sub(zone.clock.Now())) } else { - Debug.Printf("[zonedb] nobody knows about '%s'... removing", name) + Log.Debugf("[zonedb] nobody knows about '%s'... removing", name) deleteRemoteInfo() } return diff --git a/nameserver/zone_lookup_test.go b/nameserver/zone_lookup_test.go index 8a7d22fd..5f86f34c 100644 --- a/nameserver/zone_lookup_test.go +++ b/nameserver/zone_lookup_test.go @@ -24,7 +24,7 @@ func TestZoneRefresh(t *testing.T) { ) InitDefaultLogging(testing.Verbose()) - Info.Println("TestZoneRefresh starting") + Log.Infoln("TestZoneRefresh starting") clk := newMockedClock() @@ -40,77 +40,77 @@ func TestZoneRefresh(t *testing.T) { time.Sleep(100 * time.Millisecond) // allow for server to get going - Debug.Printf("Adding '%s' to Db #1", name) + Log.Debugf("Adding '%s' to Db #1", name) dbs[0].Zone.AddRecord("someident", name, net.ParseIP(addr1)) - Debug.Printf("Checking that the name %s is relevant (as it has been locally inserted) and not remote", name) + Log.Debugf("Checking that the name %s is relevant (as it has been locally inserted) and not remote", name) require.True(t, dbs[0].Zone.IsNameRelevant(name), "name relevant") require.True(t, dbs[0].Zone.HasNameLocalInfo(name), "local name info") require.False(t, dbs[0].Zone.HasNameRemoteInfo(name), "remote name info") - Debug.Printf("Asking for '%s' to Db #1: should get 1 IP from the local database...", name) + Log.Debugf("Asking for '%s' to Db #1: should get 1 IP from the local database...", name) res, err := dbs[0].Zone.DomainLookupName(name) require.NoError(t, err) - Debug.Printf("Got: %s", res) + Log.Debugf("Got: %s", res) t.Logf("Db #1 after the lookup:\n%s", dbs[0].Zone) require.Equal(t, 1, len(res), "lookup result") clk.Forward(refreshInterval / 2) dbs.Flush() - Debug.Printf("A couple of seconds later, we should still have one IP for that name") + Log.Debugf("A couple of seconds later, we should still have one IP for that name") res, err = dbs[0].Zone.DomainLookupName(name) require.NoError(t, err) require.Equal(t, 1, len(res), "lookup result") - Debug.Printf("And then we add 2 IPs for that name at ZoneDb 2") + Log.Debugf("And then we add 2 IPs for that name at ZoneDb 2") clk.Forward(1) dbs.Flush() - Debug.Printf("Adding 2 IPs to '%s' in Db #2", name) + Log.Debugf("Adding 2 IPs to '%s' in Db #2", name) dbs[1].Zone.AddRecord("someident", name, net.ParseIP(addr2)) dbs[1].Zone.AddRecord("someident", name, net.ParseIP(addr3)) - Debug.Printf("Perform a lookup, to ensure the name will be updated in the background...") + Log.Debugf("Perform a lookup, to ensure the name will be updated in the background...") dbs[0].Zone.DomainLookupName(name) - Debug.Printf("Wait for a while, until a refresh is performed...") + Log.Debugf("Wait for a while, until a refresh is performed...") clk.Forward(refreshInterval + 1) dbs.Flush() - Debug.Printf("A refresh should have been scheduled now: we should have 3 IPs:") - Debug.Printf("the first (local) IP and the others obtained from zone2 with a mDNS query") - Debug.Printf("Asking for '%s' again... we should have 3 IPs now", name) + Log.Debugf("A refresh should have been scheduled now: we should have 3 IPs:") + Log.Debugf("the first (local) IP and the others obtained from zone2 with a mDNS query") + Log.Debugf("Asking for '%s' again... we should have 3 IPs now", name) res, err = dbs[0].Zone.DomainLookupName(name) - Debug.Printf("Got: %s", res) + Log.Debugf("Got: %s", res) t.Logf("Db #1 after the second lookup:\n%s", dbs[0].Zone) require.Equal(t, 3, len(res), "lookup result length") - Debug.Printf("We will not ask for `name` for a while, so it will become irrelevant and will be removed...") + Log.Debugf("We will not ask for `name` for a while, so it will become irrelevant and will be removed...") clk.Forward(refreshInterval + relevantTime + 1) dbs.Flush() // the name should be irrelevant now, and all remote info should have been // removed from the zone database - Debug.Printf("Name '%s' should not be in the remote database in ZoneDb 1", name) + Log.Debugf("Name '%s' should not be in the remote database in ZoneDb 1", name) require.False(t, dbs[0].Zone.IsNameRelevant(name), "name still relevant after some inactivity time") require.True(t, dbs[0].Zone.HasNameLocalInfo(name), "local name info") require.False(t, dbs[0].Zone.HasNameRemoteInfo(name), "remote name info") - Debug.Printf("There is no remote info about this name at zone 1: a new IP appears remotely meanwhile...") + Log.Debugf("There is no remote info about this name at zone 1: a new IP appears remotely meanwhile...") clk.Forward(1) dbs.Flush() - Debug.Printf("Adding '%s' to Db #2", name) + Log.Debugf("Adding '%s' to Db #2", name) dbs[1].Zone.AddRecord("someident", name, net.ParseIP(addr4)) - Debug.Printf("When we ask about this name again, we get 4 IPs (1 local, 3 remote)") - Debug.Printf("Asking for '%s' again... the first lookup will return only the local results", name) + Log.Debugf("When we ask about this name again, we get 4 IPs (1 local, 3 remote)") + Log.Debugf("Asking for '%s' again... the first lookup will return only the local results", name) res, err = dbs[0].Zone.DomainLookupName(name) require.Equal(t, 1, len(res), "lookup result length") - Debug.Printf("... but a second lookup should return all the results in the network") + Log.Debugf("... but a second lookup should return all the results in the network") clk.Forward(refreshInterval + 1) dbs.Flush() res, err = dbs[0].Zone.DomainLookupName(name) - Debug.Printf("Got: %s", res) + Log.Debugf("Got: %s", res) require.Equal(t, 4, len(res), "lookup result length") } diff --git a/net/route.go b/net/route.go index 0d8a1bab..6d1722ad 100644 --- a/net/route.go +++ b/net/route.go @@ -16,7 +16,7 @@ func CheckNetworkFree(subnet *net.IPNet) error { } for _, route := range routes { if route.Dst != nil && overlaps(route.Dst, subnet) { - return fmt.Errorf("network %s would overlap with route %s", subnet, route.Dst) + return fmt.Errorf("Network %s overlaps with existing route %s on host.", subnet, route.Dst) } } return nil @@ -26,3 +26,18 @@ func CheckNetworkFree(subnet *net.IPNet) error { func overlaps(n1, n2 *net.IPNet) bool { return n1.Contains(n2.IP) || n2.Contains(n1.IP) } + +// For a specific address, we only care if it is actually *inside* an +// existing route, because weave-local traffic never hits IP routing. +func CheckAddressOverlap(addr net.IP) error { + routes, err := netlink.RouteList(nil, netlink.FAMILY_V4) + if err != nil { + return err + } + for _, route := range routes { + if route.Dst != nil && route.Dst.Contains(addr) { + return fmt.Errorf("Address %s overlaps with existing route %s on host.", addr, route.Dst) + } + } + return nil +} diff --git a/prog/netcheck/netcheck.go b/prog/netcheck/netcheck.go index 383f5d9b..96a26ed4 100644 --- a/prog/netcheck/netcheck.go +++ b/prog/netcheck/netcheck.go @@ -1,4 +1,4 @@ -/* netcheck: check whether a given network overlaps with any existing routes */ +/* netcheck: check whether a given network or address overlaps with any existing routes */ package main import ( @@ -10,7 +10,7 @@ import ( ) func fatal(err error) { - fmt.Println(err) + fmt.Fprintln(os.Stderr, err) os.Exit(1) } @@ -19,12 +19,17 @@ func main() { os.Exit(0) } - ipRangeStr := os.Args[1] - _, ipnet, err := net.ParseCIDR(ipRangeStr) + cidrStr := os.Args[1] + addr, ipnet, err := net.ParseCIDR(cidrStr) if err != nil { fatal(err) } - if err := weavenet.CheckNetworkFree(ipnet); err != nil { + if ipnet.IP.Equal(addr) { + err = weavenet.CheckNetworkFree(ipnet) + } else { + err = weavenet.CheckAddressOverlap(addr) + } + if err != nil { fatal(err) } os.Exit(0) diff --git a/prog/weavedns/main.go b/prog/weavedns/main.go index 21193da6..36763bc8 100644 --- a/prog/weavedns/main.go +++ b/prog/weavedns/main.go @@ -71,17 +71,17 @@ func main() { } InitDefaultLogging(debug) - Info.Printf("[main] WeaveDNS version %s\n", version) // first thing in log: the version + Log.Infof("[main] WeaveDNS version %s\n", version) // first thing in log: the version var iface *net.Interface if ifaceName != "" { var err error - Info.Println("[main] Waiting for mDNS interface", ifaceName, "to come up") + Log.Infoln("[main] Waiting for mDNS interface", ifaceName, "to come up") iface, err = weavenet.EnsureInterface(ifaceName, wait) if err != nil { - Error.Fatal(err) + Log.Fatal(err) } else { - Info.Println("[main] Interface", ifaceName, "is up") + Log.Infoln("[main] Interface", ifaceName, "is up") } } @@ -89,25 +89,25 @@ func main() { if httpIfaceName == "" { httpIP = "0.0.0.0" } else { - Info.Println("[main] Waiting for HTTP interface", httpIfaceName, "to come up") + Log.Infoln("[main] Waiting for HTTP interface", httpIfaceName, "to come up") httpIface, err := weavenet.EnsureInterface(httpIfaceName, wait) if err != nil { - Error.Fatal(err) + Log.Fatal(err) } - Info.Println("[main] Interface", httpIfaceName, "is up") + Log.Infoln("[main] Interface", httpIfaceName, "is up") addrs, err := httpIface.Addrs() if err != nil { - Error.Fatal(err) + Log.Fatal(err) } if len(addrs) == 0 { - Error.Fatal("[main] No addresses on HTTP interface") + Log.Fatal("[main] No addresses on HTTP interface") } ip, _, err := net.ParseCIDR(addrs[0].String()) if err != nil { - Error.Fatal(err) + Log.Fatal(err) } httpIP = ip.String() @@ -124,22 +124,22 @@ func main() { } zone, err := weavedns.NewZoneDb(zoneConfig) if err != nil { - Error.Fatal("[main] Unable to initialize the Zone database", err) + Log.Fatal("[main] Unable to initialize the Zone database", err) } if err := zone.Start(); err != nil { - Error.Fatal("[main] Unable to start the Zone database", err) + Log.Fatal("[main] Unable to start the Zone database", err) } defer zone.Stop() dockerCli, err = docker.NewClient(apiPath) if err != nil { - Error.Fatal("[main] Unable to start docker client: ", err) + Log.Fatal("[main] Unable to start docker client: ", err) } if watch { err := dockerCli.AddObserver(zone) if err != nil { - Error.Fatal("[main] Unable to start watcher", err) + Log.Fatal("[main] Unable to start watcher", err) } } @@ -158,29 +158,29 @@ func main() { if len(fallback) > 0 { fallbackHost, fallbackPort, err := net.SplitHostPort(fallback) if err != nil { - Error.Fatal("[main] Could not parse fallback host and port", err) + Log.Fatal("[main] Could not parse fallback host and port", err) } srvConfig.UpstreamCfg = &dns.ClientConfig{Servers: []string{fallbackHost}, Port: fallbackPort} - Debug.Printf("[main] DNS fallback at %s:%s", fallbackHost, fallbackPort) + Log.Debugf("[main] DNS fallback at %s:%s", fallbackHost, fallbackPort) } srv, err := weavedns.NewDNSServer(srvConfig) if err != nil { - Error.Fatal("[main] Failed to initialize the WeaveDNS server", err) + Log.Fatal("[main] Failed to initialize the WeaveDNS server", err) } httpListener, err := net.Listen("tcp", httpAddr) if err != nil { - Error.Fatal("[main] Unable to create http listener: ", err) + Log.Fatal("[main] Unable to create http listener: ", err) } - Info.Println("[main] HTTP API listening on", httpAddr) + Log.Infoln("[main] HTTP API listening on", httpAddr) go SignalHandlerLoop(srv) go weavedns.ServeHTTP(httpListener, version, srv, dockerCli) err = srv.Start() if err != nil { - Error.Fatal("[main] Failed to start the WeaveDNS server: ", err) + Log.Fatal("[main] Failed to start the WeaveDNS server: ", err) } srv.ActivateAndServe() } diff --git a/prog/weaveproxy/main.go b/prog/weaveproxy/main.go index 76466794..150b4788 100644 --- a/prog/weaveproxy/main.go +++ b/prog/weaveproxy/main.go @@ -5,28 +5,29 @@ import ( "os" "strings" - "code.google.com/p/getopt" + "github.com/pborman/getopt" . "github.com/weaveworks/weave/common" "github.com/weaveworks/weave/proxy" ) var ( - version = "(unreleased version)" - defaultListenAddr = "tcp://0.0.0.0:12375" + version = "(unreleased version)" + defaultListenAddrs = []string{"tcp://0.0.0.0:12375", "unix:///var/run/weave.sock"} ) func main() { var ( debug bool justVersion bool - c = proxy.Config{ListenAddr: defaultListenAddr} + c = proxy.Config{ListenAddrs: defaultListenAddrs} ) c.Version = version getopt.BoolVarLong(&debug, "debug", 'd', "log debugging information") getopt.BoolVarLong(&justVersion, "version", 0, "print version and exit") - getopt.StringVar(&c.ListenAddr, 'H', fmt.Sprintf("address on which to listen (default %s)", defaultListenAddr)) - getopt.BoolVarLong(&c.NoDefaultIPAM, "no-default-ipam", 0, "do not automatically allocate addresses for containers without a WEAVE_CIDR") + getopt.ListVar(&c.ListenAddrs, 'H', fmt.Sprintf("address on which to listen (default %s)", defaultListenAddrs)) + getopt.BoolVarLong(&c.NoDefaultIPAM, "no-default-ipalloc", 0, "do not automatically allocate addresses for containers without a WEAVE_CIDR") + getopt.BoolVarLong(&c.NoDefaultIPAM, "no-default-ipam", 0, "do not automatically allocate addresses for containers without a WEAVE_CIDR (deprecated; please use --no-default-ipalloc") getopt.StringVarLong(&c.TLSConfig.CACert, "tlscacert", 0, "Trust certs signed only by this CA") getopt.StringVarLong(&c.TLSConfig.Cert, "tlscert", 0, "Path to TLS certificate file") getopt.BoolVarLong(&c.TLSConfig.Enabled, "tls", 0, "Use TLS; implied by --tlsverify") @@ -42,32 +43,20 @@ func main() { } if c.WithDNS && c.WithoutDNS { - Error.Fatalf("Cannot use both '--with-dns' and '--without-dns' flags") + Log.Fatalf("Cannot use both '--with-dns' and '--without-dns' flags") } if debug { InitDefaultLogging(true) } - Info.Println("weave proxy", version) - Info.Println("Command line arguments:", strings.Join(os.Args[1:], " ")) - - protoAddrParts := strings.SplitN(c.ListenAddr, "://", 2) - if len(protoAddrParts) == 2 { - if protoAddrParts[0] != "tcp" { - Error.Fatalf("Invalid protocol format: %q", protoAddrParts[0]) - } - c.ListenAddr = protoAddrParts[1] - } else { - c.ListenAddr = protoAddrParts[0] - } + Log.Infoln("weave proxy", version) + Log.Infoln("Command line arguments:", strings.Join(os.Args[1:], " ")) p, err := proxy.NewProxy(c) if err != nil { - Error.Fatalf("Could not start proxy: %s", err) + Log.Fatalf("Could not start proxy: %s", err) } - if err := p.ListenAndServe(); err != nil { - Error.Fatalf("Could not listen on %s: %s", p.ListenAddr, err) - } + p.ListenAndServe() } diff --git a/prog/weaver/main.go b/prog/weaver/main.go index d0ac8596..297444f3 100644 --- a/prog/weaver/main.go +++ b/prog/weaver/main.go @@ -4,14 +4,12 @@ import ( "crypto/sha256" "flag" "fmt" - "log" "net" "net/http" "os" "runtime" "strings" - "code.google.com/p/gopacket/layers" "github.com/davecheney/profile" "github.com/gorilla/mux" . "github.com/weaveworks/weave/common" @@ -25,10 +23,6 @@ import ( var version = "(unreleased version)" func main() { - - log.SetPrefix(weave.Protocol + " ") - log.SetFlags(log.Ldate | log.Ltime | log.Lmicroseconds) - procs := runtime.NumCPU() // packet sniffing can block an OS thread, so we need one thread // for that plus at least one more. @@ -85,33 +79,33 @@ func main() { os.Exit(0) } - log.Println("Command line options:", options()) - log.Println("Command line peers:", peers) + Log.Println("Command line options:", options()) + Log.Println("Command line peers:", peers) var err error if ifaceName != "" { config.Iface, err = weavenet.EnsureInterface(ifaceName, wait) if err != nil { - log.Fatal(err) + Log.Fatal(err) } } if routerName == "" { if config.Iface == nil { - log.Fatal("Either an interface must be specified with -iface or a name with -name") + Log.Fatal("Either an interface must be specified with -iface or a name with -name") } routerName = config.Iface.HardwareAddr.String() } name, err := weave.PeerNameFromUserInput(routerName) if err != nil { - log.Fatal(err) + Log.Fatal(err) } if nickName == "" { nickName, err = os.Hostname() if err != nil { - log.Fatal(err) + Log.Fatal(err) } } @@ -119,10 +113,10 @@ func main() { password = os.Getenv("WEAVE_PASSWORD") } if password == "" { - log.Println("Communication between peers is unencrypted.") + Log.Println("Communication between peers is unencrypted.") } else { config.Password = []byte(password) - log.Println("Communication between peers is encrypted.") + Log.Println("Communication between peers is encrypted.") } if prof != "" { @@ -137,7 +131,7 @@ func main() { config.PeerDiscovery = !noDiscovery router := weave.NewRouter(config, name, nickName) - log.Println("Our name is", router.Ourself) + Log.Println("Our name is", router.Ourself) var allocator *ipam.Allocator var defaultSubnet address.CIDR @@ -146,18 +140,18 @@ func main() { allocator, defaultSubnet = createAllocator(router, iprangeCIDR, ipsubnetCIDR, determineQuorum(peerCount, peers)) dockerCli, err = docker.NewClient(apiPath) if err != nil { - Error.Fatal("Unable to start docker client: ", err) + Log.Fatal("Unable to start docker client: ", err) } if err = dockerCli.AddObserver(allocator); err != nil { - Error.Fatal("Unable to start watcher", err) + Log.Fatal("Unable to start watcher", err) } } else if peerCount > 0 { - log.Fatal("-initpeercount flag specified without -iprange") + Log.Fatal("-initpeercount flag specified without -iprange") } router.Start() if errors := router.ConnectionMaker.InitiateConnections(peers, false); len(errors) > 0 { - log.Fatal(errorMessages(errors)) + Log.Fatal(errorMessages(errors)) } // The weave script always waits for a status call to succeed, @@ -192,25 +186,31 @@ func options() map[string]string { func logFrameFunc(debug bool) weave.LogFrameFunc { if !debug { - return func(prefix string, frame []byte, eth *layers.Ethernet) {} + return func(prefix string, frame []byte, dec *weave.EthernetDecoder) {} } - return func(prefix string, frame []byte, eth *layers.Ethernet) { + return func(prefix string, frame []byte, dec *weave.EthernetDecoder) { h := fmt.Sprintf("%x", sha256.Sum256(frame)) - if eth == nil { - log.Println(prefix, len(frame), "bytes (", h, ")") - } else { - log.Println(prefix, len(frame), "bytes (", h, "):", eth.SrcMAC, "->", eth.DstMAC) + parts := []interface{}{prefix, len(frame), "bytes (", h, ")"} + + if dec != nil { + parts = append(parts, dec.Eth.SrcMAC, "->", dec.Eth.DstMAC) + + if dec.DF() { + parts = append(parts, "(DF)") + } } + + Log.Println(parts...) } } func parseAndCheckCIDR(cidrStr string) address.CIDR { _, cidr, err := address.ParseCIDR(cidrStr) if err != nil { - log.Fatal(err) + Log.Fatal(err) } if cidr.Size() < ipam.MinSubnetSize { - log.Fatalf("Allocation range smaller than minimum size %d: %s", ipam.MinSubnetSize, cidrStr) + Log.Fatalf("Allocation range smaller than minimum size %d: %s", ipam.MinSubnetSize, cidrStr) } return cidr } @@ -221,7 +221,7 @@ func createAllocator(router *weave.Router, ipRangeStr string, defaultSubnetStr s if defaultSubnetStr != "" { defaultSubnet = parseAndCheckCIDR(defaultSubnetStr) if !ipRange.Range().Overlaps(defaultSubnet.Range()) { - log.Fatalf("Default subnet %s out of bounds: %s", defaultSubnet, ipRange) + Log.Fatalf("Default subnet %s out of bounds: %s", defaultSubnet, ipRange) } } allocator := ipam.NewAllocator(router.Ourself.Peer.Name, router.Ourself.Peer.UID, router.Ourself.Peer.NickName, ipRange.Range(), quorum) @@ -248,7 +248,7 @@ func determineQuorum(initPeerCountFlag int, peers []string) uint { // specify it explicitly if that becomes a problem. clusterSize := uint(len(peers) + 1) quorum := clusterSize/2 + 1 - log.Println("Assuming quorum size of", quorum) + Log.Println("Assuming quorum size of", quorum) return quorum } @@ -298,11 +298,11 @@ func handleHTTP(router *weave.Router, httpAddr string, allocator *ipam.Allocator } l, err := net.Listen(protocol, httpAddr) if err != nil { - log.Fatal("Unable to create http listener socket: ", err) + Log.Fatal("Unable to create http listener socket: ", err) } err = http.Serve(l, nil) if err != nil { - log.Fatal("Unable to create http server", err) + Log.Fatal("Unable to create http server", err) } } diff --git a/proxy/common.go b/proxy/common.go index 45ed79d8..7231226c 100644 --- a/proxy/common.go +++ b/proxy/common.go @@ -20,7 +20,7 @@ var ( func callWeave(args ...string) ([]byte, error) { args = append([]string{"--local"}, args...) - Debug.Print("Calling weave", args) + Log.Debug("Calling weave", args) cmd := exec.Command("./weave", args...) cmd.Env = []string{"PROCFS=/hostproc", "PATH=/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"} out, err := cmd.CombinedOutput() @@ -41,14 +41,14 @@ func inspectContainerInPath(client *docker.Client, path string) (*docker.Contain subs := containerIDRegexp.FindStringSubmatch(path) if subs == nil { err := fmt.Errorf("No container id found in request with path %s", path) - Warning.Println(err) + Log.Warningln(err) return nil, err } containerID := subs[2] container, err := client.InspectContainer(containerID) if err != nil { - Warning.Printf("Error inspecting container %s: %v", containerID, err) + Log.Warningf("Error inspecting container %s: %v", containerID, err) } return container, err } diff --git a/proxy/create_container_interceptor.go b/proxy/create_container_interceptor.go index db9433ef..723a3d0b 100644 --- a/proxy/create_container_interceptor.go +++ b/proxy/create_container_interceptor.go @@ -13,6 +13,8 @@ import ( "github.com/weaveworks/weave/nameserver" ) +const MaxDockerHostname = 64 + type createContainerInterceptor struct{ proxy *Proxy } type createContainerRequestBody struct { @@ -45,7 +47,7 @@ func (i *createContainerInterceptor) InterceptRequest(r *http.Request) error { } if cidrs, ok := i.proxy.weaveCIDRsFromConfig(container.Config); ok { - Info.Printf("Creating container with WEAVE_CIDR \"%s\"", strings.Join(cidrs, " ")) + Log.Infof("Creating container with WEAVE_CIDR \"%s\"", strings.Join(cidrs, " ")) if container.HostConfig == nil { container.HostConfig = &docker.HostConfig{} } @@ -56,7 +58,7 @@ func (i *createContainerInterceptor) InterceptRequest(r *http.Request) error { if err := i.setWeaveWaitEntrypoint(container.Config); err != nil { return err } - if err := i.setWeaveDNS(&container, r); err != nil { + if err := i.setWeaveDNS(&container, r.URL.Query().Get("name")); err != nil { return err } } @@ -96,7 +98,7 @@ func (i *createContainerInterceptor) setWeaveWaitEntrypoint(container *docker.Co return nil } -func (i *createContainerInterceptor) setWeaveDNS(container *createContainerRequestBody, r *http.Request) error { +func (i *createContainerInterceptor) setWeaveDNS(container *createContainerRequestBody, name string) error { if i.proxy.WithoutDNS { return nil } @@ -108,11 +110,15 @@ func (i *createContainerInterceptor) setWeaveDNS(container *createContainerReque container.HostConfig.DNS = append(container.HostConfig.DNS, i.proxy.dockerBridgeIP) - name := r.URL.Query().Get("name") if container.Hostname == "" && name != "" { - container.Hostname = name // Strip trailing period because it's unusual to see it used on the end of a host name - container.Domainname = strings.TrimSuffix(dnsDomain, ".") + trimmedDNSDomain := strings.TrimSuffix(dnsDomain, ".") + if len(name)+1+len(trimmedDNSDomain) > MaxDockerHostname { + Log.Warningf("Container name [%s] too long to be used as hostname", name) + } else { + container.Hostname = name + container.Domainname = trimmedDNSDomain + } } if len(container.HostConfig.DNSSearch) == 0 { diff --git a/proxy/create_exec_interceptor.go b/proxy/create_exec_interceptor.go index 72e62730..5414346e 100644 --- a/proxy/create_exec_interceptor.go +++ b/proxy/create_exec_interceptor.go @@ -30,7 +30,7 @@ func (i *createExecInterceptor) InterceptRequest(r *http.Request) error { } if cidrs, ok := i.proxy.weaveCIDRsFromConfig(container.Config); ok { - Info.Printf("Exec in container %s with WEAVE_CIDR \"%s\"", container.ID, strings.Join(cidrs, " ")) + Log.Infof("Exec in container %s with WEAVE_CIDR \"%s\"", container.ID, strings.Join(cidrs, " ")) cmd := append(weaveWaitEntrypoint, "-s") options.Cmd = append(cmd, options.Cmd...) } diff --git a/proxy/proxy.go b/proxy/proxy.go index 7191a4a4..0812ab4b 100644 --- a/proxy/proxy.go +++ b/proxy/proxy.go @@ -2,10 +2,13 @@ package proxy import ( "crypto/tls" + "fmt" "net" "net/http" + "os" "regexp" "strings" + "syscall" "github.com/fsouza/go-dockerclient" . "github.com/weaveworks/weave/common" @@ -15,6 +18,8 @@ const ( defaultCaFile = "ca.pem" defaultKeyFile = "key.pem" defaultCertFile = "cert.pem" + dockerSock = "/var/run/docker.sock" + dockerSockUnix = "unix://" + dockerSock ) var ( @@ -24,7 +29,7 @@ var ( ) type Config struct { - ListenAddr string + ListenAddrs []string NoDefaultIPAM bool TLSConfig TLSConfig Version string @@ -42,10 +47,10 @@ func NewProxy(c Config) (*Proxy, error) { p := &Proxy{Config: c} if err := p.TLSConfig.loadCerts(); err != nil { - Error.Fatalf("Could not configure tls for proxy: %s", err) + Log.Fatalf("Could not configure tls for proxy: %s", err) } - client, err := docker.NewClient("unix:///var/run/docker.sock") + client, err := docker.NewClient(dockerSockUnix) if err != nil { return nil, err } @@ -63,11 +68,11 @@ func NewProxy(c Config) (*Proxy, error) { } func (proxy *Proxy) Dial() (net.Conn, error) { - return net.Dial("unix", "/var/run/docker.sock") + return net.Dial("unix", dockerSock) } func (proxy *Proxy) ServeHTTP(w http.ResponseWriter, r *http.Request) { - Info.Printf("%s %s", r.Method, r.URL) + Log.Infof("%s %s", r.Method, r.URL) path := r.URL.Path var i interceptor switch { @@ -83,19 +88,97 @@ func (proxy *Proxy) ServeHTTP(w http.ResponseWriter, r *http.Request) { proxy.Intercept(i, w, r) } -func (proxy *Proxy) ListenAndServe() error { - listener, err := net.Listen("tcp", proxy.ListenAddr) +func (proxy *Proxy) ListenAndServe() { + listeners := []net.Listener{} + addrs := []string{} + for _, addr := range proxy.ListenAddrs { + listener, normalisedAddr, err := proxy.listen(addr) + if err != nil { + Log.Fatalf("Cannot listen on %s: %s", addr, err) + } + listeners = append(listeners, listener) + addrs = append(addrs, normalisedAddr) + } + + for _, addr := range addrs { + Log.Infoln("proxy listening on", addr) + } + + errs := make(chan error) + for _, listener := range listeners { + go func(listener net.Listener) { + errs <- (&http.Server{Handler: proxy}).Serve(listener) + }(listener) + } + for range listeners { + err := <-errs + if err != nil { + Log.Fatalf("Serve failed: %s", err) + } + } +} + +func copyOwnerAndPermissions(from, to string) error { + stat, err := os.Stat(from) if err != nil { return err } - - if proxy.TLSConfig.enabled() { - listener = tls.NewListener(listener, proxy.TLSConfig.Config) + if err = os.Chmod(to, stat.Mode()); err != nil { + return err } - Info.Println("proxy listening on", proxy.ListenAddr) + moreStat, ok := stat.Sys().(*syscall.Stat_t) + if !ok { + return nil + } - return (&http.Server{Handler: proxy}).Serve(listener) + if err = os.Chown(to, int(moreStat.Uid), int(moreStat.Gid)); err != nil { + return err + } + + return nil +} + +func (proxy *Proxy) listen(protoAndAddr string) (net.Listener, string, error) { + var ( + listener net.Listener + err error + proto, addr string + ) + + if protoAddrParts := strings.SplitN(protoAndAddr, "://", 2); len(protoAddrParts) == 2 { + proto, addr = protoAddrParts[0], protoAddrParts[1] + } else if strings.HasPrefix(protoAndAddr, "/") { + proto, addr = "unix", protoAndAddr + } else { + proto, addr = "tcp", protoAndAddr + } + + switch proto { + case "tcp": + listener, err = net.Listen(proto, addr) + if err != nil { + return nil, "", err + } + if proxy.TLSConfig.enabled() { + listener = tls.NewListener(listener, proxy.TLSConfig.Config) + } + + case "unix": + os.Remove(addr) // remove socket from last invocation + listener, err = net.Listen(proto, addr) + if err != nil { + return nil, "", err + } + if err = copyOwnerAndPermissions(dockerSock, addr); err != nil { + return nil, "", err + } + + default: + Log.Fatalf("Invalid protocol format: %q", proto) + } + + return listener, fmt.Sprintf("%s://%s", proto, addr), nil } func (proxy *Proxy) weaveCIDRsFromConfig(config *docker.Config) ([]string, bool) { diff --git a/proxy/proxy_intercept.go b/proxy/proxy_intercept.go index d936bd16..1b6ca46c 100644 --- a/proxy/proxy_intercept.go +++ b/proxy/proxy_intercept.go @@ -23,7 +23,7 @@ func (proxy *Proxy) Intercept(i interceptor, w http.ResponseWriter, r *http.Requ http.Error(w, err.Error(), http.StatusNotFound) default: http.Error(w, err.Error(), http.StatusInternalServerError) - Warning.Print("Error intercepting request: ", err) + Log.Warning("Error intercepting request: ", err) } return } @@ -31,7 +31,7 @@ func (proxy *Proxy) Intercept(i interceptor, w http.ResponseWriter, r *http.Requ conn, err := proxy.Dial() if err != nil { http.Error(w, "Could not connect to target", http.StatusInternalServerError) - Warning.Print(err) + Log.Warning(err) return } client := httputil.NewClientConn(conn, nil) @@ -40,13 +40,13 @@ func (proxy *Proxy) Intercept(i interceptor, w http.ResponseWriter, r *http.Requ resp, err := client.Do(r) if err != nil && err != httputil.ErrPersistEOF { http.Error(w, fmt.Sprintf("Could not make request to target: %v", err), http.StatusInternalServerError) - Warning.Print("Error forwarding request: ", err) + Log.Warning("Error forwarding request: ", err) return } err = i.InterceptResponse(resp) if err != nil { http.Error(w, err.Error(), http.StatusInternalServerError) - Warning.Print("Error intercepting response: ", err) + Log.Warning("Error intercepting response: ", err) return } @@ -56,7 +56,7 @@ func (proxy *Proxy) Intercept(i interceptor, w http.ResponseWriter, r *http.Requ hdr.Add(k, v) } } - Debug.Printf("Response from target: %s %v", resp.Status, w.Header()) + Log.Debugf("Response from target: %s %v", resp.Status, w.Header()) if resp.Header.Get("Content-Type") == "application/vnd.docker.raw-stream" { doRawStream(w, resp, client) @@ -65,7 +65,7 @@ func (proxy *Proxy) Intercept(i interceptor, w http.ResponseWriter, r *http.Requ } else { w.WriteHeader(resp.StatusCode) if _, err := io.Copy(w, resp.Body); err != nil { - Warning.Print(err) + Log.Warning(err) } } } @@ -80,17 +80,17 @@ func doRawStream(w http.ResponseWriter, resp *http.Response, client *httputil.Cl defer up.Close() if _, err := down.Write([]byte("HTTP/1.1 200 OK\n")); err != nil { - Warning.Print(err) + Log.Warning(err) return } if err := resp.Header.Write(down); err != nil { - Warning.Print(err) + Log.Warning(err) return } if _, err := down.Write([]byte("\n")); err != nil { - Warning.Print(err) + Log.Warning(err) return } @@ -105,13 +105,13 @@ func doRawStream(w http.ResponseWriter, resp *http.Response, client *httputil.Cl func copyStream(dst io.Writer, src io.Reader, done chan struct{}) { defer close(done) if _, err := io.Copy(dst, src); err != nil { - Warning.Print(err) + Log.Warning(err) } if c, ok := dst.(interface { CloseWrite() error }); ok { if err := c.CloseWrite(); err != nil { - Warning.Printf("Error closing connection: %s", err) + Log.Warningf("Error closing connection: %s", err) } } } diff --git a/proxy/start_container_interceptor.go b/proxy/start_container_interceptor.go index 4d54680d..b7da0505 100644 --- a/proxy/start_container_interceptor.go +++ b/proxy/start_container_interceptor.go @@ -23,15 +23,15 @@ func (i *startContainerInterceptor) InterceptResponse(r *http.Response) error { cidrs, ok := i.proxy.weaveCIDRsFromConfig(container.Config) if !ok { - Debug.Print("No Weave CIDR, ignoring") + Log.Debug("No Weave CIDR, ignoring") return nil } - Info.Printf("Attaching container %s with WEAVE_CIDR \"%s\" to weave network", container.ID, strings.Join(cidrs, " ")) + Log.Infof("Attaching container %s with WEAVE_CIDR \"%s\" to weave network", container.ID, strings.Join(cidrs, " ")) args := []string{"attach"} args = append(args, cidrs...) args = append(args, "--or-die", container.ID) if output, err := callWeave(args...); err != nil { - Warning.Printf("Attaching container %s to weave network failed: %s", container.ID, string(output)) + Log.Warningf("Attaching container %s to weave network failed: %s", container.ID, string(output)) return errors.New(string(output)) } diff --git a/router/connection.go b/router/connection.go index adf9e04c..03c69a94 100644 --- a/router/connection.go +++ b/router/connection.go @@ -4,10 +4,11 @@ import ( "encoding/binary" "encoding/gob" "fmt" - "log" "net" "sync" "time" + + . "github.com/weaveworks/weave/common" ) type Connection interface { @@ -50,7 +51,7 @@ type LocalConnection struct { SessionKey *[32]byte heartbeatTCP *time.Ticker heartbeatTimeout *time.Timer - heartbeatFrame *ForwardedFrame + heartbeatFrame []byte heartbeat *time.Ticker fragTest *time.Ticker forwarder *Forwarder @@ -83,7 +84,11 @@ func (conn *RemoteConnection) BreakTie(Connection) ConnectionTieBreak { return T func (conn *RemoteConnection) Shutdown(error) {} func (conn *RemoteConnection) Log(args ...interface{}) { - log.Println(append(append([]interface{}{}, fmt.Sprintf("->[%s|%s]:", conn.remoteTCPAddr, conn.remote)), args...)...) + Log.Println(append(append([]interface{}{}, fmt.Sprintf("->[%s|%s]:", conn.remoteTCPAddr, conn.remote)), args...)...) +} + +func (conn *RemoteConnection) ErrorLog(args ...interface{}) { + Log.Errorln(append(append([]interface{}{}, fmt.Sprintf("->[%s|%s]:", conn.remoteTCPAddr, conn.remote)), args...)...) } func (conn *RemoteConnection) String() string { @@ -98,26 +103,23 @@ func (conn *RemoteConnection) String() string { return fmt.Sprint("Connection ", from, "->", to) } -func NewLocalConnection(connRemote *RemoteConnection, tcpConn *net.TCPConn, udpAddr *net.UDPAddr, router *Router) *LocalConnection { +// Does not return anything. If the connection is successful, it will +// end up in the local peer's connections map. +func StartLocalConnection(connRemote *RemoteConnection, tcpConn *net.TCPConn, udpAddr *net.UDPAddr, router *Router, acceptNewPeer bool) { if connRemote.local != router.Ourself.Peer { - log.Fatal("Attempt to create local connection from a peer which is not ourself") + Log.Fatal("Attempt to create local connection from a peer which is not ourself") } // NB, we're taking a copy of connRemote here. - return &LocalConnection{ + actionChan := make(chan ConnectionAction, ChannelSize) + finished := make(chan struct{}) + conn := &LocalConnection{ RemoteConnection: *connRemote, Router: router, TCPConn: tcpConn, remoteUDPAddr: udpAddr, - effectivePMTU: DefaultPMTU} -} - -// Async. Does not return anything. If the connection is successful, -// it will end up in the local peer's connections map. -func (conn *LocalConnection) Start(acceptNewPeer bool) { - actionChan := make(chan ConnectionAction, ChannelSize) - conn.actionChan = actionChan - finished := make(chan struct{}) - conn.finished = finished + effectivePMTU: DefaultPMTU, + actionChan: actionChan, + finished: finished} go conn.run(actionChan, finished, acceptNewPeer) } @@ -159,8 +161,7 @@ func (conn *LocalConnection) setEffectivePMTU(pmtu int) { } // Called by the connection's actor process, and by the connection's -// TCP received process. StackFrag is read in conn.Forward (called by -// router udp listener and sniffer processes) +// TCP receiver process. StackFrag is read in conn.forward func (conn *LocalConnection) setStackFrag(frag bool) { conn.Lock() defer conn.Unlock() @@ -231,7 +232,7 @@ func (conn *LocalConnection) ReceivedHeartbeat(remoteUDPAddr *net.UDPAddr, connU if oldRemoteUDPAddr == nil { return conn.sendFastHeartbeats() } else if oldRemoteUDPAddr.String() != remoteUDPAddr.String() { - log.Println("Peer", conn.remote, "moved from", old, "to", remoteUDPAddr) + Log.Println("Peer", conn.remote, "moved from", old, "to", remoteUDPAddr) } return nil }) @@ -254,15 +255,11 @@ func (conn *LocalConnection) SetEstablished() { } // Send a large frame down the DF channel in order to prompt // PMTU discovery to start. - conn.Forward(true, &ForwardedFrame{ - srcPeer: conn.local, - dstPeer: conn.remote, - frame: PMTUDiscovery}, - nil) + conn.Send(true, PMTUDiscovery) conn.heartbeat = time.NewTicker(SlowHeartbeat) conn.fragTest = time.NewTicker(FragTestInterval) // avoid initial waits for timers to fire - conn.Forward(true, conn.heartbeatFrame, nil) + conn.Send(true, conn.heartbeatFrame) conn.performFragTest() return nil }) @@ -287,7 +284,7 @@ func (conn *LocalConnection) run(actionChan <-chan ConnectionAction, finished ch conn.TCPConn.SetLinger(0) - _, dec, err := conn.handshake(acceptNewPeer) + dec, err := conn.handshake(acceptNewPeer) if err != nil { return } @@ -358,12 +355,8 @@ func (conn *LocalConnection) run(actionChan <-chan ConnectionAction, finished ch func (conn *LocalConnection) initHeartbeats() error { conn.heartbeatTCP = time.NewTicker(TCPHeartbeat) conn.heartbeatTimeout = time.NewTimer(HeartbeatTimeout) - heartbeatFrameBytes := make([]byte, EthernetOverhead+8) - binary.BigEndian.PutUint64(heartbeatFrameBytes[EthernetOverhead:], conn.uid) - conn.heartbeatFrame = &ForwardedFrame{ - srcPeer: conn.local, - dstPeer: conn.remote, - frame: heartbeatFrameBytes} + conn.heartbeatFrame = make([]byte, EthernetOverhead+8) + binary.BigEndian.PutUint64(conn.heartbeatFrame[EthernetOverhead:], conn.uid) if conn.remoteUDPAddr == nil { return nil } @@ -380,7 +373,7 @@ func (conn *LocalConnection) actorLoop(actionChan <-chan ConnectionAction) (err case <-conn.heartbeatTimeout.C: err = fmt.Errorf("timed out waiting for UDP heartbeat") case <-tickerChan(conn.heartbeat): - conn.Forward(true, conn.heartbeatFrame, nil) + conn.Send(true, conn.heartbeatFrame) case <-tickerChan(conn.fragTest): conn.performFragTest() } @@ -390,9 +383,9 @@ func (conn *LocalConnection) actorLoop(actionChan <-chan ConnectionAction) (err func (conn *LocalConnection) shutdown(err error) { if conn.remote == nil { - log.Printf("->[%s] connection shutting down due to error during handshake: %v\n", conn.remoteTCPAddr, err) + Log.Errorf("->[%s] connection shutting down due to error during handshake: %v\n", conn.remoteTCPAddr, err) } else { - conn.Log("connection shutting down due to error:", err) + conn.ErrorLog("connection shutting down due to error:", err) } if conn.TCPConn != nil { @@ -488,18 +481,14 @@ func (conn *LocalConnection) sendFastHeartbeats() error { err := conn.ensureForwarders() if err == nil { conn.heartbeat = time.NewTicker(FastHeartbeat) - conn.Forward(true, conn.heartbeatFrame, nil) // avoid initial wait + conn.Send(true, conn.heartbeatFrame) // avoid initial wait } return err } func (conn *LocalConnection) performFragTest() { conn.setStackFrag(false) - conn.Forward(false, &ForwardedFrame{ - srcPeer: conn.local, - dstPeer: conn.remote, - frame: FragTest}, - nil) + conn.Send(false, FragTest) } func tickerChan(ticker *time.Ticker) <-chan time.Time { diff --git a/router/connection_maker.go b/router/connection_maker.go index 57a93a06..acb1102d 100644 --- a/router/connection_maker.go +++ b/router/connection_maker.go @@ -3,10 +3,11 @@ package router import ( "bytes" "fmt" - "log" "math/rand" "net" "time" + + . "github.com/weaveworks/weave/common" ) const ( @@ -37,19 +38,17 @@ type Target struct { type ConnectionMakerAction func() bool func NewConnectionMaker(ourself *LocalPeer, peers *Peers, port int, discovery bool) *ConnectionMaker { - return &ConnectionMaker{ + actionChan := make(chan ConnectionMakerAction, ChannelSize) + cm := &ConnectionMaker{ ourself: ourself, peers: peers, port: port, discovery: discovery, directPeers: peerAddrs{}, - targets: make(map[string]*Target)} -} - -func (cm *ConnectionMaker) Start() { - actionChan := make(chan ConnectionMakerAction, ChannelSize) - cm.actionChan = actionChan + targets: make(map[string]*Target), + actionChan: actionChan} go cm.queryLoop(actionChan) + return cm } func (cm *ConnectionMaker) InitiateConnections(peers []string, replace bool) []error { @@ -300,9 +299,9 @@ func (cm *ConnectionMaker) connectToTargets(validTarget map[string]struct{}, dir } func (cm *ConnectionMaker) attemptConnection(address string, acceptNewPeer bool) { - log.Printf("->[%s] attempting connection\n", address) + Log.Printf("->[%s] attempting connection\n", address) if err := cm.ourself.CreateConnection(address, acceptNewPeer); err != nil { - log.Printf("->[%s] error during connection attempt: %v\n", address, err) + Log.Errorf("->[%s] error during connection attempt: %v\n", address, err) cm.ConnectionTerminated(address, err) } } diff --git a/router/crypto.go b/router/crypto.go index 291603d1..b66d2b73 100644 --- a/router/crypto.go +++ b/router/crypto.go @@ -8,9 +8,9 @@ import ( "fmt" "sync" - "code.google.com/p/go-bit/bit" - "code.google.com/p/go.crypto/nacl/box" - "code.google.com/p/go.crypto/nacl/secretbox" + "github.com/andybalholm/go-bit" + "golang.org/x/crypto/nacl/box" + "golang.org/x/crypto/nacl/secretbox" ) func GenerateKeyPair() (publicKey, privateKey *[32]byte, err error) { diff --git a/router/ethernet_decoder.go b/router/ethernet_decoder.go index 297a2011..0404f182 100644 --- a/router/ethernet_decoder.go +++ b/router/ethernet_decoder.go @@ -2,28 +2,32 @@ package router import ( "bytes" - "log" "net" - "code.google.com/p/gopacket" - "code.google.com/p/gopacket/layers" + "github.com/google/gopacket" + "github.com/google/gopacket/layers" + . "github.com/weaveworks/weave/common" ) type EthernetDecoder struct { - eth layers.Ethernet - ip layers.IPv4 + Eth layers.Ethernet + IP layers.IPv4 decoded []gopacket.LayerType parser *gopacket.DecodingLayerParser } func NewEthernetDecoder() *EthernetDecoder { dec := &EthernetDecoder{} - dec.parser = gopacket.NewDecodingLayerParser(layers.LayerTypeEthernet, &dec.eth, &dec.ip) + dec.parser = gopacket.NewDecodingLayerParser(layers.LayerTypeEthernet, &dec.Eth, &dec.IP) return dec } -func (dec *EthernetDecoder) DecodeLayers(data []byte) error { - return dec.parser.DecodeLayers(data, &dec.decoded) +func (dec *EthernetDecoder) DecodeLayers(data []byte) { + // We intentionally discard the error return here, because it + // is normal for gopacket to return an error saying that it + // cannot decode a layer beyond the ones we specified when + // setting up the parser. + dec.parser.DecodeLayers(data, &dec.decoded) } func (dec *EthernetDecoder) sendICMPFragNeeded(mtu int, sendFrame func([]byte) error) error { @@ -31,23 +35,23 @@ func (dec *EthernetDecoder) sendICMPFragNeeded(mtu int, sendFrame func([]byte) e opts := gopacket.SerializeOptions{ FixLengths: true, ComputeChecksums: true} - ipHeaderSize := int(dec.ip.IHL) * 4 // IHL is the number of 32-byte words in the header - payload := gopacket.Payload(dec.ip.BaseLayer.Contents[:ipHeaderSize+8]) + ipHeaderSize := int(dec.IP.IHL) * 4 // IHL is the number of 32-byte words in the header + payload := gopacket.Payload(dec.IP.BaseLayer.Contents[:ipHeaderSize+8]) err := gopacket.SerializeLayers(buf, opts, &layers.Ethernet{ - SrcMAC: dec.eth.DstMAC, - DstMAC: dec.eth.SrcMAC, - EthernetType: dec.eth.EthernetType}, + SrcMAC: dec.Eth.DstMAC, + DstMAC: dec.Eth.SrcMAC, + EthernetType: dec.Eth.EthernetType}, &layers.IPv4{ Version: 4, - TOS: dec.ip.TOS, + TOS: dec.IP.TOS, Id: 0, Flags: 0, FragOffset: 0, TTL: 64, Protocol: layers.IPProtocolICMPv4, - DstIP: dec.ip.SrcIP, - SrcIP: dec.ip.DstIP}, + DstIP: dec.IP.SrcIP, + SrcIP: dec.IP.DstIP}, &layers.ICMPv4{ TypeCode: 0x304, Id: 0, @@ -57,7 +61,7 @@ func (dec *EthernetDecoder) sendICMPFragNeeded(mtu int, sendFrame func([]byte) e return err } - log.Printf("Sending ICMP 3,4 (%v -> %v): PMTU= %v\n", dec.ip.DstIP, dec.ip.SrcIP, mtu) + Log.Printf("Sending ICMP 3,4 (%v -> %v): PMTU= %v\n", dec.IP.DstIP, dec.IP.SrcIP, mtu) return sendFrame(buf.Bytes()) } @@ -68,10 +72,14 @@ var ( ) func (dec *EthernetDecoder) DropFrame() bool { - return bytes.Equal(stpMACPrefix, dec.eth.DstMAC[:len(stpMACPrefix)]) + return bytes.Equal(stpMACPrefix, dec.Eth.DstMAC[:len(stpMACPrefix)]) } func (dec *EthernetDecoder) IsSpecial() bool { - return dec.eth.Length == 0 && dec.eth.EthernetType == layers.EthernetTypeLLC && - bytes.Equal(zeroMAC, dec.eth.SrcMAC) && bytes.Equal(zeroMAC, dec.eth.DstMAC) + return dec.Eth.Length == 0 && dec.Eth.EthernetType == layers.EthernetTypeLLC && + bytes.Equal(zeroMAC, dec.Eth.SrcMAC) && bytes.Equal(zeroMAC, dec.Eth.DstMAC) +} + +func (dec *EthernetDecoder) DF() bool { + return len(dec.decoded) == 2 && (dec.IP.Flags&layers.IPv4DontFragment != 0) } diff --git a/router/forwarder.go b/router/forwarder.go index 802369bd..a61eb782 100644 --- a/router/forwarder.go +++ b/router/forwarder.go @@ -4,8 +4,8 @@ import ( "syscall" "time" - "code.google.com/p/gopacket" - "code.google.com/p/gopacket/layers" + "github.com/google/gopacket" + "github.com/google/gopacket/layers" ) type ForwardedFrame struct { @@ -40,16 +40,12 @@ func (conn *LocalConnection) ensureForwarders() error { forwarder := NewForwarder(conn, encryptor, udpSender, DefaultPMTU) forwarderDF := NewForwarderDF(conn, encryptorDF, udpSenderDF, DefaultPMTU) - effectivePMTU := forwarderDF.unverifiedPMTU - forwarder.Start() - forwarderDF.Start() // Various fields in the conn struct are read by other processes, // so we have to use locks. conn.Lock() conn.forwarder = forwarder conn.forwarderDF = forwarderDF - conn.effectivePMTU = effectivePMTU conn.Unlock() return nil @@ -63,11 +59,23 @@ func (conn *LocalConnection) stopForwarders() { conn.forwarderDF.Shutdown() } -// Called from peer.Relay[Broadcast] which is itself invoked from -// router (both UDP listener process and sniffer process). Also called -// from connection's heartbeat process, and from the connection's TCP -// receiver process. -func (conn *LocalConnection) Forward(df bool, frame *ForwardedFrame, dec *EthernetDecoder) error { +// Called from connection's actor process, and from the connection's +// TCP receiver process. +func (conn *LocalConnection) Send(df bool, frameBytes []byte) error { + frame := &ForwardedFrame{ + srcPeer: conn.local, + dstPeer: conn.remote, + frame: frameBytes} + return conn.forward(frame, nil, df) +} + +// Called from LocalPeer.Relay[Broadcast] which is itself invoked from +// router (both UDP listener process and sniffer process). +func (conn *LocalConnection) Forward(frame *ForwardedFrame, dec *EthernetDecoder) error { + return conn.forward(frame, dec, dec != nil && dec.DF()) +} + +func (conn *LocalConnection) forward(frame *ForwardedFrame, dec *EthernetDecoder, df bool) error { conn.RLock() var ( forwarder = conn.forwarder @@ -81,6 +89,7 @@ func (conn *LocalConnection) Forward(df bool, frame *ForwardedFrame, dec *Ethern conn.Log("Cannot forward frame yet - awaiting contact") return nil } + // We could use non-blocking channel sends here, i.e. drop frames // on the floor when the forwarder is busy. This would allow our // caller - the capturing loop in the router - to read frames more @@ -109,11 +118,10 @@ func (conn *LocalConnection) Forward(df bool, frame *ForwardedFrame, dec *Ethern forwarderDF.Forward(frame) return nil } - conn.Router.LogFrame("Fragmenting", frame.frame, &dec.eth) // We can't trust the stack to fragment, we have IP, and we // have a frame that's too big for the MTU, so we have to // fragment it ourself. - return fragment(dec.eth, dec.ip, effectivePMTU, frame, func(segFrame *ForwardedFrame) { + return fragment(dec.Eth, dec.IP, effectivePMTU, frame, func(segFrame *ForwardedFrame) { forwarderDF.Forward(segFrame) }) } @@ -195,20 +203,18 @@ type Forwarder struct { } func NewForwarder(conn *LocalConnection, enc Encryptor, udpSender UDPSender, pmtu int) *Forwarder { - return &Forwarder{ + ch := make(chan *ForwardedFrame, ChannelSize) + finished := make(chan struct{}) + fwd := &Forwarder{ conn: conn, + ch: ch, + finished: finished, enc: enc, udpSender: udpSender, maxPayload: pmtu - UDPOverhead, processSendError: func(err error) error { return err }} -} - -func (fwd *Forwarder) Start() { - ch := make(chan *ForwardedFrame, ChannelSize) - fwd.ch = ch - finished := make(chan struct{}) - fwd.finished = finished go fwd.run(ch, finished) + return fwd } func (fwd *Forwarder) Shutdown() { @@ -275,7 +281,7 @@ func (fwd *Forwarder) accumulateAndSendFrames(ch <-chan *ForwardedFrame, frame * } func (fwd *Forwarder) logDrop(frame *ForwardedFrame) { - fwd.conn.Log("Dropping too big frame during forwarding: frame len:", len(frame.frame), "; effective PMTU:", fwd.maxPayload+UDPOverhead-fwd.effectiveOverhead()) + fwd.conn.ErrorLog("Dropping too big frame during forwarding: frame len:", len(frame.frame), "; effective PMTU:", fwd.maxPayload+UDPOverhead-fwd.effectiveOverhead()) } func (fwd *Forwarder) appendFrame(frame *ForwardedFrame) bool { @@ -310,25 +316,23 @@ type ForwarderDF struct { } func NewForwarderDF(conn *LocalConnection, enc Encryptor, udpSender UDPSender, pmtu int) *ForwarderDF { + ch := make(chan *ForwardedFrame, ChannelSize) + finished := make(chan struct{}) + verifyPMTU := make(chan int, ChannelSize) fwd := &ForwarderDF{ Forwarder: Forwarder{ conn: conn, + ch: ch, + finished: finished, enc: enc, udpSender: udpSender, - maxPayload: pmtu - UDPOverhead}} + maxPayload: pmtu - UDPOverhead}, + verifyPMTU: verifyPMTU} fwd.Forwarder.processSendError = fwd.processSendError fwd.unverifiedPMTU = pmtu - fwd.effectiveOverhead() - return fwd -} - -func (fwd *ForwarderDF) Start() { - ch := make(chan *ForwardedFrame, ChannelSize) - fwd.ch = ch - finished := make(chan struct{}) - fwd.finished = finished - verifyPMTU := make(chan int, ChannelSize) - fwd.verifyPMTU = verifyPMTU + conn.setEffectivePMTU(fwd.unverifiedPMTU) go fwd.run(ch, finished, verifyPMTU) + return fwd } func (fwd *ForwarderDF) PMTUVerified(pmtu int) { diff --git a/router/gossip.go b/router/gossip.go index f66ea9d0..a3af241b 100644 --- a/router/gossip.go +++ b/router/gossip.go @@ -40,13 +40,15 @@ type GossipSender struct { } func NewGossipSender(send func(GossipData)) *GossipSender { - return &GossipSender{send: send} -} - -func (sender *GossipSender) Start() { - sender.cell = make(chan GossipData, 1) - sender.flushch = make(chan chan bool) + cell := make(chan GossipData, 1) + flushch := make(chan chan bool) + sender := &GossipSender{ + send: send, + cell: cell, + flushch: flushch, + } go sender.run() + return sender } func (sender *GossipSender) run() { diff --git a/router/gossip_channel.go b/router/gossip_channel.go index da7dc0ec..795573f8 100644 --- a/router/gossip_channel.go +++ b/router/gossip_channel.go @@ -3,8 +3,10 @@ package router import ( "bytes" "encoding/gob" - "log" + "fmt" "sync" + + . "github.com/weaveworks/weave/common" ) type GossipChannel struct { @@ -58,7 +60,12 @@ func (c *GossipChannel) deliverUnicast(srcName PeerName, origPayload []byte, dec return err } if c.ourself.Name != destName { - return c.relayUnicast(destName, origPayload) + if err := c.relayUnicast(destName, origPayload); err != nil { + // just log errors from relayUnicast; a problem between us and destination + // is not enough reason to break the connection from the source + c.log(err) + } + return nil } var payload []byte if err := dec.Decode(&payload); err != nil { @@ -147,7 +154,6 @@ func (c *GossipChannel) sendDown(conn Connection, data GossipData) { } }) c.senders[conn] = sender - sender.Start() } sender.Send(data) } @@ -160,15 +166,15 @@ func (c *GossipChannel) GossipBroadcast(update GossipData) error { return c.relayBroadcast(c.ourself.Name, update) } -func (c *GossipChannel) relayUnicast(dstPeerName PeerName, buf []byte) error { +func (c *GossipChannel) relayUnicast(dstPeerName PeerName, buf []byte) (err error) { if relayPeerName, found := c.routes.UnicastAll(dstPeerName); !found { - c.log("unknown relay destination:", dstPeerName) + err = fmt.Errorf("unknown relay destination: %s", dstPeerName) } else if conn, found := c.ourself.ConnectionTo(relayPeerName); !found { - c.log("unable to find connection to relay peer", relayPeerName) + err = fmt.Errorf("unable to find connection to relay peer %s", relayPeerName) } else { conn.(ProtocolSender).SendProtocolMsg(ProtocolMsg{ProtocolGossipUnicast, buf}) } - return nil + return err } func (c *GossipChannel) relayBroadcast(srcName PeerName, update GossipData) error { @@ -198,7 +204,6 @@ func (c *GossipChannel) relayBroadcast(srcName PeerName, update GossipData) erro if !found { broadcaster = NewGossipSender(func(pending GossipData) { c.sendBroadcast(srcName, pending) }) c.broadcasters[srcName] = broadcaster - broadcaster.Start() } broadcaster.Send(update) return nil @@ -221,5 +226,5 @@ func (c *GossipChannel) sendBroadcast(srcName PeerName, update GossipData) { } func (c *GossipChannel) log(args ...interface{}) { - log.Println(append(append([]interface{}{}, "[gossip "+c.name+"]:"), args...)...) + Log.Println(append(append([]interface{}{}, "[gossip "+c.name+"]:"), args...)...) } diff --git a/router/gossip_test.go b/router/gossip_test.go index c1ace338..c6936a09 100644 --- a/router/gossip_test.go +++ b/router/gossip_test.go @@ -18,15 +18,10 @@ type mockChannelConnection struct { dest *Router } -// Construct a "passive" Router, i.e. without any goroutines, except -// for Routes and GossipSenders. func NewTestRouter(name string) *Router { peerName, _ := PeerNameFromString(name) - router := NewRouter(Config{}, peerName, "") - // need to create a dummy channel otherwise tests hang on nil - // channels when the Router invoked ConnectionMaker.Refresh - router.ConnectionMaker.actionChan = make(chan ConnectionMakerAction, ChannelSize) - router.Routes.Start() + router := NewRouter(Config{}, peerName, "nick") + router.Start() return router } diff --git a/router/handshake.go b/router/handshake.go index 25a93690..d90423e7 100644 --- a/router/handshake.go +++ b/router/handshake.go @@ -45,7 +45,7 @@ func (fv *FieldValidator) Err() error { return fv.err } -func (conn *LocalConnection) handshake(acceptNewPeer bool) (*gob.Encoder, *gob.Decoder, error) { +func (conn *LocalConnection) handshake(acceptNewPeer bool) (*gob.Decoder, error) { // We do not need to worry about locking in here as at this point // the connection is not reachable by any go-routine other than // ourself. Only when we add this connection to the conn.local @@ -54,7 +54,7 @@ func (conn *LocalConnection) handshake(acceptNewPeer bool) (*gob.Encoder, *gob.D conn.TCPConn.SetDeadline(time.Now().Add(HeaderTimeout)) version, err := exchangeProtocolHeader(conn.TCPConn, conn.TCPConn) if err != nil { - return nil, nil, err + return nil, err } conn.version = version conn.TCPConn.SetDeadline(time.Time{}) @@ -66,7 +66,7 @@ func (conn *LocalConnection) handshake(acceptNewPeer bool) (*gob.Encoder, *gob.D dec := gob.NewDecoder(conn.TCPConn) fv, private, err := conn.exchangeHandshake(localConnID, usingPassword, enc, dec) if err != nil { - return nil, nil, err + return nil, err } nameStr, _ := fv.Value("Name") @@ -74,39 +74,39 @@ func (conn *LocalConnection) handshake(acceptNewPeer bool) (*gob.Encoder, *gob.D uidStr, _ := fv.Value("UID") remoteConnIDStr, _ := fv.Value("ConnID") if err := fv.Err(); err != nil { - return nil, nil, err + return nil, err } name, err := PeerNameFromString(nameStr) if err != nil { - return nil, nil, err + return nil, err } if !acceptNewPeer { if _, found := conn.Router.Peers.Fetch(name); !found { - return nil, nil, fmt.Errorf("Found unknown remote name: %s at %s", name, conn.remoteTCPAddr) + return nil, fmt.Errorf("Found unknown remote name: %s at %s", name, conn.remoteTCPAddr) } } if existingConn, found := conn.Router.Ourself.ConnectionTo(name); found && existingConn.Established() { - return nil, nil, fmt.Errorf("Already have connection to %s at %s", existingConn.Remote(), existingConn.RemoteTCPAddr()) + return nil, fmt.Errorf("Already have connection to %s at %s", existingConn.Remote(), existingConn.RemoteTCPAddr()) } uid, err := ParsePeerUID(uidStr) if err != nil { - return nil, nil, err + return nil, err } remoteConnID, err := strconv.ParseUint(remoteConnIDStr, 10, 64) if err != nil { - return nil, nil, err + return nil, err } conn.uid = localConnID ^ remoteConnID remotePublicStr, rpErr := fv.Value("PublicKey") if usingPassword { if rpErr != nil { - return nil, nil, rpErr + return nil, rpErr } remotePublicSlice, rpErr := hex.DecodeString(remotePublicStr) if rpErr != nil { - return nil, nil, rpErr + return nil, rpErr } remotePublic := [32]byte{} for idx, elem := range remotePublicSlice { @@ -117,13 +117,13 @@ func (conn *LocalConnection) handshake(acceptNewPeer bool) (*gob.Encoder, *gob.D conn.Decryptor = NewNaClDecryptor(conn.SessionKey, conn.outbound) } else { if rpErr == nil { - return nil, nil, fmt.Errorf("Remote network is encrypted. Password required.") + return nil, fmt.Errorf("Remote network is encrypted. Password required.") } conn.tcpSender = NewSimpleTCPSender(enc) conn.Decryptor = NewNonDecryptor() } - return enc, dec, conn.setRemote(NewPeer(name, nickNameStr, uid, 0)) + return dec, conn.setRemote(NewPeer(name, nickNameStr, uid, 0)) } func (conn *LocalConnection) exchangeHandshake(localConnID uint64, usingPassword bool, enc *gob.Encoder, dec *gob.Decoder) (*FieldValidator, *[32]byte, error) { diff --git a/router/local_peer.go b/router/local_peer.go index 09498629..3c9ac880 100644 --- a/router/local_peer.go +++ b/router/local_peer.go @@ -2,10 +2,11 @@ package router import ( "fmt" - "log" "net" "sync" "time" + + . "github.com/weaveworks/weave/common" ) type LocalPeer struct { @@ -18,60 +19,61 @@ type LocalPeer struct { type LocalPeerAction func() func NewLocalPeer(name PeerName, nickName string, router *Router) *LocalPeer { - return &LocalPeer{Peer: NewPeer(name, nickName, 0, 0), router: router} -} - -func (peer *LocalPeer) Start() { actionChan := make(chan LocalPeerAction, ChannelSize) - peer.actionChan = actionChan + peer := &LocalPeer{ + Peer: NewPeer(name, nickName, 0, 0), + router: router, + actionChan: actionChan, + } go peer.actorLoop(actionChan) + return peer } -func (peer *LocalPeer) Forward(dstPeer *Peer, df bool, frame []byte, dec *EthernetDecoder) error { - return peer.Relay(peer.Peer, dstPeer, df, frame, dec) +func (peer *LocalPeer) Forward(dstPeer *Peer, frame []byte, dec *EthernetDecoder) error { + return peer.Relay(peer.Peer, dstPeer, frame, dec) } -func (peer *LocalPeer) Broadcast(df bool, frame []byte, dec *EthernetDecoder) { - peer.RelayBroadcast(peer.Peer, df, frame, dec) +func (peer *LocalPeer) Broadcast(frame []byte, dec *EthernetDecoder) { + peer.RelayBroadcast(peer.Peer, frame, dec) } -func (peer *LocalPeer) Relay(srcPeer, dstPeer *Peer, df bool, frame []byte, dec *EthernetDecoder) error { +func (peer *LocalPeer) Relay(srcPeer, dstPeer *Peer, frame []byte, dec *EthernetDecoder) error { relayPeerName, found := peer.router.Routes.Unicast(dstPeer.Name) if !found { // Not necessarily an error as there could be a race with the // dst disappearing whilst the frame is in flight - log.Println("Received packet for unknown destination:", dstPeer) + Log.Println("Received packet for unknown destination:", dstPeer) return nil } conn, found := peer.ConnectionTo(relayPeerName) if !found { // Again, could just be a race, not necessarily an error - log.Println("Unable to find connection to relay peer", relayPeerName) + Log.Println("Unable to find connection to relay peer", relayPeerName) return nil } - return conn.(*LocalConnection).Forward(df, &ForwardedFrame{ + return conn.(*LocalConnection).Forward(&ForwardedFrame{ srcPeer: srcPeer, dstPeer: dstPeer, frame: frame}, dec) } -func (peer *LocalPeer) RelayBroadcast(srcPeer *Peer, df bool, frame []byte, dec *EthernetDecoder) { +func (peer *LocalPeer) RelayBroadcast(srcPeer *Peer, frame []byte, dec *EthernetDecoder) { nextHops := peer.router.Routes.Broadcast(srcPeer.Name) if len(nextHops) == 0 { return } for _, conn := range peer.ConnectionsTo(nextHops) { - err := conn.(*LocalConnection).Forward(df, &ForwardedFrame{ + err := conn.(*LocalConnection).Forward(&ForwardedFrame{ srcPeer: srcPeer, dstPeer: conn.Remote(), frame: frame}, dec) if err != nil { if ftbe, ok := err.(FrameTooBigError); ok { - log.Printf("dropping too big DF broadcast frame (%v -> %v): PMTU= %v\n", dec.ip.DstIP, dec.ip.SrcIP, ftbe.EPMTU) + Log.Warningf("dropping too big DF broadcast frame (%v -> %v): PMTU= %v\n", dec.IP.DstIP, dec.IP.SrcIP, ftbe.EPMTU) } else { - log.Println(err) + Log.Errorln(err) } } } @@ -132,8 +134,7 @@ func (peer *LocalPeer) CreateConnection(peerAddr string, acceptNewPeer bool) err return err } connRemote := NewRemoteConnection(peer.Peer, nil, tcpConn.RemoteAddr().String(), true, false) - connLocal := NewLocalConnection(connRemote, tcpConn, udpAddr, peer.router) - connLocal.Start(acceptNewPeer) + StartLocalConnection(connRemote, tcpConn, udpAddr, peer.router, acceptNewPeer) return nil } @@ -181,10 +182,10 @@ func (peer *LocalPeer) actorLoop(actionChan <-chan LocalPeerAction) { func (peer *LocalPeer) handleAddConnection(conn Connection) error { if peer.Peer != conn.Local() { - log.Fatal("Attempt made to add connection to peer where peer is not the source of connection") + Log.Fatal("Attempt made to add connection to peer where peer is not the source of connection") } if conn.Remote() == nil { - log.Fatal("Attempt made to add connection to peer with unknown remote peer") + Log.Fatal("Attempt made to add connection to peer with unknown remote peer") } toName := conn.Remote().Name dupErr := fmt.Errorf("Multiple connections to %s added to %s", conn.Remote(), peer.String()) @@ -223,7 +224,7 @@ func (peer *LocalPeer) handleAddConnection(conn Connection) error { func (peer *LocalPeer) handleConnectionEstablished(conn Connection) { if peer.Peer != conn.Local() { - log.Fatal("Peer informed of active connection where peer is not the source of connection") + Log.Fatal("Peer informed of active connection where peer is not the source of connection") } if dupConn, found := peer.connections[conn.Remote().Name]; !found || conn != dupConn { conn.Shutdown(fmt.Errorf("Cannot set unknown connection active")) @@ -236,10 +237,10 @@ func (peer *LocalPeer) handleConnectionEstablished(conn Connection) { func (peer *LocalPeer) handleDeleteConnection(conn Connection) { if peer.Peer != conn.Local() { - log.Fatal("Attempt made to delete connection from peer where peer is not the source of connection") + Log.Fatal("Attempt made to delete connection from peer where peer is not the source of connection") } if conn.Remote() == nil { - log.Fatal("Attempt made to delete connection to peer with unknown remote peer") + Log.Fatal("Attempt made to delete connection to peer with unknown remote peer") } toName := conn.Remote().Name if connFound, found := peer.connections[toName]; !found || connFound != conn { diff --git a/router/mac_cache.go b/router/mac_cache.go index d251d194..5eb03f41 100644 --- a/router/mac_cache.go +++ b/router/mac_cache.go @@ -22,14 +22,12 @@ type MacCache struct { } func NewMacCache(maxAge time.Duration, onExpiry func(net.HardwareAddr, *Peer)) *MacCache { - return &MacCache{ + cache := &MacCache{ table: make(map[uint64]*MacCacheEntry), maxAge: maxAge, onExpiry: onExpiry} -} - -func (cache *MacCache) Start() { cache.setExpiryTimer() + return cache } func (cache *MacCache) Enter(mac net.HardwareAddr, peer *Peer) bool { diff --git a/router/pcap.go b/router/pcap.go index 07d8b1d9..36962f20 100644 --- a/router/pcap.go +++ b/router/pcap.go @@ -3,7 +3,7 @@ package router import ( "fmt" - "code.google.com/p/gopacket/pcap" + "github.com/google/gopacket/pcap" ) type PcapIO struct { diff --git a/router/router.go b/router/router.go index ab671a0d..00f53588 100644 --- a/router/router.go +++ b/router/router.go @@ -5,13 +5,11 @@ import ( "encoding/binary" "fmt" "io" - "log" "net" "sync" "syscall" "time" - "code.google.com/p/gopacket/layers" . "github.com/weaveworks/weave/common" ) @@ -27,7 +25,7 @@ const ( // against brute-force attacks on the password when encryption is in // use. It is also a basic DoS defence. -type LogFrameFunc func(string, []byte, *layers.Ethernet) +type LogFrameFunc func(string, []byte, *EthernetDecoder) type Config struct { Port int @@ -68,11 +66,11 @@ type PacketSourceSink interface { func NewRouter(config Config, name PeerName, nickName string) *Router { router := &Router{Config: config, gossipChannels: make(GossipChannels)} onMacExpiry := func(mac net.HardwareAddr, peer *Peer) { - log.Println("Expired MAC", mac, "at", peer) + Log.Println("Expired MAC", mac, "at", peer) } onPeerGC := func(peer *Peer) { router.Macs.Delete(peer) - log.Println("Removed unreachable peer", peer) + Log.Println("Removed unreachable peer", peer) } router.Ourself = NewLocalPeer(name, nickName, router) router.Macs = NewMacCache(macMaxAge, onMacExpiry) @@ -84,6 +82,9 @@ func NewRouter(config Config, name PeerName, nickName string) *Router { return router } +// Start listening for TCP connections, locally captured packets, and +// packets forwarded over UDP. This is separate from NewRouter so +// that gossipers can register before we start forming connections. func (router *Router) Start() { // we need two pcap handles since they aren't thread-safe var pio PacketSourceSink @@ -95,10 +96,6 @@ func (router *Router) Start() { po, err = NewPcapO(router.Iface.Name) checkFatal(err) } - router.Ourself.Start() - router.Macs.Start() - router.Routes.Start() - router.ConnectionMaker.Start() router.UDPListener = router.listenUDP(router.Port, po) router.listenTCP(router.Port) if pio != nil { @@ -129,12 +126,12 @@ func (router *Router) Status() string { } func (router *Router) sniff(pio PacketSourceSink) { - log.Println("Sniffing traffic on", router.Iface) + Log.Println("Sniffing traffic on", router.Iface) dec := NewEthernetDecoder() mac := router.Iface.HardwareAddr if router.Macs.Enter(mac, router.Ourself.Peer) { - log.Println("Discovered our MAC", mac) + Log.Println("Discovered our MAC", mac) } go func() { for { @@ -152,7 +149,7 @@ func (router *Router) handleCapturedPacket(frameData []byte, dec *EthernetDecode if decodedLen == 0 { return } - srcMac := dec.eth.SrcMAC + srcMac := dec.Eth.SrcMAC srcPeer, found := router.Macs.Lookup(srcMac) // We need to filter out frames we injected ourselves. For such // frames, the srcMAC will have been recorded as associated with a @@ -161,22 +158,18 @@ func (router *Router) handleCapturedPacket(frameData []byte, dec *EthernetDecode return } if router.Macs.Enter(srcMac, router.Ourself.Peer) { - log.Println("Discovered local MAC", srcMac) + Log.Println("Discovered local MAC", srcMac) } if dec.DropFrame() { return } - dstMac := dec.eth.DstMAC + dstMac := dec.Eth.DstMAC dstPeer, found := router.Macs.Lookup(dstMac) if found && dstPeer == router.Ourself.Peer { return } - df := decodedLen == 2 && (dec.ip.Flags&layers.IPv4DontFragment != 0) - if df { - router.LogFrame("Forwarding DF", frameData, &dec.eth) - } else { - router.LogFrame("Forwarding", frameData, &dec.eth) - } + router.LogFrame("Forwarding", frameData, dec) + // at this point we are handing over the frame to forwarders, so // we need to make a copy of it in order to prevent the next // capture from overwriting the data @@ -187,11 +180,11 @@ func (router *Router) handleCapturedPacket(frameData []byte, dec *EthernetDecode // If we don't know which peer corresponds to the dest MAC, // broadcast it. if !found { - router.Ourself.Broadcast(df, frameCopy, dec) + router.Ourself.Broadcast(frameCopy, dec) return } - err := router.Ourself.Forward(dstPeer, df, frameCopy, dec) + err := router.Ourself.Forward(dstPeer, frameCopy, dec) if ftbe, ok := err.(FrameTooBigError); ok { err = dec.sendICMPFragNeeded(ftbe.EPMTU, po.WritePacket) } @@ -208,7 +201,7 @@ func (router *Router) listenTCP(localPort int) { for { tcpConn, err := ln.AcceptTCP() if err != nil { - log.Println(err) + Log.Errorln(err) continue } router.acceptTCP(tcpConn) @@ -222,10 +215,9 @@ func (router *Router) acceptTCP(tcpConn *net.TCPConn) { // on router.Port and we wait for them to send us something on UDP to // start. remoteAddrStr := tcpConn.RemoteAddr().String() - log.Printf("->[%s] connection accepted\n", remoteAddrStr) + Log.Printf("->[%s] connection accepted\n", remoteAddrStr) connRemote := NewRemoteConnection(router.Ourself.Peer, nil, remoteAddrStr, false, false) - connLocal := NewLocalConnection(connRemote, tcpConn, nil, router) - connLocal.Start(true) + StartLocalConnection(connRemote, tcpConn, nil, router, true) } func (router *Router) listenUDP(localPort int, po PacketSink) *net.UDPConn { @@ -253,10 +245,10 @@ func (router *Router) udpReader(conn *net.UDPConn, po PacketSink) { if err == io.EOF { return } else if err != nil { - log.Println("ignoring UDP read error", err) + Log.Warnln("ignoring UDP read error", err) continue } else if n < NameSize { - log.Println("ignoring too short UDP packet from", sender) + Log.Warnln("ignoring too short UDP packet from", sender) continue } name := PeerNameFromBin(buf[:NameSize]) @@ -318,20 +310,13 @@ func (router *Router) handleUDPPacketFunc(relayConn *LocalConnection, dec *Ether return } - df := decodedLen == 2 && (dec.ip.Flags&layers.IPv4DontFragment != 0) - if dstPeer != router.Ourself.Peer { // it's not for us, we're just relaying it - if df { - router.LogFrame("Relaying DF", frame, &dec.eth) - } else { - router.LogFrame("Relaying", frame, &dec.eth) - } - - err := router.Ourself.Relay(srcPeer, dstPeer, df, frame, dec) + router.LogFrame("Relaying", frame, dec) + err := router.Ourself.Relay(srcPeer, dstPeer, frame, dec) if ftbe, ok := err.(FrameTooBigError); ok { err = dec.sendICMPFragNeeded(ftbe.EPMTU, func(icmpFrame []byte) error { - return router.Ourself.Forward(srcPeer, false, icmpFrame, nil) + return router.Ourself.Forward(srcPeer, icmpFrame, nil) }) } @@ -339,21 +324,21 @@ func (router *Router) handleUDPPacketFunc(relayConn *LocalConnection, dec *Ether return } - srcMac := dec.eth.SrcMAC - dstMac := dec.eth.DstMAC + srcMac := dec.Eth.SrcMAC + dstMac := dec.Eth.DstMAC if router.Macs.Enter(srcMac, srcPeer) { - log.Println("Discovered remote MAC", srcMac, "at", srcPeer) + Log.Println("Discovered remote MAC", srcMac, "at", srcPeer) } if po != nil { - router.LogFrame("Injecting", frame, &dec.eth) + router.LogFrame("Injecting", frame, dec) checkWarn(po.WritePacket(frame)) } dstPeer, found = router.Macs.Lookup(dstMac) if !found || dstPeer != router.Ourself.Peer { - router.LogFrame("Relaying broadcast", frame, &dec.eth) - router.Ourself.RelayBroadcast(srcPeer, df, frame, dec) + router.LogFrame("Relaying broadcast", frame, dec) + router.Ourself.RelayBroadcast(srcPeer, frame, dec) } } } @@ -429,7 +414,7 @@ func (router *Router) applyTopologyUpdate(update []byte) (PeerNameSet, PeerNameS // itself included in the update, and we didn't know about // already. We ignore this; eventually we should receive an // update containing a complete topology. - log.Println("Topology gossip:", err) + Log.Println("Topology gossip:", err) return nil, nil, nil } if err != nil { diff --git a/router/routes.go b/router/routes.go index f244f28f..1f73833d 100644 --- a/router/routes.go +++ b/router/routes.go @@ -22,26 +22,23 @@ type Routes struct { } func NewRoutes(ourself *LocalPeer, peers *Peers) *Routes { + recalculate := make(chan *struct{}, 1) + wait := make(chan chan struct{}) routes := &Routes{ ourself: ourself, peers: peers, unicast: make(map[PeerName]PeerName), unicastAll: make(map[PeerName]PeerName), broadcast: make(map[PeerName][]PeerName), - broadcastAll: make(map[PeerName][]PeerName)} + broadcastAll: make(map[PeerName][]PeerName), + recalculate: recalculate, + wait: wait} routes.unicast[ourself.Name] = UnknownPeerName routes.unicastAll[ourself.Name] = UnknownPeerName routes.broadcast[ourself.Name] = []PeerName{} routes.broadcastAll[ourself.Name] = []PeerName{} - return routes -} - -func (routes *Routes) Start() { - recalculate := make(chan *struct{}, 1) - wait := make(chan chan struct{}) - routes.recalculate = recalculate - routes.wait = wait go routes.run(recalculate, wait) + return routes } func (routes *Routes) PeerNames() PeerNameSet { diff --git a/router/udp_sender.go b/router/udp_sender.go index 4c264762..bbc89e14 100644 --- a/router/udp_sender.go +++ b/router/udp_sender.go @@ -1,12 +1,12 @@ package router import ( - "log" "net" "syscall" - "code.google.com/p/gopacket" - "code.google.com/p/gopacket/layers" + "github.com/google/gopacket" + "github.com/google/gopacket/layers" + . "github.com/weaveworks/weave/common" ) type UDPSender interface { @@ -87,7 +87,7 @@ func (sender *RawUDPSender) Send(msg []byte) error { } defer f.Close() fd := int(f.Fd()) - log.Println("EMSGSIZE on send, expecting PMTU update (IP packet was", + Log.Println("EMSGSIZE on send, expecting PMTU update (IP packet was", len(packet), "bytes, payload was", len(msg), "bytes)") pmtu, err := syscall.GetsockoptInt(fd, syscall.IPPROTO_IP, syscall.IP_MTU) if err != nil { diff --git a/router/utils.go b/router/utils.go index a57d9e8b..8b56e810 100644 --- a/router/utils.go +++ b/router/utils.go @@ -5,21 +5,22 @@ import ( "crypto/rand" "encoding/gob" "fmt" - "log" "net" + + . "github.com/weaveworks/weave/common" ) var void = struct{}{} func checkFatal(e error) { if e != nil { - log.Fatal(e) + Log.Fatal(e) } } func checkWarn(e error) { if e != nil { - log.Println(e) + Log.Warnln(e) } } diff --git a/site/_includes/footer.html b/site/_includes/footer.html index e569c16e..1d114958 100644 --- a/site/_includes/footer.html +++ b/site/_includes/footer.html @@ -2,38 +2,49 @@