Merge lp:~chipaca/ubuntu-push/release-0.67 into lp:ubuntu-push

[John Lenton]

  * Updated precommit script. [dev]

  * Include code examples in docs (instead of repeating). [docs]

  * Make tests more robust in the face of go 1.3 [client, server]

  * Introduce StartClientAuthFlex for acceptance tests: Start a client
    with auth, take a devId regexp, don't check any client event; support
    connbroken in acceptanceclient. [server]

  * Cleanup and improve logging, and make log messages more
    consistent. [client]

  * Partially work around bug lp:1390663 in a minimally intrusive way
    (real fix will have to wait). [client]

  * Add SIGQUIT handler to spit out stack dumps; more logging
    tweaks. [client, server]

  * Adds a couple of buttons to exercise more APIs, version bump to
    0.44. [sample app]

  * Add APIError to server/acceptance/kit that includes the body for
    debugging. [server]

  * Add DisableKeepAlives and MaxIdleConnsPerHost to the APIClient
    SetupClient method. [server]

  * Clean up goroutines in tests. [client]

  * Add an explicit check and log message for nil error on webcheck's CopyN. [client]

  * Log line nums, enabled when logLevel = debug. [client server]

  * Workaround gc issue with 1.3 and 32 bits. Fixes FTBFS. [client]

Merging from automatic.

  * Updated precommit script. [dev]

  * Include code examples in docs (instead of repeating). [docs]

  * Make tests more robust in the face of go 1.3 [client, server]

  * Introduce StartClientAuthFlex for acceptance tests: Start a client
    with auth, take a devId regexp, don't check any client event; support
    connbroken in acceptanceclient. [server]

  * Cleanup and improve logging, and make log messages more
    consistent. [client]

  * Partially work around bug lp:1390663 in a minimally intrusive way
    (real fix will have to wait). [client]

  * Add SIGQUIT handler to spit out stack dumps; more logging
    tweaks. [client, server]

  * Adds a couple of buttons to exercise more APIs, version bump to
    0.44. [sample app]

  * Add APIError to server/acceptance/kit that includes the body for
    debugging. [server]

  * Add DisableKeepAlives and MaxIdleConnsPerHost to the APIClient
    SetupClient method. [server]

  * Clean up goroutines in tests. [client]

  * Add an explicit check and log message for nil error on webcheck's CopyN. [client]

  * Log line nums, enabled when logLevel = debug. [client server]

  * Workaround gc issue with 1.3 and 32 bits. Fixes FTBFS. [client]

[lp:~chipaca/ubuntu-push/release-0.67]

141. By John Lenton on 2015-02-09

changelog polish.

[John Lenton (chipaca)]

Individual branches have been approved sepparately.

review: Approve

=== modified file 'bus/connectivity/connectivity.go'
--- bus/connectivity/connectivity.go	2014-07-04 19:12:38 +0000
+++ bus/connectivity/connectivity.go	2015-02-09 10:47:29 +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-02-09 10:47:29 +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-02-09 10:47:29 +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,20 @@
 	hash := md5.New()
 	_, err = io.CopyN(hash, response.Body, 1024)
 	if err != io.EOF {
-		wb.log.Errorf("Reading %s, expecting EOF, got: %v",
-			wb.url, err)
+		if err == nil {
+			wb.log.Errorf("reading %s, but response body is larger than 1k.", wb.url)
+		} else {
+			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/connectivity/webchecker_test.go'
--- bus/connectivity/webchecker_test.go	2014-03-20 12:24:33 +0000
+++ bus/connectivity/webchecker_test.go	2015-02-09 10:47:29 +0000
@@ -18,7 +18,6 @@
 
 import (
 	. "launchpad.net/gocheck"
-	"launchpad.net/ubuntu-push/logger"
 	helpers "launchpad.net/ubuntu-push/testing"
 	"launchpad.net/ubuntu-push/util"
 	"net/http"
@@ -28,7 +27,7 @@
 
 type WebcheckerSuite struct {
 	timeouts []time.Duration
-	log      logger.Logger
+	log      *helpers.TestLogger
 }
 
 var _ = Suite(&WebcheckerSuite{})
@@ -104,6 +103,7 @@
 	ch := make(chan bool, 1)
 	ck.Webcheck(ch)
 	c.Check(<-ch, Equals, false)
+	c.Check(s.log.Captured(), Matches, "(?ism).*content mismatch.*")
 }
 
 // Webchecker sends false if the download is too big
@@ -115,6 +115,7 @@
 	ch := make(chan bool, 1)
 	ck.Webcheck(ch)
 	c.Check(<-ch, Equals, false)
+	c.Check(s.log.Captured(), Matches, "(?ism).*larger than 1k.*")
 }
 
 // Webchecker sends false if the request timeouts
 
=== modified file 'bus/endpoint.go'
--- bus/endpoint.go	2014-09-08 15:48:00 +0000
+++ bus/endpoint.go	2015-02-09 10:47:29 +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-02-09 10:47:29 +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-02-09 10:47:29 +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-02-09 10:47:29 +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 'bus/testing/testing_endpoint.go'
--- bus/testing/testing_endpoint.go	2014-07-04 23:00:42 +0000
+++ bus/testing/testing_endpoint.go	2015-02-09 10:47:29 +0000
@@ -89,7 +89,11 @@
 				ticker := tc.watchTicker
 				tc.watchLck.RUnlock()
 				if ticker != nil {
-					<-ticker
+					_, ok := <-ticker
+					if !ok {
+						// bail out
+						return
+					}
 				} else {
 					time.Sleep(10 * time.Millisecond)
 				}
 
=== modified file 'click/cclick/cclick.go'
--- click/cclick/cclick.go	2014-07-07 22:04:30 +0000
+++ click/cclick/cclick.go	2015-02-09 10:47:29 +0000
@@ -51,6 +51,7 @@
 	}
 	ccu.cref = cref
 	runtime.SetFinalizer(holder, func(interface{}) {
+		ccu.cref = nil // 1.3 gc gets confused otherwise
 		C.g_object_unref((C.gpointer)(cref))
 	})
 	return nil
 
=== modified file 'client/client.go'
--- client/client.go	2014-11-03 13:36:00 +0000
+++ client/client.go	2015-02-09 10:47:29 +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-02-09 10:47:29 +0000
@@ -27,6 +27,7 @@
 	"os"
 	"path/filepath"
 	"reflect"
+	//"runtime"
 	"testing"
 	"time"
 
@@ -203,6 +204,15 @@
 	cs.writeTestConfig(nil)
 }
 
+func (cs *clientSuite) TearDownTest(c *C) {
+	//fmt.Println("GOROUTINE# ", runtime.NumGoroutine())
+	/*
+	   var x [16*1024]byte
+	   sz := runtime.Stack(x[:], true)
+	   fmt.Println(string(x[:sz]))
+	*/
+}
+
 type sqlientSuite struct{ clientSuite }
 
 func (s *sqlientSuite) SetUpSuite(c *C) {
@@ -651,7 +661,9 @@
 	)
 	siCond := condition.Fail2Work(2)
 	siEndp := testibus.NewMultiValuedTestingEndpoint(siCond, condition.Work(true), []interface{}{int32(101), "mako", "daily", "Unknown", map[string]string{}})
-	testibus.SetWatchTicker(cEndp, make(chan bool))
+	tickerCh := make(chan bool)
+	testibus.SetWatchTicker(cEndp, tickerCh)
+	defer close(tickerCh)
 	// ok, create the thing
 	cli := NewPushClient(cs.configPath, cs.leveldbPath)
 	cli.log = cs.log
@@ -700,6 +712,7 @@
 	c.Assert(cli.initSessionAndPoller(), IsNil)
 	cs.log.ResetCapture()
 	cli.hasConnectivity = true
+	defer cli.session.Close()
 	cli.handleErr(errors.New("bananas"))
 	c.Check(cs.log.Captured(), Matches, ".*session exited.*bananas\n")
 }
@@ -712,6 +725,7 @@
 	cli := NewPushClient(cs.configPath, "")
 	ln, err := cli.seenStateFactory()
 	c.Assert(err, IsNil)
+	defer ln.Close()
 	c.Check(fmt.Sprintf("%T", ln), Equals, "*seenstate.memSeenState")
 }
 
@@ -719,6 +733,7 @@
 	cli := NewPushClient(cs.configPath, ":memory:")
 	ln, err := cli.seenStateFactory()
 	c.Assert(err, IsNil)
+	defer ln.Close()
 	c.Check(fmt.Sprintf("%T", ln), Equals, "*seenstate.sqliteSeenState")
 }
 
@@ -733,6 +748,7 @@
 	c.Assert(cli.initSessionAndPoller(), IsNil)
 
 	c.Assert(cli.hasConnectivity, Equals, false)
+	defer cli.session.Close()
 	cli.handleConnState(true)
 	c.Check(cli.hasConnectivity, Equals, true)
 	c.Assert(cli.session, NotNil)
@@ -1135,7 +1151,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-11-03 13:36:00 +0000
+++ client/service/postal.go	2015-02-09 10:47:29 +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-11-19 13:58:12 +0000
+++ client/service/service.go	2015-02-09 10:47:29 +0000
@@ -149,14 +149,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)
 	}
 
@@ -181,7 +181,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/seenstate/seenstate.go'
--- client/session/seenstate/seenstate.go	2014-05-14 17:42:24 +0000
+++ client/session/seenstate/seenstate.go	2015-02-09 10:47:29 +0000
@@ -28,8 +28,10 @@
 	// GetAll() returns a "simple" map of the current levels.
 	GetAllLevels() (map[string]int64, error)
 	// FilterBySeen filters notifications already seen, keep track
-	// of them as well
+	// of them as well.
 	FilterBySeen([]protocol.Notification) ([]protocol.Notification, error)
+	// Close closes state.
+	Close()
 }
 
 type memSeenState struct {
@@ -58,6 +60,9 @@
 	return acc, nil
 }
 
+func (m *memSeenState) Close() {
+}
+
 var _ SeenState = (*memSeenState)(nil)
 
 // NewSeenState returns an implementation of SeenState that is memory-based and
 
=== modified file 'client/session/seenstate/sqlseenstate.go'
--- client/session/seenstate/sqlseenstate.go	2014-05-14 17:42:24 +0000
+++ client/session/seenstate/sqlseenstate.go	2015-02-09 10:47:29 +0000
@@ -48,6 +48,11 @@
 	return &sqliteSeenState{db}, nil
 }
 
+// Closes closes the underlying db.
+func (ps *sqliteSeenState) Close() {
+	ps.db.Close()
+}
+
 func (ps *sqliteSeenState) SetLevel(level string, top int64) error {
 	_, err := ps.db.Exec("REPLACE INTO level_map (level, top) VALUES (?, ?)", level, top)
 	if err != nil {
 
=== modified file 'client/session/seenstate/sqlseenstate_test.go'
--- client/session/seenstate/sqlseenstate_test.go	2014-05-14 17:42:24 +0000
+++ client/session/seenstate/sqlseenstate_test.go	2015-02-09 10:47:29 +0000
@@ -112,6 +112,15 @@
 	c.Check(err, ErrorMatches, "cannot insert .*")
 }
 
+func (s *sqlsSuite) TestClose(c *C) {
+	dir := c.MkDir()
+	filename := dir + "test.db"
+	sqls, err := NewSqliteSeenState(filename)
+	c.Check(err, IsNil)
+	c.Assert(sqls, NotNil)
+	sqls.Close()
+}
+
 func (s *sqlsSuite) TestDropPrevThan(c *C) {
 	dir := c.MkDir()
 	filename := dir + "test.db"
 
=== modified file 'client/session/session.go'
--- client/session/session.go	2014-11-19 13:58:12 +0000
+++ client/session/session.go	2015-02-09 10:47:29 +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 'client/session/session_test.go'
--- client/session/session_test.go	2014-11-25 17:36:27 +0000
+++ client/session/session_test.go	2015-02-09 10:47:29 +0000
@@ -162,6 +162,7 @@
 
 func (*brokenSeenState) SetLevel(string, int64) error            { return errors.New("broken.") }
 func (*brokenSeenState) GetAllLevels() (map[string]int64, error) { return nil, errors.New("broken.") }
+func (*brokenSeenState) Close()                                  {}
 func (*brokenSeenState) FilterBySeen([]protocol.Notification) ([]protocol.Notification, error) {
 	return nil, errors.New("broken.")
 }
 
=== modified file 'debian/changelog'
--- debian/changelog	2014-12-11 16:56:31 +0000
+++ debian/changelog	2015-02-09 10:47:29 +0000
@@ -1,3 +1,43 @@
+ubuntu-push (0.67-0ubuntu1) UNRELEASED; urgency=medium
+
+  * Updated precommit script. [dev]
+
+  * Include code examples in docs (instead of repeating). [docs]
+
+  * Make tests more robust in the face of go 1.3 [client, server]
+
+  * Introduce StartClientAuthFlex for acceptance tests: Start a client
+    with auth, take a devId regexp, don't check any client event; support
+    connbroken in acceptanceclient. [server]
+
+  * Cleanup and improve logging, and make log messages more
+    consistent. [client]
+
+  * Partially work around bug lp:1390663 in a minimally intrusive way
+    (real fix will have to wait). [client]
+
+  * Add SIGQUIT handler to spit out stack dumps; more logging
+    tweaks. [client, server]
+
+  * Adds a couple of buttons to exercise more APIs, version bump to
+    0.44. [sample app]
+
+  * Add APIError to server/acceptance/kit that includes the body for
+    debugging. [server]
+
+  * Add DisableKeepAlives and MaxIdleConnsPerHost to the APIClient
+    SetupClient method. [server]
+
+  * Clean up goroutines in tests. [client]
+
+  * Add an explicit check and log message for nil error on webcheck's CopyN. [client]
+
+  * Log line nums, enabled when logLevel = debug. [client server]
+
+  * Workaround gc issue with 1.3 and 32 bits. Fixes FTBFS. [client]
+
+ -- John R. Lenton <[e-mail]>  Mon, 09 Feb 2015 10:19:59 +0000
+
 ubuntu-push (0.66+15.04.20141211-0ubuntu1) vivid; urgency=medium
 
   [ Roberto Alsina ]
 
=== modified file 'dependencies.tsv'
--- dependencies.tsv	2014-08-20 12:42:51 +0000
+++ dependencies.tsv	2015-02-09 10:47:29 +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 'docs/example-client/main.qml'
--- docs/example-client/main.qml	2014-10-23 15:37:21 +0000
+++ docs/example-client/main.qml	2015-02-09 10:47:29 +0000
@@ -71,8 +71,12 @@
         Component.onCompleted: {
             notificationsChanged.connect(messageList.handle_notifications)
             error.connect(messageList.handle_error)
+            onTokenChanged: {
+                console.log("foooooo")
+            }
         }
         appId: "com.ubuntu.developer.ralsina.hello_hello"
+
     }
 
     TextField {
@@ -227,7 +231,7 @@
             right: parent.right
             bottom: parent.bottom
         }
-        height: item1.height * 7
+        height: item1.height * 9
         UbuntuShape {
             anchors.fill: parent
             color: Theme.palette.normal.overlay
@@ -285,6 +289,14 @@
                         value: 42
                     }
                 }
+                Button {
+                    text: "Set Counter Via Plugin"
+                    onClicked: { pushClient.count = counterSlider.value; }
+                }
+                Button {
+                    text: "Clear Persistent Notifications"
+                    onClicked: { pushClient.clearPersistent([]); }
+                }
             }
         }
     }
 
=== modified file 'docs/example-client/manifest.json'
--- docs/example-client/manifest.json	2014-10-23 17:46:23 +0000
+++ docs/example-client/manifest.json	2015-02-09 10:47:29 +0000
@@ -1,7 +1,7 @@
 {
     "architecture": "all",
     "description": "Example app for Ubuntu push notifications.",
-    "framework": "ubuntu-sdk-14.10-dev2",
+    "framework": "ubuntu-sdk-14.10",
     "hooks": {
         "hello": {
             "apparmor": "hello.json",
@@ -15,5 +15,5 @@
     "maintainer": "Roberto Alsina <[e-mail]>",
     "name": "com.ubuntu.developer.ralsina.hello",
     "title": "Hello",
-    "version": "0.4.3"
+    "version": "0.4.4"
 }
 
=== modified file 'identifier/identifier.go'
--- identifier/identifier.go	2014-08-04 20:40:50 +0000
+++ identifier/identifier.go	2015-02-09 10:47:29 +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-02-09 10:47:29 +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-02-09 10:47:29 +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-02-09 10:47:29 +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	2014-11-05 12:07:53 +0000
+++ launch_helper/kindpool.go	2015-02-09 10:47:29 +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	2014-11-05 12:07:53 +0000
+++ launch_helper/legacy/legacy.go	2015-02-09 10:47:29 +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-02-09 10:47:29 +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 'logger/logger.go'
--- logger/logger.go	2014-04-11 23:17:40 +0000
+++ logger/logger.go	2015-02-09 10:47:29 +0000
@@ -50,7 +50,8 @@
 }
 
 const (
-	lError = iota
+	calldepthBase = 3
+	lError        = iota
 	lInfo
 	lDebug
 )
@@ -81,8 +82,12 @@
 // level. The level can be, in order: "error", "info", "debug". It takes an
 // io.Writer.
 func NewSimpleLogger(w io.Writer, level string) Logger {
+	flags := log.Ldate | log.Ltime | log.Lmicroseconds
+	if levelToNLevel[level] >= lDebug {
+		flags = flags | log.Lshortfile
+	}
 	return NewSimpleLoggerFromMinimalLogger(
-		log.New(w, "", log.Ldate|log.Ltime|log.Lmicroseconds),
+		log.New(w, "", flags),
 		level,
 	)
 }
@@ -92,13 +97,13 @@
 }
 
 func (lg *simpleLogger) Errorf(format string, v ...interface{}) {
-	lg.outputFunc(2, fmt.Sprintf("ERROR "+format, v...))
+	lg.outputFunc(calldepthBase, fmt.Sprintf("ERROR "+format, v...))
 }
 
 var osExit = os.Exit // for testing
 
 func (lg *simpleLogger) Fatalf(format string, v ...interface{}) {
-	lg.outputFunc(2, fmt.Sprintf("ERROR "+format, v...))
+	lg.outputFunc(calldepthBase, fmt.Sprintf("ERROR "+format, v...))
 	osExit(1)
 }
 
@@ -107,18 +112,18 @@
 	stack := make([]byte, 8*1024) // Stack writes less but doesn't fail
 	stackWritten := runtime.Stack(stack, false)
 	stack = stack[:stackWritten]
-	lg.outputFunc(2, fmt.Sprintf("ERROR(PANIC) %s:\n%s", msg, stack))
+	lg.outputFunc(calldepthBase, fmt.Sprintf("ERROR(PANIC) %s:\n%s", msg, stack))
 }
 
 func (lg *simpleLogger) Infof(format string, v ...interface{}) {
 	if lg.nlevel >= lInfo {
-		lg.outputFunc(2, fmt.Sprintf("INFO "+format, v...))
+		lg.outputFunc(calldepthBase, fmt.Sprintf("INFO "+format, v...))
 	}
 }
 
 func (lg *simpleLogger) Debugf(format string, v ...interface{}) {
 	if lg.nlevel >= lDebug {
-		lg.outputFunc(2, fmt.Sprintf("DEBUG "+format, v...))
+		lg.outputFunc(calldepthBase, fmt.Sprintf("DEBUG "+format, v...))
 	}
 }
 
 
=== modified file 'logger/logger_test.go'
--- logger/logger_test.go	2014-04-11 19:05:35 +0000
+++ logger/logger_test.go	2015-02-09 10:47:29 +0000
@@ -163,3 +163,15 @@
 	checkError(`{"lvl": 1}`, "lvl:.*type string")
 	checkError(`{"lvl": "foo"}`, "lvl: not a log level: foo")
 }
+
+func (s *loggerSuite) TestLogLineNo(c *C) {
+	buf := &bytes.Buffer{}
+	logger := NewSimpleLogger(buf, "debug")
+	logger.Output(1, "foobaz")
+	c.Check(buf.String(), Matches, ".* .* logger_test.go:[0-9]+: foobaz\n")
+
+	buf.Reset()
+	logger = NewSimpleLogger(buf, "error")
+	logger.Output(1, "foobaz")
+	c.Check(buf.String(), Matches, ".* .* foobaz\n")
+}
 
=== modified file 'messaging/messaging.go'
--- messaging/messaging.go	2014-07-27 02:54:40 +0000
+++ messaging/messaging.go	2015-02-09 10:47:29 +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-02-09 10:47:29 +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-02-09 10:47:29 +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/kit/api.go'
--- server/acceptance/kit/api.go	2014-08-20 19:48:59 +0000
+++ server/acceptance/kit/api.go	2015-02-09 10:47:29 +0000
@@ -35,10 +35,21 @@
 	httpClient *http.Client
 }
 
+type APIError struct {
+	Msg  string
+	Body []byte
+}
+
+func (e *APIError) Error() string {
+	return e.Msg
+}
+
 // SetupClient sets up the http client to make requests.
-func (api *APIClient) SetupClient(tlsConfig *tls.Config) {
+func (api *APIClient) SetupClient(tlsConfig *tls.Config, disableKeepAlives bool, maxIdleConnsPerHost int) {
 	api.httpClient = &http.Client{
-		Transport: &http.Transport{TLSClientConfig: tlsConfig},
+		Transport: &http.Transport{TLSClientConfig: tlsConfig,
+			DisableKeepAlives:   disableKeepAlives,
+			MaxIdleConnsPerHost: maxIdleConnsPerHost},
 	}
 }
 
@@ -73,7 +84,7 @@
 	var res map[string]interface{}
 	err = json.Unmarshal(body, &res)
 	if err != nil {
-		return nil, err
+		return nil, &APIError{err.Error(), body}
 	}
 	if ok, _ := res["ok"].(bool); !ok {
 		return res, ErrNOk
 
=== modified file 'server/acceptance/suites/helpers.go'
--- server/acceptance/suites/helpers.go	2014-11-04 16:29:31 +0000
+++ server/acceptance/suites/helpers.go	2015-02-09 10:47:29 +0000
@@ -80,7 +80,7 @@
 	return cfgFpath
 }
 
-var rxLineInfo = regexp.MustCompile("^.*? ([[:alpha:]].*)\n")
+var rxLineInfo = regexp.MustCompile("^.*?(?: .+\\.go:\\d+:)? ([[:alpha:]].*)\n")
 
 // RunAndObserve runs cmdName and returns a channel that will receive
 // cmdName stderr logging and a function to kill the process.
 
=== 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-02-09 10:47:29 +0000
@@ -21,7 +21,9 @@
 	"flag"
 	"fmt"
 	"net"
+	"net/http"
 	"os"
+	"regexp"
 	"runtime"
 	"time"
 
@@ -48,6 +50,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 +85,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 }
 }
 
@@ -101,7 +109,7 @@
 	c.Assert(s.ServerHandle.ServerEvents, NotNil)
 	c.Assert(s.ServerHandle.ServerAddr, Not(Equals), "")
 	c.Assert(s.ServerAPIURL, Not(Equals), "")
-	s.SetupClient(nil)
+	s.SetupClient(nil, false, http.DefaultMaxIdleConnsPerHost)
 }
 
 func (s *AcceptanceSuite) TearDownTest(c *C) {
 
=== modified file 'testing/helpers.go'
--- testing/helpers.go	2014-07-11 19:42:57 +0000
+++ testing/helpers.go	2015-02-09 10:47:29 +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-02-09 10:47:29 +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-02-09 10:47:29 +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-02-09 10:47:29 +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-02-09 10:47:29 +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-02-09 10:47:29 +0000
@@ -65,30 +65,69 @@
 	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
-	dial   func() error
-	jitter func(time.Duration) time.Duration
+	stateLock     sync.RWMutex
+	stateValue    redialerState
+	stopping      chan struct{}
+	reallyStopped chan struct{}
+	dial          func() error
+	jitter        func(time.Duration) time.Duration
+}
+
+func (ar *autoRedialer) state() redialerState {
+	ar.stateLock.RLock()
+	defer ar.stateLock.RUnlock()
+	return ar.stateValue
+}
+
+func (ar *autoRedialer) setState(s redialerState) {
+	ar.stateLock.Lock()
+	defer ar.stateLock.Unlock()
+	ar.stateValue = s
+}
+
+func (ar *autoRedialer) setStateIfEqual(oldState, newState redialerState) bool {
+	ar.stateLock.Lock()
+	defer ar.stateLock.Unlock()
+	if ar.stateValue != oldState {
+		return false
+	}
+	ar.stateValue = newState
+	return true
+}
+
+func (ar *autoRedialer) setStateStopped() {
+	ar.stateLock.Lock()
+	defer ar.stateLock.Unlock()
+	switch ar.stateValue {
+	case Stopped:
+		return
+	case Unconfigured:
+		close(ar.reallyStopped)
+	}
+	ar.stateValue = Stopped
+	close(ar.stopping)
 }
 
 func (ar *autoRedialer) Stop() {
 	if ar != nil {
-		ar.lock.RLock()
-		defer ar.lock.RUnlock()
-		if ar.stop != nil {
-			ar.stop <- true
-		}
+		ar.setStateStopped()
+		<-ar.reallyStopped
 	}
 }
 
-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 +135,20 @@
 		// 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()
+	defer close(ar.reallyStopped)
 
 	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
 		}
@@ -123,8 +162,7 @@
 		}
 		dialAttempts++
 		select {
-		case <-stop:
-			return dialAttempts
+		case <-ar.stopping:
 		case <-time.After(timeout):
 		}
 	}
@@ -133,7 +171,12 @@
 // 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}
+	ar := &autoRedialer{
+		stateValue:    Unconfigured,
+		dial:          dialer.Dial,
+		reallyStopped: make(chan struct{}),
+		stopping:      make(chan struct{}),
+	}
 	jitterer, ok := dialer.(Jitterer)
 	if ok {
 		ar.jitter = jitterer.Jitter
 
=== added file 'util/redialer_states.gv'
--- util/redialer_states.gv	1970-01-01 00:00:00 +0000
+++ util/redialer_states.gv	2015-02-09 10:47:29 +0000
@@ -0,0 +1,9 @@
+digraph "redialer" {
+    "Unconfigured" -> "Redialing" [ label="Redial" ]
+    "Unconfigured" -> "Stopped"   [ label="Stop"   ]
+
+    "Redialing"    -> "Redialing" [ label="Redial" ]
+    "Redialing"    -> "Stopped"   [ label="Stop"   ]
+
+    "Stopped"      -> "Stopped"   [ label="*"      ]
+}
 
=== modified file 'util/redialer_test.go'
--- util/redialer_test.go	2014-02-05 13:02:47 +0000
+++ util/redialer_test.go	2015-02-09 10:47:29 +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()
 }