Merge lp:~chipaca/ubuntu-push/fix-1390663-for-rtm into lp:ubuntu-push/krillin-rtm

[John Lenton]

Chery pick r140 from trunk to fix lp:1390663 for RTM.

[Bret Barker (noise)]

+1

review: Approve

=== modified file 'bus/connectivity/connectivity.go'
--- bus/connectivity/connectivity.go	2014-07-04 19:12:38 +0000
+++ bus/connectivity/connectivity.go	2015-01-22 17:41:21 +0000
@@ -82,7 +82,7 @@
 		// Get the current state.
 		initial = nm.GetState()
 		if initial == networkmanager.Unknown {
-			cs.log.Debugf("Failed to get state.")
+			cs.log.Debugf("failed to get state.")
 			goto Continue
 		}
 		cs.log.Debugf("got initial state of %s", initial)
@@ -120,40 +120,51 @@
 		case <-cs.networkConCh:
 			cs.webgetCh = nil
 			cs.timer.Reset(stabilizingTimeout)
-			log.Debugf("PrimaryConnection changed. Assuming disconnect.")
 			if cs.lastSent == true {
+				log.Debugf("connectivity: PrimaryConnection changed. lastSent: %v, sending 'disconnected'.", cs.lastSent)
 				cs.lastSent = false
 				break Loop
+			} else {
+				log.Debugf("connectivity: PrimaryConnection changed. lastSent: %v, Ignoring.", cs.lastSent)
 			}
 
 		case v, ok := <-cs.networkStateCh:
+			// Handle only disconnecting here, connecting handled under the timer below
 			if !ok {
 				// tear it all down and start over
 				return false, errors.New("got not-OK from StateChanged watch")
 			}
 			cs.webgetCh = nil
+			lastState := cs.currentState
 			cs.currentState = v
-			cs.timer.Reset(stabilizingTimeout)
-			log.Debugf("State changed to %s. Assuming disconnect.", v)
-			if cs.lastSent == true {
-				log.Infof("Sending 'disconnected'.")
-				cs.lastSent = false
-				break Loop
+			// ignore Connecting (followed immediately by "Connected Global") and repeats
+			if v != networkmanager.Connecting && lastState != v {
+				cs.timer.Reset(stabilizingTimeout)
+				log.Debugf("state changed to %s. Assuming disconnect.", v)
+				if cs.lastSent == true {
+					log.Debugf("connectivity: %s -> %s. lastSent: %v, sending 'disconnected'", lastState, v, cs.lastSent)
+					cs.lastSent = false
+					break Loop
+				} else {
+					log.Debugf("connectivity: %s -> %s. lastSent: %v, Ignoring.", lastState, v, cs.lastSent)
+				}
+			} else {
+				log.Debugf("connectivity: %s -> %s. lastSent: %v, Ignoring.", lastState, v, cs.lastSent)
 			}
 
 		case <-cs.timer.C:
 			if cs.currentState == networkmanager.ConnectedGlobal {
-				log.Debugf("May be connected; checking...")
+				log.Debugf("connectivity: timer signal, state: ConnectedGlobal, checking...")
 				cs.webgetCh = make(chan bool)
 				go cs.webget(cs.webgetCh)
 			}
 
 		case connected := <-cs.webgetCh:
 			cs.timer.Reset(recheckTimeout)
-			log.Debugf("Connection check says: %t", connected)
+			log.Debugf("connectivity: connection check says: %t", connected)
 			cs.webgetCh = nil
 			if connected && cs.lastSent == false {
-				log.Infof("Sending 'connected'.")
+				log.Debugf("connectivity: connection check ok, lastSent: %v, sending 'connected'.", cs.lastSent)
 				cs.lastSent = true
 				break Loop
 			}
@@ -178,7 +189,7 @@
 	}
 
 Start:
-	log.Infof("Sending initial 'disconnected'.")
+	log.Debugf("sending initial 'disconnected'.")
 	out <- false
 	cs.lastSent = false
 	cs.currentState = cs.start()

=== modified file 'bus/connectivity/connectivity_test.go'
--- bus/connectivity/connectivity_test.go	2014-07-04 23:00:42 +0000
+++ bus/connectivity/connectivity_test.go	2015-01-22 17:41:21 +0000
@@ -217,20 +217,22 @@
 	f, e := cs.connectedStateStep()
 	c.Check(e, IsNil)
 	c.Check(f, Equals, true)
-	ch <- networkmanager.ConnectedGlobal // a ConnectedGlobal when connected signals trouble
-	f, e = cs.connectedStateStep()
-	c.Check(e, IsNil)
-	c.Check(f, Equals, false) // so we assume a disconnect happened
-	f, e = cs.connectedStateStep()
-	c.Check(e, IsNil)
-	c.Check(f, Equals, true) // and if the web check works, go back to connected
+	ch <- networkmanager.Disconnected
+	ch <- networkmanager.ConnectedGlobal
+	f, e = cs.connectedStateStep()
+	c.Check(e, IsNil)
+	c.Check(f, Equals, false)
+	f, e = cs.connectedStateStep()
+	c.Check(e, IsNil)
+	c.Check(f, Equals, true)
 
 	// same scenario, but with failing web check
 	webget_p = condition.Fail2Work(1)
+	ch <- networkmanager.Disconnected
 	ch <- networkmanager.ConnectedGlobal
 	f, e = cs.connectedStateStep()
 	c.Check(e, IsNil)
-	c.Check(f, Equals, false) // first false is from assuming a Connected signals trouble
+	c.Check(f, Equals, false) // first false is from the Disconnected
 
 	// the next call to Step will time out
 	_ch := make(chan bool, 1)
@@ -284,7 +286,6 @@
 
 	endp := testingbus.NewTestingEndpoint(condition.Work(true), condition.Work(true),
 		uint32(networkmanager.ConnectedGlobal),
-		uint32(networkmanager.ConnectedGlobal),
 		uint32(networkmanager.Disconnected),
 	)
 
@@ -303,8 +304,6 @@
 	}{
 		{false, "first state is always false", 0},
 		{true, "then it should be true as per ConnectedGlobal above", 0},
-		{false, "then, false (upon receiving the next ConnectedGlobal)", 2},
-		{true, "then it should be true (webcheck passed)", 0},
 		{false, "then it should be false (Disconnected)", 2},
 		{false, "then it should be false again because it's restarted", 2},
 	}

=== modified file 'bus/connectivity/webchecker.go'
--- bus/connectivity/webchecker.go	2014-03-20 12:24:33 +0000
+++ bus/connectivity/webchecker.go	2015-01-22 17:41:21 +0000
@@ -64,7 +64,7 @@
 func (wb *webchecker) Webcheck(ch chan<- bool) {
 	response, err := wb.cli.Get(wb.url)
 	if err != nil {
-		wb.log.Errorf("While GETting %s: %v", wb.url, err)
+		wb.log.Errorf("while GETting %s: %v", wb.url, err)
 		ch <- false
 		return
 	}
@@ -72,17 +72,17 @@
 	hash := md5.New()
 	_, err = io.CopyN(hash, response.Body, 1024)
 	if err != io.EOF {
-		wb.log.Errorf("Reading %s, expecting EOF, got: %v",
+		wb.log.Errorf("reading %s, expecting EOF, got: %v",
 			wb.url, err)
 		ch <- false
 		return
 	}
 	sum := fmt.Sprintf("%x", hash.Sum(nil))
 	if sum == wb.target {
-		wb.log.Infof("Connectivity check passed.")
+		wb.log.Infof("connectivity check passed.")
 		ch <- true
 	} else {
-		wb.log.Infof("Connectivity check failed: content mismatch.")
+		wb.log.Infof("connectivity check failed: content mismatch.")
 		ch <- false
 	}
 }

=== modified file 'bus/endpoint.go'
--- bus/endpoint.go	2014-09-08 15:48:00 +0000
+++ bus/endpoint.go	2015-01-22 17:41:21 +0000
@@ -84,7 +84,7 @@
 	name := endp.addr.Name
 	hasOwner, err := d.NameHasOwner(name)
 	if err != nil {
-		endp.log.Debugf("Unable to determine ownership of %#v: %v", name, err)
+		endp.log.Debugf("unable to determine ownership of %#v: %v", name, err)
 		bus.Close()
 		return err
 	}
@@ -110,7 +110,7 @@
 			return errors.New(msg)
 		}
 	}
-	endp.log.Infof("%#v dialed in.", name)
+	endp.log.Debugf("%#v dialed in.", name)
 	endp.bus = bus
 	endp.proxy = bus.Object(name, dbus.ObjectPath(endp.addr.Path))
 	return nil
@@ -126,7 +126,7 @@
 func (endp *endpoint) WatchSignal(member string, f func(...interface{}), d func()) error {
 	watch, err := endp.proxy.WatchSignal(endp.addr.Interface, member)
 	if err != nil {
-		endp.log.Debugf("Failed to set up the watch: %s", err)
+		endp.log.Debugf("failed to set up the watch: %s", err)
 		return err
 	}
 
@@ -167,15 +167,15 @@
 	variantvs := endp.unpackOneMsg(msg, property)
 	switch len(variantvs) {
 	default:
-		return nil, fmt.Errorf("Too many values in Properties.Get response: %d", len(variantvs))
+		return nil, fmt.Errorf("too many values in Properties.Get response: %d", len(variantvs))
 	case 0:
-		return nil, fmt.Errorf("Not enough values in Properties.Get response: %d", len(variantvs))
+		return nil, fmt.Errorf("not enough values in Properties.Get response: %d", len(variantvs))
 	case 1:
 		// carry on
 	}
 	variant, ok := variantvs[0].(*dbus.Variant)
 	if !ok {
-		return nil, fmt.Errorf("Response from Properties.Get wasn't a *dbus.Variant")
+		return nil, fmt.Errorf("response from Properties.Get wasn't a *dbus.Variant")
 	}
 	return variant.Value, nil
 }
@@ -324,6 +324,6 @@
 		}
 		f(endp.unpackOneMsg(msg, member)...)
 	}
-	endp.log.Errorf("Got not-OK from %s watch", member)
+	endp.log.Errorf("got not-OK from %s watch", member)
 	d()
 }

=== modified file 'bus/networkmanager/networkmanager.go'
--- bus/networkmanager/networkmanager.go	2014-04-04 12:01:42 +0000
+++ bus/networkmanager/networkmanager.go	2015-01-22 17:41:21 +0000
@@ -71,14 +71,14 @@
 func (nm *networkManager) GetState() State {
 	s, err := nm.bus.GetProperty("state")
 	if err != nil {
-		nm.log.Errorf("Failed gettting current state: %s", err)
-		nm.log.Debugf("Defaulting state to Unknown")
+		nm.log.Errorf("failed gettting current state: %s", err)
+		nm.log.Debugf("defaulting state to Unknown")
 		return Unknown
 	}
 
 	v, ok := s.(uint32)
 	if !ok {
-		nm.log.Errorf("Got weird state: %#v", s)
+		nm.log.Errorf("got weird state: %#v", s)
 		return Unknown
 	}
 
@@ -110,8 +110,8 @@
 func (nm *networkManager) GetPrimaryConnection() string {
 	s, err := nm.bus.GetProperty("PrimaryConnection")
 	if err != nil {
-		nm.log.Errorf("Failed gettting current primary connection: %s", err)
-		nm.log.Debugf("Defaulting primary connection to empty")
+		nm.log.Errorf("failed gettting current primary connection: %s", err)
+		nm.log.Debugf("defaulting primary connection to empty")
 		return ""
 	}
 
@@ -146,7 +146,7 @@
 			ch <- string(con)
 		}, func() { close(ch) })
 	if err != nil {
-		nm.log.Debugf("Failed to set up the watch: %s", err)
+		nm.log.Debugf("failed to set up the watch: %s", err)
 		return nil, err
 	}
 

=== modified file 'bus/notifications/raw.go'
--- bus/notifications/raw.go	2014-08-15 10:33:04 +0000
+++ bus/notifications/raw.go	2015-01-22 17:41:21 +0000
@@ -119,7 +119,7 @@
 			ch <- action
 		}, func() { close(ch) })
 	if err != nil {
-		raw.log.Debugf("Failed to set up the watch: %s", err)
+		raw.log.Debugf("failed to set up the watch: %s", err)
 		return nil, err
 	}
 	return ch, nil

=== modified file 'bus/systemimage/systemimage.go'
--- bus/systemimage/systemimage.go	2014-04-02 08:46:48 +0000
+++ bus/systemimage/systemimage.go	2015-01-22 17:41:21 +0000
@@ -57,7 +57,7 @@
 var _ SystemImage = &systemImage{} // ensures it conforms
 
 func (si *systemImage) Info() (*InfoResult, error) {
-	si.log.Debugf("Invoking Info")
+	si.log.Debugf("invoking Info")
 	res := &InfoResult{}
 	err := si.endp.Call("Info", bus.Args(), &res.BuildNumber, &res.Device, &res.Channel, &res.LastUpdate, &res.VersionDetail)
 	if err != nil {

=== modified file 'client/client.go'
--- client/client.go	2014-10-23 19:30:24 +0000
+++ client/client.go	2015-01-22 17:41:21 +0000
@@ -376,15 +376,15 @@
 
 // handleConnState deals with connectivity events
 func (client *PushClient) handleConnState(hasConnectivity bool) {
+	client.log.Debugf("handleConnState: %v", hasConnectivity)
 	if client.hasConnectivity == hasConnectivity {
 		// nothing to do!
 		return
 	}
 	client.hasConnectivity = hasConnectivity
+	client.session.Close()
 	if hasConnectivity {
 		client.session.AutoRedial(client.sessionConnectedCh)
-	} else {
-		client.session.Close()
 	}
 }
 
@@ -490,7 +490,7 @@
 		case err := <-client.session.ErrCh:
 			errhandler(err)
 		case count := <-client.sessionConnectedCh:
-			client.log.Debugf("Session connected after %d attempts", count)
+			client.log.Debugf("session connected after %d attempts", count)
 		case app := <-client.unregisterCh:
 			unregisterhandler(app)
 		}

=== modified file 'client/client_test.go'
--- client/client_test.go	2014-09-05 10:47:29 +0000
+++ client/client_test.go	2015-01-22 17:41:21 +0000
@@ -1135,7 +1135,7 @@
 	// sessionConnectedCh to nothing in particular, but it'll help sync this test
 	cli.sessionConnectedCh <- 42
 	tick()
-	c.Check(cs.log.Captured(), Matches, "(?ms).*Session connected after 42 attempts$")
+	c.Check(cs.log.Captured(), Matches, "(?msi).*Session connected after 42 attempts$")
 
 	// loop() should have connected:
 	//  * connCh to the connectivity checker

=== modified file 'client/service/postal.go'
--- client/service/postal.go	2014-10-23 14:39:53 +0000
+++ client/service/postal.go	2015-01-22 17:41:21 +0000
@@ -244,7 +244,6 @@
 	for _, endp := range endps {
 		go func(name string, endp bus.Endpoint) {
 			util.NewAutoRedialer(endp).Redial()
-			svc.Log.Debugf("%s dialed in", name)
 			wg.Done()
 		}(endp.name, endp.endp)
 	}

=== modified file 'client/service/service.go'
--- client/service/service.go	2014-10-23 14:39:53 +0000
+++ client/service/service.go	2015-01-22 17:41:21 +0000
@@ -147,14 +147,14 @@
 	// errors below here Can't Happen (tm).
 	body, err := ioutil.ReadAll(resp.Body)
 	if err != nil {
-		svc.Log.Errorf("Reading response body: %v", err)
+		svc.Log.Errorf("during ReadAll() of response body: %v", err)
 		return nil, err
 	}
 
 	var reply registrationReply
 	err = json.Unmarshal(body, &reply)
 	if err != nil {
-		svc.Log.Errorf("Unmarshalling response body: %v", err)
+		svc.Log.Errorf("during Unmarshal of response body: %v", err)
 		return nil, fmt.Errorf("unable to unmarshal register response: %v", err)
 	}
 
@@ -179,7 +179,7 @@
 	}
 
 	if !reply.Ok || reply.Token == "" {
-		svc.Log.Errorf("Unexpected response: %#v", reply)
+		svc.Log.Errorf("unexpected response: %#v", reply)
 		return nil, ErrBadToken
 	}
 

=== modified file 'client/session/session.go'
--- client/session/session.go	2015-01-16 16:40:55 +0000
+++ client/session/session.go	2015-01-22 17:41:21 +0000
@@ -74,8 +74,22 @@
 	Connected
 	Started
 	Running
+	Unknown
 )
 
+func (s ClientSessionState) String() string {
+	if s >= Unknown {
+		return fmt.Sprintf("??? (%d)", s)
+	}
+	return [Unknown]string{
+		"Error",
+		"Disconnected",
+		"Connected",
+		"Started",
+		"Running",
+	}[s]
+}
+
 type hostGetter interface {
 	Get() (*gethosts.Host, error)
 }
@@ -131,6 +145,7 @@
 	proto        protocol.Protocol
 	pingInterval time.Duration
 	retrier      util.AutoRedialer
+	retrierLock  sync.Mutex
 	cookie       string
 	// status
 	stateP          *uint32
@@ -220,6 +235,7 @@
 }
 
 func (sess *ClientSession) setState(state ClientSessionState) {
+	sess.Log.Debugf("session.setState: %s -> %s", ClientSessionState(atomic.LoadUint32(sess.stateP)), state)
 	atomic.StoreUint32(sess.stateP, uint32(state))
 }
 
@@ -348,6 +364,8 @@
 }
 
 func (sess *ClientSession) stopRedial() {
+	sess.retrierLock.Lock()
+	defer sess.retrierLock.Unlock()
 	if sess.retrier != nil {
 		sess.retrier.Stop()
 		sess.retrier = nil
@@ -360,15 +378,31 @@
 		sess.setShouldDelay()
 	}
 	time.Sleep(sess.redialDelay(sess))
+	sess.retrierLock.Lock()
+	defer sess.retrierLock.Unlock()
+	if sess.retrier != nil {
+		panic("session AutoRedial: unexpected non-nil retrier.")
+	}
 	sess.retrier = util.NewAutoRedialer(sess)
 	sess.lastAutoRedial = time.Now()
-	go func() { doneCh <- sess.retrier.Redial() }()
+	go func() {
+		sess.retrierLock.Lock()
+		retrier := sess.retrier
+		sess.retrierLock.Unlock()
+		if retrier == nil {
+			sess.Log.Debugf("session autoredialer skipping retry: retrier has been set to nil.")
+			return
+		}
+		sess.Log.Debugf("session autoredialier launching Redial goroutine")
+		doneCh <- retrier.Redial()
+	}()
 }
 
 func (sess *ClientSession) Close() {
 	sess.stopRedial()
 	sess.doClose()
 }
+
 func (sess *ClientSession) doClose() {
 	sess.connLock.Lock()
 	defer sess.connLock.Unlock()
@@ -508,6 +542,7 @@
 		sess.proto.SetDeadline(time.Now().Add(deadAfter))
 		err = sess.proto.ReadMessage(&recv)
 		if err != nil {
+			sess.Log.Debugf("session aborting with error on read.")
 			sess.setState(Error)
 			return err
 		}
@@ -529,6 +564,7 @@
 			sess.Log.Errorf("server sent warning: %s", recv.Reason)
 		}
 		if err != nil {
+			sess.Log.Debugf("session aborting with error from handler.")
 			return err
 		}
 	}
@@ -591,7 +627,7 @@
 	}
 	sess.proto = proto
 	sess.pingInterval = pingInterval
-	sess.Log.Debugf("Connected %v.", conn.RemoteAddr())
+	sess.Log.Debugf("connected %v.", conn.RemoteAddr())
 	sess.started() // deals with choosing which host to retry with as well
 	return nil
 }

=== modified file 'dependencies.tsv'
--- dependencies.tsv	2014-08-20 12:42:51 +0000
+++ dependencies.tsv	2015-01-22 17:41:21 +0000
@@ -1,5 +1,5 @@
 code.google.com/p/go-uuid	hg	7dda39b2e7d5e265014674c5af696ba4186679e9	11
 code.google.com/p/gosqlite	hg	74691fb6f83716190870cde1b658538dd4b18eb0	15
-launchpad.net/go-dbus/v1	bzr	[e-mail]-20140801110939-lzfql7fk76dt6ckd	128
+launchpad.net/go-dbus/v1	bzr	[e-mail]-20141023032446-s5icvsucwlv5o38a	129
 launchpad.net/go-xdg/v0	bzr	[e-mail]-20140208094800-gubd5md7cro3mtxa	10
 launchpad.net/gocheck	bzr	[e-mail]-20140225173054-xu9zlkf9kxhvow02	87

=== modified file 'identifier/identifier.go'
--- identifier/identifier.go	2014-08-04 20:40:50 +0000
+++ identifier/identifier.go	2015-01-22 17:41:21 +0000
@@ -48,7 +48,7 @@
 func New() (Id, error) {
 	value, err := readMachineId()
 	if err != nil {
-		return &Identifier{value: ""}, fmt.Errorf("Failed to read the machine id: %s", err)
+		return &Identifier{value: ""}, fmt.Errorf("failed to read the machine id: %s", err)
 	}
 	return &Identifier{value: value}, nil
 }

=== modified file 'identifier/identifier_test.go'
--- identifier/identifier_test.go	2014-08-12 00:32:32 +0000
+++ identifier/identifier_test.go	2015-01-22 17:41:21 +0000
@@ -48,7 +48,7 @@
 	machineIdPath = "/var/lib/dbus/no-such-file"
 	id, err := New()
 	c.Check(err, NotNil)
-	c.Check(err.Error(), Equals, "Failed to read the machine id: open /var/lib/dbus/no-such-file: no such file or directory")
+	c.Check(err.Error(), Equals, "failed to read the machine id: open /var/lib/dbus/no-such-file: no such file or directory")
 	c.Check(id.String(), HasLen, 0)
 }
 

=== modified file 'launch_helper/helper_finder/helper_finder.go'
--- launch_helper/helper_finder/helper_finder.go	2014-07-29 15:36:00 +0000
+++ launch_helper/helper_finder/helper_finder.go	2015-01-22 17:41:21 +0000
@@ -72,7 +72,7 @@
 	fInfo, err := os.Stat(helpersDataPath)
 	if err != nil {
 		// cache file is missing, go via the slow route
-		log.Infof("Cache file not found, falling back to .json file lookup")
+		log.Infof("cache file not found, falling back to .json file lookup")
 		return helperFromHookFile(app)
 	}
 	// get the lock as the map can be changed while we read

=== modified file 'launch_helper/helper_finder/helper_finder_test.go'
--- launch_helper/helper_finder/helper_finder_test.go	2014-07-29 15:36:00 +0000
+++ launch_helper/helper_finder/helper_finder_test.go	2015-01-22 17:41:21 +0000
@@ -139,7 +139,7 @@
 	hid, hex := Helper(app, s.log)
 	c.Check(hid, Equals, "com.example.test_test-helper_1")
 	c.Check(hex, Equals, filepath.Join(s.symlinkPath, "tsthlpr"))
-	c.Check(s.log.Captured(), Matches, ".*Cache file not found, falling back to .json file lookup\n")
+	c.Check(s.log.Captured(), Matches, ".*(?i)Cache file not found, falling back to .json file lookup\n")
 }
 
 func (s *helperSuite) TestHelperFromHookBasic(c *C) {

=== modified file 'launch_helper/kindpool.go'
--- launch_helper/kindpool.go	2015-01-16 16:40:55 +0000
+++ launch_helper/kindpool.go	2015-01-22 17:41:21 +0000
@@ -296,7 +296,7 @@
 	if err != nil {
 		pool.log.Errorf("unable to read output from %v helper: %v", args.AppId, err)
 	} else {
-		pool.log.Infof("%v helper output: %#v", args.AppId, payload)
+		pool.log.Infof("%v helper output: %s", args.AppId, payload)
 		res := &HelperResult{Input: args.Input}
 		err = json.Unmarshal(payload, &res.HelperOutput)
 		if err != nil {

=== modified file 'launch_helper/legacy/legacy.go'
--- launch_helper/legacy/legacy.go	2015-01-16 16:40:55 +0000
+++ launch_helper/legacy/legacy.go	2015-01-22 17:41:21 +0000
@@ -78,7 +78,7 @@
 		p_err := cmd.Wait()
 		if p_err != nil {
 			// Helper failed or got killed, log output/errors
-			lhl.log.Errorf("Legacy helper failed: appId: %v, helper: %v, pid: %v, error: %v, stdout: %#v, stderr: %#v.",
+			lhl.log.Errorf("legacy helper failed: appId: %v, helper: %v, pid: %v, error: %v, stdout: %#v, stderr: %#v.",
 				appId, progname, id, p_err, stdout.String(), stderr.String())
 		}
 		lhl.done(id)

=== modified file 'launch_helper/legacy/legacy_test.go'
--- launch_helper/legacy/legacy_test.go	2014-08-21 18:03:49 +0000
+++ launch_helper/legacy/legacy_test.go	2015-01-22 17:41:21 +0000
@@ -104,7 +104,7 @@
 	c.Assert(err, IsNil)
 
 	takeNext(ch, c)
-	c.Check(ls.log.Captured(), Matches, "(?s).*Legacy helper failed.*")
+	c.Check(ls.log.Captured(), Matches, "(?si).*Legacy helper failed.*")
 }
 
 func (ls *legacySuite) TestHelperFailsLog(c *C) {

=== modified file 'messaging/messaging.go'
--- messaging/messaging.go	2014-07-27 02:54:40 +0000
+++ messaging/messaging.go	2015-01-22 17:41:21 +0000
@@ -181,7 +181,7 @@
 			Action:   action,
 		})
 		if err != nil {
-			mmu.Log.Errorf("Failed to build action: %s", action)
+			mmu.Log.Errorf("failed to build action: %s", action)
 			return false
 		}
 		actions[2*i] = string(act)

=== modified file 'poller/poller.go'
--- poller/poller.go	2014-08-29 13:50:16 +0000
+++ poller/poller.go	2015-01-22 17:41:21 +0000
@@ -167,7 +167,7 @@
 		// the channel will produce a true for every
 		// wakeup, not only the one we asked for
 		now := time.Now()
-		p.log.Debugf("got woken up; time is %s", now)
+		p.log.Debugf("got woken up; time is %s (𝛥: %s)", now, now.Sub(t))
 		if !now.Before(t) {
 			break
 		}

=== modified file 'server/acceptance/acceptanceclient.go'
--- server/acceptance/acceptanceclient.go	2014-08-27 21:19:51 +0000
+++ server/acceptance/acceptanceclient.go	2015-01-22 17:41:21 +0000
@@ -176,6 +176,8 @@
 			events <- fmt.Sprintf("%sbroadcast chan:%v app:%v topLevel:%d payloads:%s", sess.Prefix, recv.ChanId, recv.AppId, recv.TopLevel, pack)
 		case "warn", "connwarn":
 			events <- fmt.Sprintf("%sconnwarn %s", sess.Prefix, recv.Reason)
+		case "connbroken":
+			events <- fmt.Sprintf("%sconnbroken %s", sess.Prefix, recv.Reason)
 		case "setparams":
 			sess.SetCookie(recv.SetCookie)
 			if sess.ReportSetParams {

=== modified file 'server/acceptance/suites/suite.go'
--- server/acceptance/suites/suite.go	2014-09-01 14:48:03 +0000
+++ server/acceptance/suites/suite.go	2015-01-22 17:41:21 +0000
@@ -22,6 +22,7 @@
 	"fmt"
 	"net"
 	"os"
+	"regexp"
 	"runtime"
 	"time"
 
@@ -48,6 +49,13 @@
 
 // Start a client with auth.
 func (h *ServerHandle) StartClientAuth(c *C, devId string, levels map[string]int64, auth string, cookie string) (events <-chan string, errorCh <-chan error, stop func()) {
+	cliEvents, errCh, stop := h.StartClientAuthFlex(c, devId, levels, auth, cookie, regexp.QuoteMeta(devId))
+	c.Assert(NextEvent(cliEvents, errCh), Matches, "connected .*")
+	return cliEvents, errCh, stop
+}
+
+// Start a client with auth, take a devId regexp, don't check any client event.
+func (h *ServerHandle) StartClientAuthFlex(c *C, devId string, levels map[string]int64, auth, cookie, devIdRegexp string) (events <-chan string, errorCh <-chan error, stop func()) {
 	errCh := make(chan error, 1)
 	cliEvents := make(chan string, 10)
 	sess := testClientSession(h.ServerAddr, devId, "m1", "img1", false)
@@ -76,9 +84,8 @@
 	go func() {
 		errCh <- sess.Run(cliEvents)
 	}()
-	c.Assert(NextEvent(cliEvents, errCh), Matches, "connected .*")
 	c.Assert(NextEvent(h.ServerEvents, nil), Matches, ".*session.* connected .*")
-	c.Assert(NextEvent(h.ServerEvents, nil), Matches, ".*session.* registered "+devId)
+	c.Assert(NextEvent(h.ServerEvents, nil), Matches, ".*session.* registered "+devIdRegexp)
 	return cliEvents, errCh, func() { clientShutdown <- true }
 }
 

=== modified file 'testing/helpers.go'
--- testing/helpers.go	2014-07-11 19:42:57 +0000
+++ testing/helpers.go	2015-01-22 17:41:21 +0000
@@ -118,7 +118,7 @@
 
 		idx := strings.LastIndex(dir, sep)
 		if idx == -1 {
-			panic(fmt.Errorf("Unable to find %s in %#v", sep, dir))
+			panic(fmt.Errorf("unable to find %s in %#v", sep, dir))
 		}
 		idx += len(sep)
 

=== modified file 'ubuntu-push-client.go'
--- ubuntu-push-client.go	2014-05-08 22:29:26 +0000
+++ ubuntu-push-client.go	2015-01-22 17:41:21 +0000
@@ -18,13 +18,31 @@
 
 import (
 	"log"
+	"os"
+	"os/signal"
+	"runtime"
+	"syscall"
 
 	"launchpad.net/go-xdg/v0"
 
 	"launchpad.net/ubuntu-push/client"
 )
 
+func installSigQuitHandler() {
+	go func() {
+		sigs := make(chan os.Signal, 1)
+		signal.Notify(sigs, syscall.SIGQUIT)
+		buf := make([]byte, 1<<20)
+		for {
+			<-sigs
+			runtime.Stack(buf, true)
+			log.Printf("=== received SIGQUIT ===\n*** goroutine dump...\n%s\n*** end\n", buf)
+		}
+	}()
+}
+
 func main() {
+	installSigQuitHandler()
 	cfgFname, err := xdg.Config.Find("ubuntu-push-client/config.json")
 	if err != nil {
 		log.Fatalf("unable to find a configuration file: %v", err)

=== modified file 'urldispatcher/curldispatcher/curldispatcher.go'
--- urldispatcher/curldispatcher/curldispatcher.go	2014-09-01 13:27:17 +0000
+++ urldispatcher/curldispatcher/curldispatcher.go	2015-01-22 17:41:21 +0000
@@ -79,7 +79,7 @@
 	C.dispatch_url(c_url, (C.gpointer)(&payload))
 	success := <-doneCh
 	if !success {
-		return fmt.Errorf("Failed to DispatchURL: %s for %s", url, appPackage)
+		return fmt.Errorf("failed to DispatchURL: %s for %s", url, appPackage)
 	}
 	return nil
 }

=== modified file 'urldispatcher/urldispatcher.go'
--- urldispatcher/urldispatcher.go	2014-09-01 13:27:17 +0000
+++ urldispatcher/urldispatcher.go	2015-01-22 17:41:21 +0000
@@ -44,7 +44,7 @@
 var cTestURL = curldispatcher.TestURL
 
 func (ud *urlDispatcher) DispatchURL(url string, app *click.AppId) error {
-	ud.log.Debugf("Dispatching %s", url)
+	ud.log.Debugf("dispatching %s", url)
 	err := cDispatchURL(url, app.DispatchPackage())
 	if err != nil {
 		ud.log.Errorf("DispatchURL failed: %s", err)
@@ -62,7 +62,7 @@
 	}
 	for _, appId := range appIds {
 		if appId != app.Versioned() {
-			ud.log.Debugf("Notification skipped because of different appid for actions: %v - %s != %s", urls, appId, app.Versioned())
+			ud.log.Debugf("notification skipped because of different appid for actions: %v - %s != %s", urls, appId, app.Versioned())
 			return false
 		}
 	}

=== modified file 'urldispatcher/urldispatcher_test.go'
--- urldispatcher/urldispatcher_test.go	2014-08-21 17:45:01 +0000
+++ urldispatcher/urldispatcher_test.go	2015-01-22 17:41:21 +0000
@@ -106,7 +106,7 @@
 	appId := clickhelp.MustParseAppId("com.example.test_app_0.99")
 	urls := []string{"potato://test-app"}
 	c.Check(ud.TestURL(appId, urls), Equals, false)
-	c.Check(s.log.Captured(), Matches, `(?sm).*Notification skipped because of different appid for actions: \[potato://test-app\] - com.example.test_test-app_0.1 != com.example.test_app_0.99`)
+	c.Check(s.log.Captured(), Matches, `(?smi).*notification skipped because of different appid for actions: \[potato://test-app\] - com.example.test_test-app_0.1 != com.example.test_app_0.99`)
 }
 
 func (s *UDSuite) TestTestURLOneWrongApp(c *C) {
@@ -117,7 +117,7 @@
 	appId := clickhelp.MustParseAppId("com.example.test_test-app_0")
 	urls := []string{"potato://test-app", "potato_a://foo"}
 	c.Check(ud.TestURL(appId, urls), Equals, false)
-	c.Check(s.log.Captured(), Matches, `(?sm).*Notification skipped because of different appid for actions: \[potato://test-app potato_a://foo\] - com.example.test_test-app1 != com.example.test_test-app.*`)
+	c.Check(s.log.Captured(), Matches, `(?smi).*notification skipped because of different appid for actions: \[potato://test-app potato_a://foo\] - com.example.test_test-app1 != com.example.test_test-app.*`)
 }
 
 func (s *UDSuite) TestTestURLInvalidURL(c *C) {

=== modified file 'util/redialer.go'
--- util/redialer.go	2014-03-20 12:15:47 +0000
+++ util/redialer.go	2015-01-22 17:41:21 +0000
@@ -19,6 +19,7 @@
 
 import (
 	"sync"
+	"sync/atomic"
 	"time"
 )
 
@@ -65,30 +66,42 @@
 	Stop()          // Stop shuts down the given AutoRedialer, if it is still retrying.
 }
 
+type redialerState uint32
+
+const (
+	Unconfigured redialerState = iota
+	Redialing
+	Stopped
+)
+
+func (s *redialerState) String() string {
+	return [3]string{"Unconfigured", "Redialing", "Stopped"}[uint32(*s)]
+}
+
 type autoRedialer struct {
-	stop   chan bool
-	lock   sync.RWMutex
+	stateP *redialerState
 	dial   func() error
 	jitter func(time.Duration) time.Duration
 }
 
+func (ar *autoRedialer) state() redialerState {
+	return redialerState(atomic.LoadUint32((*uint32)(ar.stateP)))
+}
+
+func (ar *autoRedialer) setState(s redialerState) {
+	atomic.StoreUint32((*uint32)(ar.stateP), uint32(s))
+}
+
+func (ar *autoRedialer) setStateIfEqual(oldState, newState redialerState) bool {
+	return atomic.CompareAndSwapUint32((*uint32)(ar.stateP), uint32(oldState), uint32(newState))
+}
+
 func (ar *autoRedialer) Stop() {
 	if ar != nil {
-		ar.lock.RLock()
-		defer ar.lock.RUnlock()
-		if ar.stop != nil {
-			ar.stop <- true
-		}
+		ar.setState(Stopped)
 	}
 }
 
-func (ar *autoRedialer) shutdown() {
-	ar.lock.Lock()
-	defer ar.lock.Unlock()
-	close(ar.stop)
-	ar.stop = nil
-}
-
 // Redial keeps on calling Dial until it stops returning an error.  It does
 // exponential backoff, adding back the output of Jitter at each step.
 func (ar *autoRedialer) Redial() uint32 {
@@ -96,20 +109,19 @@
 		// at least it's better than a segfault...
 		panic("you can't Redial a nil AutoRedialer")
 	}
-	if ar.stop == nil {
-		panic("this AutoRedialer has already been shut down")
+	if !ar.setStateIfEqual(Unconfigured, Redialing) {
+		// XXX log this
+		return 0
 	}
-	defer ar.shutdown()
-
-	ar.lock.RLock()
-	stop := ar.stop
-	ar.lock.RUnlock()
 
 	var timeout time.Duration
 	var dialAttempts uint32 = 0 // unsigned so it can wrap safely ...
 	timeouts := Timeouts()
 	var numTimeouts uint32 = uint32(len(timeouts))
 	for {
+		if ar.state() != Redialing {
+			return dialAttempts
+		}
 		if ar.dial() == nil {
 			return dialAttempts + 1
 		}
@@ -122,18 +134,15 @@
 			timeout += ar.jitter(timeout)
 		}
 		dialAttempts++
-		select {
-		case <-stop:
-			return dialAttempts
-		case <-time.After(timeout):
-		}
+		time.Sleep(timeout)
 	}
 }
 
 // Returns a stoppable AutoRedialer using the provided Dialer. If the Dialer
 // is also a Jitterer, the backoff will be jittered.
 func NewAutoRedialer(dialer Dialer) AutoRedialer {
-	ar := &autoRedialer{stop: make(chan bool), dial: dialer.Dial}
+	state := Unconfigured
+	ar := &autoRedialer{stateP: &state, dial: dialer.Dial}
 	jitterer, ok := dialer.(Jitterer)
 	if ok {
 		ar.jitter = jitterer.Jitter

=== modified file 'util/redialer_test.go'
--- util/redialer_test.go	2014-02-05 13:02:47 +0000
+++ util/redialer_test.go	2015-01-22 17:41:21 +0000
@@ -48,10 +48,10 @@
 func (s *RedialerSuite) TestWorks(c *C) {
 	endp := testibus.NewTestingEndpoint(condition.Fail2Work(3), nil)
 	ar := NewAutoRedialer(endp)
-	c.Check(ar.(*autoRedialer).stop, NotNil)
+	//	c.Check(ar.(*autoRedialer).stop, NotNil)
 	c.Check(ar.Redial(), Equals, uint32(4))
 	// and on success, the stopper goes away
-	c.Check(ar.(*autoRedialer).stop, IsNil)
+	//	c.Check(ar.(*autoRedialer).stop, IsNil)
 }
 
 func (s *RedialerSuite) TestRetryNil(c *C) {
@@ -63,7 +63,7 @@
 	endp := testibus.NewTestingEndpoint(condition.Work(true), nil)
 	ar := NewAutoRedialer(endp)
 	c.Check(ar.Redial(), Equals, uint32(1))
-	c.Check(ar.Redial, PanicMatches, ".*shut.?down.*")
+	c.Check(ar.Redial(), Equals, uint32(0))
 }
 
 type JitteringEndpoint struct {
@@ -103,13 +103,13 @@
 	go func() { countCh <- ar.Redial() }()
 	ar.Stop()
 	select {
-	case n := <-countCh:
-		c.Check(n, Equals, uint32(1))
+	case <-countCh:
+		// pass
 	case <-time.After(20 * time.Millisecond):
 		c.Fatal("timed out waiting for redial")
 	}
-	// on Stop(), the stopper goes away too
-	c.Check(ar.(*autoRedialer).stop, IsNil)
+	// on Stop(), the redialer is Stopped
+	c.Check(ar.(*autoRedialer).state(), Equals, Stopped)
 	// and the next Stop() doesn't panic nor block
 	ar.Stop()
 }