Merge lp:~pedronis/ubuntu-push/robust-tests-1.3 into lp:ubuntu-push

[Samuele Pedroni]

make tests more robust in the face of 1.3

make tests more robust in the face of 1.3

- avoid map order issues
- -race slows down some tests so that small timeouts were problematic => increase timeout
- Reader Read can return data and EOF error together => use helpers

Unmerged revisions

=== modified file '.precommit'
--- .precommit	2014-01-23 10:03:39 +0000
+++ .precommit	2014-11-25 18:40:27 +0000
@@ -5,25 +5,27 @@
 # And put this here-document in ~/.bazaar/plugins/precommit_script.py:
 <<EOF
 import os
-import subprocess
-from bzrlib.mutabletree import MutableTree
-from bzrlib import errors
-
-def start_commit_hook(*_):
-    """This hook will execute '.precommit' script from root path of the bazaar
-    branch. Commit will be canceled if precommit fails."""
-
-    # this hook only makes sense if a precommit file exist.
-    if not os.path.exists(".precommit"):
-        return
-    try:
-        subprocess.check_call(os.path.abspath(".precommit"))
-    # if precommit fails (process return not zero) cancel commit.
-    except subprocess.CalledProcessError:
-        raise errors.BzrError("pre commit check failed.")
-
-MutableTree.hooks.install_named_hook('start_commit', start_commit_hook,
-                                     'Run "precommit" script on start_commit')
+
+if not os.getenv("SKIP_COMMIT_HOOK"):
+    import subprocess
+    from bzrlib.mutabletree import MutableTree
+    from bzrlib import errors
+
+    def start_commit_hook(*_):
+        """This hook will execute '.precommit' script from root path of the bazaar
+        branch. Commit will be canceled if precommit fails."""
+
+        # this hook only makes sense if a precommit file exist.
+        if not os.path.exists(".precommit"):
+            return
+        try:
+            subprocess.check_call(os.path.abspath(".precommit"))
+        # if precommit fails (process return not zero) cancel commit.
+        except subprocess.CalledProcessError:
+            raise errors.BzrError("pre commit check failed (set SKIP_COMMIT_HOOK to skip).")
+
+    MutableTree.hooks.install_named_hook('start_commit', start_commit_hook,
+                                         'Run "precommit" script on start_commit')
 EOF
 
 make check-format # or whatever
 
=== modified file 'PACKAGE_DEPS'
--- PACKAGE_DEPS	2014-09-05 10:48:36 +0000
+++ PACKAGE_DEPS	2014-11-25 18:40:27 +0000
@@ -12,3 +12,4 @@
 libclick-0.4-dev
 liburl-dispatcher1-dev
 libaccounts-glib-dev
+system-image-dbus
 
=== modified file 'client/service/service.go'
--- client/service/service.go	2014-11-03 13:36:00 +0000
+++ client/service/service.go	2014-11-25 18:40:27 +0000
@@ -140,6 +140,8 @@
 		case resp.StatusCode >= http.StatusInternalServerError:
 			// XXX retry on 503
 			return nil, ErrBadServer
+		case resp.StatusCode == http.StatusUnauthorized:
+			return nil, ErrBadAuth
 		default:
 			return nil, ErrBadRequest
 		}
 
=== modified file 'client/service/service_test.go'
--- client/service/service_test.go	2014-08-06 09:01:59 +0000
+++ client/service/service_test.go	2014-11-25 18:40:27 +0000
@@ -19,6 +19,7 @@
 import (
 	"encoding/json"
 	"fmt"
+	"io"
 	"net/http"
 	"net/http/httptest"
 	"os"
@@ -179,7 +180,8 @@
 func (ss *serviceSuite) TestRegistrationWorks(c *C) {
 	ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		buf := make([]byte, 256)
-		n, e := r.Body.Read(buf)
+		n := r.ContentLength
+		_, e := io.ReadFull(r.Body, buf[:n])
 		c.Assert(e, IsNil)
 		req := registrationRequest{}
 		c.Assert(json.Unmarshal(buf[:n], &req), IsNil)
@@ -240,6 +242,23 @@
 	c.Check(err, ErrorMatches, "unable to request registration: .*")
 }
 
+func (ss *serviceSuite) TestManageRegFailsOn401(c *C) {
+	ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		http.Error(w, "Unauthorized", 401)
+	}))
+	defer ts.Close()
+	setup := &PushServiceSetup{
+		DeviceId:   "fake-device-id",
+		RegURL:     helpers.ParseURL(ts.URL),
+		AuthGetter: func(string) string { return "tok" },
+	}
+	svc := NewPushService(setup, ss.log)
+	svc.Bus = ss.bus
+	reg, err := svc.register(aPackageOnBus, []interface{}{anAppId}, nil)
+	c.Check(err, Equals, ErrBadAuth)
+	c.Check(reg, IsNil)
+}
+
 func (ss *serviceSuite) TestManageRegFailsOn40x(c *C) {
 	ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		http.Error(w, "I'm a teapot", 418)
@@ -277,7 +296,8 @@
 func (ss *serviceSuite) TestManageRegFailsOnBadJSON(c *C) {
 	ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		buf := make([]byte, 256)
-		n, e := r.Body.Read(buf)
+		n := r.ContentLength
+		_, e := io.ReadFull(r.Body, buf[:n])
 		c.Assert(e, IsNil)
 		req := registrationRequest{}
 		c.Assert(json.Unmarshal(buf[:n], &req), IsNil)
@@ -303,7 +323,8 @@
 func (ss *serviceSuite) TestManageRegFailsOnBadJSONDocument(c *C) {
 	ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		buf := make([]byte, 256)
-		n, e := r.Body.Read(buf)
+		n := r.ContentLength
+		_, e := io.ReadFull(r.Body, buf[:n])
 		c.Assert(e, IsNil)
 		req := registrationRequest{}
 		c.Assert(json.Unmarshal(buf[:n], &req), IsNil)
@@ -329,7 +350,8 @@
 func (ss *serviceSuite) TestDBusUnregisterWorks(c *C) {
 	ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		buf := make([]byte, 256)
-		n, e := r.Body.Read(buf)
+		n := r.ContentLength
+		_, e := io.ReadFull(r.Body, buf[:n])
 		c.Assert(e, IsNil)
 		req := registrationRequest{}
 		c.Assert(json.Unmarshal(buf[:n], &req), IsNil)
@@ -356,7 +378,8 @@
 	invoked := make(chan bool, 1)
 	ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		buf := make([]byte, 256)
-		n, e := r.Body.Read(buf)
+		n := r.ContentLength
+		_, e := io.ReadFull(r.Body, buf[:n])
 		c.Assert(e, IsNil)
 		req := registrationRequest{}
 		c.Assert(json.Unmarshal(buf[:n], &req), IsNil)
 
=== modified file 'client/session/session.go'
--- client/session/session.go	2014-11-03 13:36:00 +0000
+++ client/session/session.go	2014-11-25 18:40:27 +0000
@@ -430,7 +430,7 @@
 		return err
 	}
 	sess.clearShouldDelay()
-	sess.Log.Debugf("broadcast chan:%v app:%v topLevel:%d payloads:%s",
+	sess.Log.Infof("broadcast chan:%v app:%v topLevel:%d payloads:%s",
 		bcast.ChanId, bcast.AppId, bcast.TopLevel, bcast.Payloads)
 	if bcast.ChanId == protocol.SystemChannelId {
 		// the system channel id, the only one we care about for now
@@ -438,7 +438,7 @@
 		sess.BroadcastCh <- sess.decodeBroadcast(bcast)
 		sess.Log.Debugf("sent bcast over")
 	} else {
-		sess.Log.Debugf("what is this weird channel, %#v?", bcast.ChanId)
+		sess.Log.Errorf("what is this weird channel, %#v?", bcast.ChanId)
 	}
 	return nil
 }
@@ -468,7 +468,7 @@
 		if to == nil {
 			continue
 		}
-		sess.Log.Debugf("unicast app:%v msg:%s payload:%s",
+		sess.Log.Infof("unicast app:%v msg:%s payload:%s",
 			notif.AppId, notif.MsgId, notif.Payload)
 		sess.Log.Debugf("sending ucast over")
 		sess.NotificationsCh <- AddressedNotification{to, notif}
 
=== modified file 'client/session/session_test.go'
--- client/session/session_test.go	2014-11-03 13:36:00 +0000
+++ client/session/session_test.go	2014-11-25 18:40:27 +0000
@@ -1480,7 +1480,7 @@
 }
 
 var (
-	dialTestTimeout = 100 * time.Millisecond
+	dialTestTimeout = 300 * time.Millisecond
 	dialTestConf    = ClientSessionConfig{
 		ExchangeTimeout: dialTestTimeout,
 		PEM:             helpers.TestCertPEMBlock,
@@ -1584,7 +1584,7 @@
 
 	// 2. "connect" (but on the fake protcol above! woo)
 
-	c.Check(takeNext(downCh), Equals, "deadline 100ms")
+	c.Check(takeNext(downCh), Equals, fmt.Sprintf("deadline %v", dialTestTimeout))
 	_, ok := takeNext(downCh).(protocol.ConnectMsg)
 	c.Check(ok, Equals, true)
 	upCh <- nil // no error
@@ -1597,7 +1597,7 @@
 	// 3. "loop"
 
 	// ping works,
-	c.Check(takeNext(downCh), Equals, "deadline 110ms")
+	c.Check(takeNext(downCh), Equals, fmt.Sprintf("deadline %v", dialTestTimeout+10*time.Millisecond))
 	upCh <- protocol.PingPongMsg{Type: "ping"}
 	c.Check(takeNext(downCh), Equals, protocol.PingPongMsg{Type: "pong"})
 	upCh <- nil
@@ -1613,7 +1613,7 @@
 		TopLevel: 2,
 		Payloads: []json.RawMessage{json.RawMessage(`{"b":1}`)},
 	}
-	c.Check(takeNext(downCh), Equals, "deadline 110ms")
+	c.Check(takeNext(downCh), Equals, fmt.Sprintf("deadline %v", dialTestTimeout+10*time.Millisecond))
 	upCh <- b
 	c.Check(takeNext(downCh), Equals, protocol.AckMsg{"ack"})
 	upCh <- nil
@@ -1625,7 +1625,7 @@
 	c.Check(levels, DeepEquals, map[string]int64{"0": 2})
 
 	// and ping still work even after that.
-	c.Check(takeNext(downCh), Equals, "deadline 110ms")
+	c.Check(takeNext(downCh), Equals, fmt.Sprintf("deadline %v", dialTestTimeout+10*time.Millisecond))
 	upCh <- protocol.PingPongMsg{Type: "ping"}
 	c.Check(takeNext(downCh), Equals, protocol.PingPongMsg{Type: "pong"})
 	failure := errors.New("pongs")
 
=== modified file 'debian/config.json'
--- debian/config.json	2014-08-21 10:47:12 +0000
+++ debian/config.json	2014-11-25 18:40:27 +0000
@@ -12,7 +12,7 @@
     "recheck_timeout": "10m",
     "connectivity_check_url": "http://start.ubuntu.com/connectivity-check.html",
     "connectivity_check_md5": "4589f42e1546aa47ca181e5d949d310b",
-    "log_level": "debug",
+    "log_level": "info",
     "fallback_vibration": {"pattern": [100, 100], "repeat": 2},
     "fallback_sound": "sounds/ubuntu/notifications/Slick.ogg",
     "poll_interval": "5m",
 
=== modified file 'docs/_common.txt'
--- docs/_common.txt	2014-10-09 16:06:52 +0000
+++ docs/_common.txt	2014-11-25 18:40:27 +0000
@@ -185,3 +185,46 @@
 :clear_pending: Discards all previous pending notifications. Usually in response to getting a "too-many-pending" error.
 :replace_tag: If there's a pending notification with the same tag, delete it before queuing this new one.
 :data: A JSON object.
+
+Limitations of the Server API
+-----------------------------
+
+The push notification infrastructure is meant to help ensuring timely
+delivery of application notifications if the device is online or
+timely informing the device user about application notifications that
+were pending when the device comes back online. This in the face of
+applications not being allowed to be running all the time, and
+avoiding the resource cost of many applications all polling different services
+frequently.
+
+The push notification infrastructure is architected to guarantee at
+least best-effort with respect to these goals and beyond it, on the
+other end applications should not expect to be able to use and only
+rely on the push notification infrastructure to store application
+messages if they want ensure all their notification or messages are
+delivered, the infrastructure is not intended to be the only long term
+"inbox" storage for an application.
+
+To preserve overall throughput the infrastructure imposes some limits
+on applications:
+
+ * message data payload is limited to 2K
+
+ * when inserted all messages need to specify an expiration date after
+   which they can be dropped and not delivered
+
+ * an application is limited in the number of messages per token
+   (application/user/device combination) that can be undelivered/pending at the
+   same time (100 currently)
+
+replace_tag can be used to implement notifications for which the newest
+one replace the previous one if pending.
+
+clear_pending can be used to be deal with a pending message limit
+reached, possibly substituting the current undelivered messages with a
+more generic one.
+
+Applications using the push notification HTTP API should be robust
+against receiving 503 errors, retrying after waiting with increasing
+back-off. Later rate limits (signaled with the 429 status) may also come
+into play.
 
=== modified file 'docs/example-client/main.qml'
--- docs/example-client/main.qml	2014-09-10 14:38:40 +0000
+++ docs/example-client/main.qml	2014-11-25 18:40:27 +0000
@@ -26,9 +26,42 @@
         property alias nickEnabled: nickEdit.enabled
     }
 
+    states: [
+        State {
+            name: "no-push-token"
+            when: (pushClient.token == "")
+            PropertyChanges { target: nickEdit; readOnly: true}
+            PropertyChanges { target: nickEdit; focus: true}
+            PropertyChanges { target: messageEdit; enabled: false}
+            PropertyChanges { target: loginButton; enabled: false}
+            PropertyChanges { target: loginButton; text: "Login"}
+        },
+        State {
+            name: "push-token-not-registered"
+            when: ((pushClient.token != "") && (chatClient.registered == false))
+            PropertyChanges { target: nickEdit; readOnly: false}
+            PropertyChanges { target: nickEdit; text: ""}
+            PropertyChanges { target: nickEdit; focus: true}
+            PropertyChanges { target: messageEdit; enabled: false}
+            PropertyChanges { target: loginButton; enabled: true}
+            PropertyChanges { target: loginButton; text: "Login"}
+        },
+        State {
+            name: "registered"
+            when: ((pushClient.token != "") && (chatClient.registered == true))
+            PropertyChanges { target: nickEdit; readOnly: true}
+            PropertyChanges { target: nickEdit; text: "Your nick is " + chatClient.nick}
+            PropertyChanges { target: messageEdit; focus: true}
+            PropertyChanges { target: messageEdit; enabled: true}
+            PropertyChanges { target: loginButton; enabled: true}
+            PropertyChanges { target: loginButton; text: "Logout"}
+        }
+    ]
+
+    state: "no-push-token"
+
     ChatClient {
         id: chatClient
-        onRegisteredChanged: {nickEdit.registered()}
         onError: {messageList.handle_error(msg)}
         token: pushClient.token
     }
@@ -44,7 +77,6 @@
 
     TextField {
         id: nickEdit
-        focus: true
         placeholderText: "Your nickname"
         inputMethodHints: Qt.ImhNoAutoUppercase | Qt.ImhNoPredictiveText | Qt.ImhPreferLowercase
         anchors.left: parent.left
@@ -53,31 +85,17 @@
         anchors.leftMargin: units.gu(.5)
         anchors.rightMargin: units.gu(1)
         anchors.topMargin: units.gu(.5)
-        function registered() {
-            readOnly = true
-            text = "Your nick is " + chatClient.nick
-            messageEdit.focus = true
-            messageEdit.enabled = true
-            loginButton.text = "Logout"
-        }
         onAccepted: { loginButton.clicked() }
     }
 
     Button {
         id: loginButton
-        text: chatClient.rgistered? "Logout": "Login"
         anchors.top: nickEdit.top
         anchors.right: parent.right
         anchors.rightMargin: units.gu(.5)
         onClicked: {
             if (chatClient.nick) { // logout
                 chatClient.nick = ""
-                text = "Login"
-                nickEdit.enabled = true
-                nickEdit.readOnly = false
-                nickEdit.text = ""
-                nickEdit.focus = true
-                messageEdit.enabled = false
             } else { // login
                 chatClient.nick = nickEdit.text
             }
@@ -94,7 +112,6 @@
         anchors.rightMargin: units.gu(.5)
         anchors.leftMargin: units.gu(.5)
         placeholderText: "Your message"
-        enabled: false
         onAccepted: {
             console.log("sending " + text)
             var idx = text.indexOf(":")
 
=== modified file 'docs/example-client/manifest.json'
--- docs/example-client/manifest.json	2014-09-10 14:38:31 +0000
+++ docs/example-client/manifest.json	2014-11-25 18:40:27 +0000
@@ -15,5 +15,5 @@
     "maintainer": "Roberto Alsina <[e-mail]>",
     "name": "com.ubuntu.developer.ralsina.hello",
     "title": "Hello",
-    "version": "0.4.2"
+    "version": "0.4.3"
 }
 
=== modified file 'docs/lowlevel.txt'
--- docs/lowlevel.txt	2014-10-15 16:34:25 +0000
+++ docs/lowlevel.txt	2014-11-25 18:40:27 +0000
@@ -57,6 +57,8 @@
 The Register method takes as argument the APP_ID (in the example, com.ubuntu.music_music) and returns a token identifying the user
 and device. For this to succeed the user **must** have an Ubuntu One account configured in the device.
 
+In the case the Register method returns a "bad auth" error, the application should inform the user to generate new Ubuntu One tokens.
+
 The APP_ID is as described in the `ApplicationId documentation <https://wiki.ubuntu.com/AppStore/Interfaces/ApplicationId>`__
 except that the version is treated as optional. Therefore both ``com.ubuntu.music_music`` and ``com.ubuntu.music_music_1.3.496``
 are valid. Keep in mind that while both versioned and unversioned APP_IDs are valid, they are still different and will affect
 
=== modified file 'launch_helper/kindpool.go'
--- launch_helper/kindpool.go	2014-08-20 12:42:51 +0000
+++ launch_helper/kindpool.go	2014-11-25 18:40:27 +0000
@@ -294,12 +294,13 @@
 	}
 	payload, err := ioutil.ReadFile(args.FileOut)
 	if err != nil {
-		pool.log.Errorf("unable to read output from helper: %v", err)
+		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)
 		res := &HelperResult{Input: args.Input}
 		err = json.Unmarshal(payload, &res.HelperOutput)
 		if err != nil {
-			pool.log.Debugf("failed to parse HelperOutput from helper output: %v", err)
+			pool.log.Errorf("failed to parse HelperOutput from %v helper output: %v", args.AppId, err)
 		} else {
 			pool.chOut <- res
 		}
 
=== modified file 'launch_helper/legacy/legacy.go'
--- launch_helper/legacy/legacy.go	2014-08-21 18:03:49 +0000
+++ launch_helper/legacy/legacy.go	2014-11-25 18:40:27 +0000
@@ -55,7 +55,7 @@
 	err error
 }
 
-func (lhl *legacyHelperLauncher) Launch(_, progname, f1, f2 string) (string, error) {
+func (lhl *legacyHelperLauncher) Launch(appId, progname, f1, f2 string) (string, error) {
 	comm := make(chan msg)
 
 	go func() {
@@ -78,9 +78,8 @@
 		p_err := cmd.Wait()
 		if p_err != nil {
 			// Helper failed or got killed, log output/errors
-			lhl.log.Errorf("Legacy helper failed: %v", p_err)
-			lhl.log.Errorf("Legacy helper failed. Stdout: %s", stdout)
-			lhl.log.Errorf("Legacy helper failed. Stderr: %s", stderr)
+			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 'messaging/messaging_test.go'
--- messaging/messaging_test.go	2014-07-27 02:54:40 +0000
+++ messaging/messaging_test.go	2014-11-25 18:40:27 +0000
@@ -17,6 +17,7 @@
 package messaging
 
 import (
+	"sort"
 	"time"
 
 	. "launchpad.net/gocheck"
@@ -121,6 +122,12 @@
 	c.Check(payload.Actions[1], Equals, "action-1")
 }
 
+func (msg *MessagingSuite) checkTags(c *C, got, expected []string) {
+	sort.Strings(got)
+	sort.Strings(expected)
+	c.Check(got, DeepEquals, expected)
+}
+
 func (ms *MessagingSuite) TestTagsListsTags(c *C) {
 	mmu := New(ms.log)
 	f := func(s string) *launch_helper.Notification {
@@ -130,15 +137,15 @@
 
 	c.Check(mmu.Tags(ms.app), IsNil)
 	c.Assert(mmu.Present(ms.app, "notif1", f("one")), Equals, true)
-	c.Check(mmu.Tags(ms.app), DeepEquals, []string{"one"})
+	ms.checkTags(c, mmu.Tags(ms.app), []string{"one"})
 	c.Assert(mmu.Present(ms.app, "notif2", f("")), Equals, true)
-	c.Check(mmu.Tags(ms.app), DeepEquals, []string{"one", ""})
+	ms.checkTags(c, mmu.Tags(ms.app), []string{"one", ""})
 	// and an empty notification doesn't count
 	c.Assert(mmu.Present(ms.app, "notif3", &launch_helper.Notification{Tag: "X"}), Equals, false)
-	c.Check(mmu.Tags(ms.app), DeepEquals, []string{"one", ""})
+	ms.checkTags(c, mmu.Tags(ms.app), []string{"one", ""})
 	// and they go away if we remove one
 	mmu.RemoveNotification("notif1", false)
-	c.Check(mmu.Tags(ms.app), DeepEquals, []string{""})
+	ms.checkTags(c, mmu.Tags(ms.app), []string{""})
 	mmu.RemoveNotification("notif2", false)
 	c.Check(mmu.Tags(ms.app), IsNil)
 }
@@ -169,9 +176,9 @@
 	//   app 1: "one", "two", "";
 	//   app 2: "one", "two";
 	//   app 3: "one", ""
-	c.Assert(mm.Tags(app1), DeepEquals, []string{"one", "two", ""})
-	c.Assert(mm.Tags(app2), DeepEquals, []string{"one", "two"})
-	c.Assert(mm.Tags(app3), DeepEquals, []string{"one", ""})
+	ms.checkTags(c, mm.Tags(app1), []string{"one", "two", ""})
+	ms.checkTags(c, mm.Tags(app2), []string{"one", "two"})
+	ms.checkTags(c, mm.Tags(app3), []string{"one", ""})
 
 	// clearing a non-existent tag does nothing
 	c.Check(mm.Clear(app1, "foo"), Equals, 0)
 
=== modified file 'server/acceptance/suites/helpers.go'
--- server/acceptance/suites/helpers.go	2014-07-08 15:08:52 +0000
+++ server/acceptance/suites/helpers.go	2014-11-25 18:40:27 +0000
@@ -127,6 +127,11 @@
 				c.Log(info)
 				continue
 			}
+			if strings.HasPrefix(info, "DEBUG ") && !strings.HasPrefix(info, "DEBUG session(") {
+				// skip non session DEBUG logs
+				c.Log(info)
+				continue
+			}
 			logs <- info
 		}
 	}()
@@ -136,16 +141,12 @@
 const (
 	DevListeningOnPat  = "INFO listening for devices on "
 	HTTPListeningOnPat = "INFO listening for http on "
-	debugPrefix        = "DEBUG "
 )
 
-// ExtractListeningAddr goes over logs ignoring DEBUG lines
-// until a line starting with pat and returns the rest of that line.
+// ExtractListeningAddr goes over logs until a line starting with pat
+// and returns the rest of that line.
 func ExtractListeningAddr(c *C, logs <-chan string, pat string) string {
 	for line := range logs {
-		if strings.HasPrefix(line, debugPrefix) {
-			continue
-		}
 		if !strings.HasPrefix(line, pat) {
 			c.Fatalf("matching %v: %v", pat, line)
 		}
 
=== modified file 'server/api/handlers.go'
--- server/api/handlers.go	2014-07-14 15:23:17 +0000
+++ server/api/handlers.go	2014-11-25 18:40:27 +0000
@@ -23,6 +23,7 @@
 	"encoding/json"
 	"fmt"
 	"io"
+	"mime"
 	"net/http"
 	"time"
 
@@ -98,6 +99,12 @@
 		"Wrong request method, should be POST",
 		nil,
 	}
+	ErrWrongRequestMethodGET = &APIError{
+		http.StatusMethodNotAllowed,
+		invalidRequest,
+		"Wrong request method, should be GET",
+		nil,
+	}
 	ErrMalformedJSONObject = &APIError{
 		http.StatusBadRequest,
 		invalidRequest,
@@ -268,7 +275,8 @@
 	if err := checkContentLength(request, maxBodySize); err != nil {
 		return err
 	}
-	if request.Header.Get("Content-Type") != JSONMediaType {
+	mediaType, _, err := mime.ParseMediaType(request.Header.Get("Content-Type"))
+	if err != nil || mediaType != JSONMediaType {
 		return ErrWrongContentType
 	}
 	return nil
@@ -452,14 +460,17 @@
 	if err != nil {
 		switch err {
 		case store.ErrUnknownToken:
+			ctx.logger.Debugf("notify: %v %v unknown", ucast.AppId, ucast.Token)
 			return nil, ErrUnknownToken
 		case store.ErrUnauthorized:
+			ctx.logger.Debugf("notify: %v %v unauthorized", ucast.AppId, ucast.Token)
 			return nil, ErrUnauthorized
 		default:
 			ctx.logger.Errorf("could not resolve token: %v", err)
 			return nil, ErrCouldNotResolveToken
 		}
 	}
+	ctx.logger.Debugf("notify: %v %v -> %v", ucast.AppId, ucast.Token, chanId)
 
 	_, notifs, meta, err := sto.GetChannelUnfiltered(chanId)
 	if err != nil {
@@ -491,6 +502,7 @@
 	if ucast.ClearPending {
 		scrubCriteria = []string{ucast.AppId}
 	} else if forApp >= ctx.storage.GetMaxNotificationsPerApplication() {
+		ctx.logger.Debugf("notify: %v %v too many pending", ucast.AppId, chanId)
 		return nil, apiErrorWithExtra(ErrTooManyPendingNotifications,
 			&last.Payload)
 	} else if replaceable > 0 {
@@ -518,6 +530,8 @@
 	}
 
 	ctx.broker.Unicast(chanId)
+
+	ctx.logger.Debugf("notify: ok %v %v id:%v clear:%v replace:%v expired:%v", ucast.AppId, chanId, msgId, ucast.ClearPending, replaceable, expired)
 	return nil, nil
 }
 
 
=== modified file 'server/api/handlers_test.go'
--- server/api/handlers_test.go	2014-07-15 15:03:49 +0000
+++ server/api/handlers_test.go	2014-11-25 18:40:27 +0000
@@ -362,7 +362,7 @@
 	}
 	sto := store.NewInMemoryPendingStore()
 	bsend := &checkBrokerSending{store: sto}
-	ctx := &context{testStoreAccess(nil), bsend, nil}
+	ctx := &context{testStoreAccess(nil), bsend, s.testlog}
 	payload := json.RawMessage(`{"a": 1}`)
 	res, apiErr := doUnicast(ctx, sto, &Unicast{
 		UserId:   "user1",
@@ -487,7 +487,7 @@
 	sto.AppendToUnicastChannel(chanId, "app1", n, "m4", expire)
 
 	bsend := &checkBrokerSending{store: sto}
-	ctx := &context{testStoreAccess(nil), bsend, nil}
+	ctx := &context{testStoreAccess(nil), bsend, s.testlog}
 	payload := json.RawMessage(`{"a": 1}`)
 	res, apiErr := doUnicast(ctx, sto, &Unicast{
 		UserId:   "user1",
@@ -528,7 +528,7 @@
 	sto.AppendToUnicastChannel(chanId, "app1", n, "m1", expire)
 
 	bsend := &checkBrokerSending{store: sto}
-	ctx := &context{testStoreAccess(nil), bsend, nil}
+	ctx := &context{testStoreAccess(nil), bsend, s.testlog}
 	payload := json.RawMessage(`{"a": 1}`)
 	res, apiErr := doUnicast(ctx, sto, &Unicast{
 		UserId:     "user1",
@@ -634,7 +634,7 @@
 	sto.AppendToUnicastChannel(chanId, "app1", n, "m4", expire)
 
 	bsend := &checkBrokerSending{store: sto}
-	ctx := &context{testStoreAccess(nil), bsend, nil}
+	ctx := &context{testStoreAccess(nil), bsend, s.testlog}
 	payload := json.RawMessage(`{"a": 1}`)
 	res, apiErr := doUnicast(ctx, sto, &Unicast{
 		UserId:       "user1",
@@ -933,6 +933,22 @@
 	checkError(c, response, ErrWrongContentType)
 }
 
+func (s *handlersSuite) TestContentTypeWithCharset(c *C) {
+	testServer := httptest.NewServer(&JSONPostHandler{})
+	defer testServer.Close()
+
+	dataString := `{"foo":"bar"}`
+
+	request := newPostRequest("/", &Broadcast{
+		Channel:  "some-channel",
+		ExpireOn: future,
+		Data:     json.RawMessage([]byte(dataString)),
+	}, testServer)
+	request.Header.Set("Content-Type", "application/json; charset=UTF-8")
+	result := checkRequestAsPost(request, 1024)
+	c.Assert(result, IsNil)
+}
+
 func (s *handlersSuite) TestCannotBroadcastNonPostMessages(c *C) {
 	testServer := httptest.NewServer(&JSONPostHandler{})
 	defer testServer.Close()
@@ -965,7 +981,7 @@
 		return sto, nil
 	})
 	bsend := testBrokerSending{make(chan store.InternalChannelId, 1)}
-	testServer := httptest.NewServer(MakeHandlersMux(storage, bsend, nil))
+	testServer := httptest.NewServer(MakeHandlersMux(storage, bsend, s.testlog))
 	defer testServer.Close()
 
 	payload := json.RawMessage(`{"foo":"bar"}`)
@@ -1049,7 +1065,7 @@
 		return sto, nil
 	})
 	bsend := testBrokerSending{make(chan store.InternalChannelId, 1)}
-	testServer := httptest.NewServer(MakeHandlersMux(storage, bsend, nil))
+	testServer := httptest.NewServer(MakeHandlersMux(storage, bsend, s.testlog))
 	defer testServer.Close()
 
 	request := newPostRequest("/register", &Registration{
 
=== modified file 'server/broker/testsuite/suite.go'
--- server/broker/testsuite/suite.go	2014-09-25 11:16:38 +0000
+++ server/broker/testsuite/suite.go	2014-11-25 18:40:27 +0000
@@ -66,12 +66,12 @@
 
 func (s *CommonBrokerSuite) TestSanity(c *C) {
 	sto := store.NewInMemoryPendingStore()
-	b := s.MakeBroker(sto, testBrokerConfig, nil)
+	b := s.MakeBroker(sto, testBrokerConfig, s.testlog)
 	c.Check(s.RevealSession(b, "FOO"), IsNil)
 }
 
 func (s *CommonBrokerSuite) TestStartStop(c *C) {
-	b := s.MakeBroker(nil, testBrokerConfig, nil)
+	b := s.MakeBroker(nil, testBrokerConfig, s.testlog)
 	b.Start()
 	c.Check(b.Running(), Equals, true)
 	b.Start()
@@ -82,7 +82,7 @@
 
 func (s *CommonBrokerSuite) TestRegistration(c *C) {
 	sto := store.NewInMemoryPendingStore()
-	b := s.MakeBroker(sto, testBrokerConfig, nil)
+	b := s.MakeBroker(sto, testBrokerConfig, s.testlog)
 	b.Start()
 	defer b.Stop()
 	sess, err := b.Register(&protocol.ConnectMsg{
@@ -112,7 +112,7 @@
 
 func (s *CommonBrokerSuite) TestRegistrationBrokenLevels(c *C) {
 	sto := store.NewInMemoryPendingStore()
-	b := s.MakeBroker(sto, testBrokerConfig, nil)
+	b := s.MakeBroker(sto, testBrokerConfig, s.testlog)
 	b.Start()
 	defer b.Stop()
 	_, err := b.Register(&protocol.ConnectMsg{Type: "connect", DeviceId: "dev-1", Levels: map[string]int64{"z": 5}}, s.MakeTracker("s1"))
@@ -121,7 +121,7 @@
 
 func (s *CommonBrokerSuite) TestRegistrationInfoErrors(c *C) {
 	sto := store.NewInMemoryPendingStore()
-	b := s.MakeBroker(sto, testBrokerConfig, nil)
+	b := s.MakeBroker(sto, testBrokerConfig, s.testlog)
 	b.Start()
 	defer b.Stop()
 	info := map[string]interface{}{
@@ -140,7 +140,7 @@
 	notification1 := json.RawMessage(`{"m": "M"}`)
 	muchLater := time.Now().Add(10 * time.Minute)
 	sto.AppendToChannel(store.SystemInternalChannelId, notification1, muchLater)
-	b := s.MakeBroker(sto, testBrokerConfig, nil)
+	b := s.MakeBroker(sto, testBrokerConfig, s.testlog)
 	b.Start()
 	defer b.Stop()
 	sess, err := b.Register(&protocol.ConnectMsg{Type: "connect", DeviceId: "dev-1"}, s.MakeTracker("s1"))
@@ -166,7 +166,7 @@
 
 func (s *CommonBrokerSuite) TestRegistrationLastWins(c *C) {
 	sto := store.NewInMemoryPendingStore()
-	b := s.MakeBroker(sto, testBrokerConfig, nil)
+	b := s.MakeBroker(sto, testBrokerConfig, s.testlog)
 	b.Start()
 	defer b.Stop()
 	sess1, err := b.Register(&protocol.ConnectMsg{Type: "connect", DeviceId: "dev-1"}, s.MakeTracker("s1"))
@@ -197,7 +197,7 @@
 	sto := store.NewInMemoryPendingStore()
 	notification1 := json.RawMessage(`{"m": "M"}`)
 	decoded1 := map[string]interface{}{"m": "M"}
-	b := s.MakeBroker(sto, testBrokerConfig, nil)
+	b := s.MakeBroker(sto, testBrokerConfig, s.testlog)
 	b.Start()
 	defer b.Stop()
 	sess1, err := b.Register(&protocol.ConnectMsg{Type: "connect", DeviceId: "dev-1"}, s.MakeTracker("s1"))
@@ -278,7 +278,7 @@
 	notification2 := json.RawMessage(`{"m": "M2"}`)
 	chanId1 := store.UnicastInternalChannelId("dev1", "dev1")
 	chanId2 := store.UnicastInternalChannelId("dev2", "dev2")
-	b := s.MakeBroker(sto, testBrokerConfig, nil)
+	b := s.MakeBroker(sto, testBrokerConfig, s.testlog)
 	b.Start()
 	defer b.Stop()
 	sess1, err := b.Register(&protocol.ConnectMsg{Type: "connect", DeviceId: "dev1"}, s.MakeTracker("s1"))
@@ -312,7 +312,7 @@
 	sto := store.NewInMemoryPendingStore()
 	notification1 := json.RawMessage(`{"m": "M1"}`)
 	chanId1 := store.UnicastInternalChannelId("dev3", "dev3")
-	b := s.MakeBroker(sto, testBrokerConfig, nil)
+	b := s.MakeBroker(sto, testBrokerConfig, s.testlog)
 	b.Start()
 	defer b.Stop()
 	sess1, err := b.Register(&protocol.ConnectMsg{Type: "connect", DeviceId: "dev3"}, s.MakeTracker("s1"))
@@ -354,7 +354,7 @@
 
 func (s *CommonBrokerSuite) TestSessionFeed(c *C) {
 	sto := store.NewInMemoryPendingStore()
-	b := s.MakeBroker(sto, testBrokerConfig, nil)
+	b := s.MakeBroker(sto, testBrokerConfig, s.testlog)
 	b.Start()
 	defer b.Stop()
 	sess1, err := b.Register(&protocol.ConnectMsg{Type: "connect", DeviceId: "dev3"}, s.MakeTracker("s1"))
 
=== modified file 'server/listener/listener_test.go'
--- server/listener/listener_test.go	2014-09-25 11:20:00 +0000
+++ server/listener/listener_test.go	2014-11-25 18:40:27 +0000
@@ -18,6 +18,7 @@
 
 import (
 	"crypto/tls"
+	"io"
 	"net"
 	"os/exec"
 	"regexp"
@@ -112,7 +113,7 @@
 	conn.SetDeadline(time.Now().Add(10 * time.Second))
 	var buf [1]byte
 	for {
-		_, err := conn.Read(buf[:])
+		_, err := io.ReadFull(conn, buf[:])
 		if err != nil {
 			return err
 		}
@@ -137,7 +138,7 @@
 
 func testReadByte(c *C, conn net.Conn, expected uint32) {
 	var buf [1]byte
-	_, err := conn.Read(buf[:])
+	_, err := io.ReadFull(conn, buf[:])
 	c.Check(err, IsNil)
 	c.Check(buf[0], Equals, byte(expected))
 }