Merge lp:~rogpeppe/juju-core/313-jsoncodec-optional-log into lp:~juju/juju-core/trunk

[Roger Peppe]

rpc/jsoncodec: optional logging

Because we're now using the same codec on
both client and server, we were seeing each message
logged twice when testing. This changes
things so we only log on the server side.

https://codereview.appspot.com/9692044/

[Roger Peppe (rogpeppe)]

Reviewers: mp+165736_code.launchpad.net,

Message:
Please take a look.

Description:
rpc/jsoncodec: optional logging

Because we're now using the same codec on
both client and server, we were seeing each message
logged twice when testing. This changes
things so we only log on the server side.

https://code.launchpad.net/~rogpeppe/juju-core/313-jsoncodec-optional-log/+merge/165736

Requires:
https://code.launchpad.net/~rogpeppe/juju-core/312-api-jobs/+merge/165705

(do not edit description out of merge proposal)

Please review this at https://codereview.appspot.com/9692044/

Affected files:
   A [revision details]
   M rpc/jsoncodec/codec.go
   M rpc/jsoncodec/codec_test.go
   M rpc/jsoncodec/conn.go
   M state/apiserver/apiserver.go

[Roger Peppe (rogpeppe)]

Please take a look.

https://codereview.appspot.com/9692044/

[William Reade (fwereade)]

NOT LGTM I'm afraid.

https://codereview.appspot.com/9692044/diff/5002/rpc/jsoncodec/codec.go
File rpc/jsoncodec/codec.go (right):

https://codereview.appspot.com/9692044/diff/5002/rpc/jsoncodec/codec.go#newcode44
rpc/jsoncodec/codec.go:44: // called before the codec is used for
serving RPC requests.
This is a timebomb that will explode as soon as we have dynamic logging
levels, and someone notices that the API server doesn't respect them. If
you're going to implement this, please do it properly...

https://codereview.appspot.com/9692044/

[Roger Peppe (rogpeppe)]

Please take a look.

https://codereview.appspot.com/9692044/diff/5002/rpc/jsoncodec/codec.go
File rpc/jsoncodec/codec.go (right):

https://codereview.appspot.com/9692044/diff/5002/rpc/jsoncodec/codec.go#newcode44
rpc/jsoncodec/codec.go:44: // called before the codec is used for
serving RPC requests.
On 2013/05/27 20:29:44, fwereade wrote:
> This is a timebomb that will explode as soon as we have dynamic
logging levels,
> and someone notices that the API server doesn't respect them. If
you're going to
> implement this, please do it properly...

Done.

https://codereview.appspot.com/9692044/

[William Reade (fwereade)]

LGTM, thanks.

https://codereview.appspot.com/9692044/

[Ian Booth (wallyworld)]

LGTM

https://codereview.appspot.com/9692044/

[Roger Peppe (rogpeppe)]

On 2013/06/21 01:28:02, wallyworld wrote:
> LGTM

merged as https://codereview.appspot.com/10410046/

https://codereview.appspot.com/9692044/

Unmerged revisions

1243. By Roger Peppe on 2013-06-07

rpc/jsoncodec: s/LogMessages/SetLogging/

1242. By Roger Peppe on 2013-06-07

Merged 312-api-jobs into 313-jsoncodec-optional-log.

1241. By Roger Peppe on 2013-06-07

Merged 312-api-jobs into 313-jsoncodec-optional-log.

1240. By Roger Peppe on 2013-05-25

rpc/jsoncodec: remove unnecessary logic in test code

1239. By Roger Peppe on 2013-05-25

rpc/jsoncodec: make log messaging configurable

1238. By Roger Peppe on 2013-05-24

api: implement Machine.Jobs

1237. By Roger Peppe on 2013-05-24

merge trunk

1236. By Roger Peppe on 2013-05-24

cmd/juju: revert bogus change

1235. By Roger Peppe on 2013-05-24

cmd/jujud: change password for machine agent

1234. By Roger Peppe on 2013-05-24

gofmt

=== modified file 'rpc/jsoncodec/codec.go'
--- rpc/jsoncodec/codec.go	2013-05-28 07:01:54 +0000
+++ rpc/jsoncodec/codec.go	2013-06-07 17:45:32 +0000
@@ -8,6 +8,7 @@
 	"launchpad.net/juju-core/log"
 	"launchpad.net/juju-core/rpc"
 	"sync"
+	"sync/atomic"
 )
 
 // JSONConn sends and receives messages to an underlying connection
@@ -20,26 +21,39 @@
 	Close() error
 }
 
-var logRequests = true
-
-// codec implements rpc.Codec for a connection.
-type codec struct {
+// Codec implements rpc.Codec for a connection.
+type Codec struct {
 	// msg holds the message that's just been read by ReadHeader, so
 	// that the body can be read by ReadBody.
-	msg     inMsg
-	conn    JSONConn
-	mu      sync.Mutex
-	closing bool
+	msg         inMsg
+	conn        JSONConn
+	logMessages int32
+	mu          sync.Mutex
+	closing     bool
 }
 
 // New returns an rpc codec that uses conn to send and receive
 // messages.
-func New(conn JSONConn) rpc.Codec {
-	return &codec{
+func New(conn JSONConn) *Codec {
+	return &Codec{
 		conn: conn,
 	}
 }
 
+// SetLogging sets whether messages will be logged
+// by the codec.
+func (c *Codec) SetLogging(on bool) {
+	val := int32(0)
+	if on {
+		val = 1
+	}
+	atomic.StoreInt32(&c.logMessages, val)
+}
+
+func (c *Codec) isLogging() bool {
+	return atomic.LoadInt32(&c.logMessages) != 0
+}
+
 // inMsg holds an incoming message.  We don't know the type of the
 // parameters or response yet, so we delay parsing by storing them
 // in a RawMessage.
@@ -66,23 +80,23 @@
 	Response  interface{} `json:",omitempty"`
 }
 
-func (c *codec) Close() error {
+func (c *Codec) Close() error {
 	c.mu.Lock()
 	c.closing = true
 	c.mu.Unlock()
 	return c.conn.Close()
 }
 
-func (c *codec) isClosing() bool {
+func (c *Codec) isClosing() bool {
 	c.mu.Lock()
 	defer c.mu.Unlock()
 	return c.closing
 }
 
-func (c *codec) ReadHeader(hdr *rpc.Header) error {
+func (c *Codec) ReadHeader(hdr *rpc.Header) error {
 	c.msg = inMsg{} // avoid any potential cross-message contamination.
 	var err error
-	if logRequests {
+	if c.isLogging() {
 		var m json.RawMessage
 		err = c.conn.Receive(&m)
 		if err == nil {
@@ -111,7 +125,7 @@
 	return nil
 }
 
-func (c *codec) ReadBody(body interface{}, isRequest bool) error {
+func (c *Codec) ReadBody(body interface{}, isRequest bool) error {
 	if body == nil {
 		return nil
 	}
@@ -129,7 +143,7 @@
 	return json.Unmarshal(rawBody, body)
 }
 
-func (c *codec) WriteMessage(hdr *rpc.Header, body interface{}) error {
+func (c *Codec) WriteMessage(hdr *rpc.Header, body interface{}) error {
 	r := &outMsg{
 		RequestId: hdr.RequestId,
 
@@ -145,7 +159,7 @@
 	} else {
 		r.Response = body
 	}
-	if logRequests {
+	if c.isLogging() {
 		data, err := json.Marshal(r)
 		if err != nil {
 			log.Debugf("rpc/jsoncodec: -> marshal error: %v", err)

=== modified file 'rpc/jsoncodec/codec_test.go'
--- rpc/jsoncodec/codec_test.go	2013-05-15 12:34:10 +0000
+++ rpc/jsoncodec/codec_test.go	2013-06-07 17:45:32 +0000
@@ -7,15 +7,19 @@
 	. "launchpad.net/gocheck"
 	"launchpad.net/juju-core/rpc"
 	"launchpad.net/juju-core/rpc/jsoncodec"
+	"launchpad.net/juju-core/testing"
 	"reflect"
-	"testing"
+	"regexp"
+	stdtesting "testing"
 )
 
-type suite struct{}
-
-var _ = Suite(suite{})
-
-func TestPackage(t *testing.T) {
+type suite struct {
+	testing.LoggingSuite
+}
+
+var _ = Suite(&suite{})
+
+func TestPackage(t *stdtesting.T) {
 	TestingT(t)
 }
 
@@ -52,7 +56,7 @@
 	expectBody: &value{X: "result"},
 }}
 
-func (suite) TestRead(c *C) {
+func (*suite) TestRead(c *C) {
 	for i, test := range readTests {
 		c.Logf("test %d", i)
 		codec := jsoncodec.New(&testConn{
@@ -75,7 +79,97 @@
 	}
 }
 
-func (suite) TestErrorAfterClose(c *C) {
+func (*suite) TestReadHeaderLogsRequests(c *C) {
+	msg := `{"RequestId":1,"Type": "foo","Id": "id","Request":"frob","Params":{"X":"param"}}`
+	codec := jsoncodec.New(&testConn{
+		readMsgs: []string{msg, msg, msg},
+	})
+	// Check that logging is off by default
+	var h rpc.Header
+	err := codec.ReadHeader(&h)
+	c.Assert(err, IsNil)
+	c.Assert(c.GetTestLog(), Matches, "")
+
+	// Check that we see a log message when we switch logging on.
+	codec.SetLogging(true)
+	err = codec.ReadHeader(&h)
+	c.Assert(err, IsNil)
+	c.Assert(c.GetTestLog(), Matches, ".*DEBUG rpc/jsoncodec: <- "+regexp.QuoteMeta(msg)+`\n`)
+
+	// Check that we can switch it off again
+	codec.SetLogging(false)
+	err = codec.ReadHeader(&h)
+	c.Assert(err, IsNil)
+	c.Assert(c.GetTestLog(), Matches, ".*DEBUG rpc/jsoncodec: <- "+regexp.QuoteMeta(msg)+`\n`)
+}
+
+func (*suite) TestWriteMessageLogsRequests(c *C) {
+	codec := jsoncodec.New(&testConn{})
+	h := rpc.Header{
+		RequestId: 1,
+		Type:      "foo",
+		Id:        "id",
+		Request:   "frob",
+	}
+
+	// Check that logging is off by default
+	err := codec.WriteMessage(&h, value{X: "param"})
+	c.Assert(err, IsNil)
+	c.Assert(c.GetTestLog(), Matches, "")
+
+	// Check that we see a log message when we switch logging on.
+	codec.SetLogging(true)
+	err = codec.WriteMessage(&h, value{X: "param"})
+	c.Assert(err, IsNil)
+	msg := `{"RequestId":1,"Type":"foo","Id":"id","Request":"frob","Params":{"X":"param"}}`
+	c.Assert(c.GetTestLog(), Matches, `.*DEBUG rpc/jsoncodec: -> `+regexp.QuoteMeta(msg)+`\n`)
+
+	// Check that we can switch it off again
+	codec.SetLogging(false)
+	err = codec.WriteMessage(&h, value{X: "param"})
+	c.Assert(err, IsNil)
+	c.Assert(c.GetTestLog(), Matches, `.*DEBUG rpc/jsoncodec: -> `+regexp.QuoteMeta(msg)+`\n`)
+}
+
+func (*suite) TestConcurrentSetLoggingAndWrite(c *C) {
+	// If log messages are not set atomically, this
+	// test will fail when run under the race detector.
+	codec := jsoncodec.New(&testConn{})
+	done := make(chan struct{})
+	go func() {
+		codec.SetLogging(true)
+		done <- struct{}{}
+	}()
+	h := rpc.Header{
+		RequestId: 1,
+		Type:      "foo",
+		Id:        "id",
+		Request:   "frob",
+	}
+	err := codec.WriteMessage(&h, value{X: "param"})
+	c.Assert(err, IsNil)
+	<-done
+}
+
+func (*suite) TestConcurrentSetLoggingAndRead(c *C) {
+	// If log messages are not set atomically, this
+	// test will fail when run under the race detector.
+	msg := `{"RequestId":1,"Type": "foo","Id": "id","Request":"frob","Params":{"X":"param"}}`
+	codec := jsoncodec.New(&testConn{
+		readMsgs: []string{msg, msg, msg},
+	})
+	done := make(chan struct{})
+	go func() {
+		codec.SetLogging(true)
+		done <- struct{}{}
+	}()
+	var h rpc.Header
+	err := codec.ReadHeader(&h)
+	c.Assert(err, IsNil)
+	<-done
+}
+
+func (*suite) TestErrorAfterClose(c *C) {
 	conn := &testConn{
 		err: errors.New("some error"),
 	}
@@ -105,7 +199,7 @@
 		Request:   "frob",
 	},
 	body:   &value{X: "param"},
-	expect: `{"RequestId": 1, "Type": "foo", "Id": "id", "Request": "frob", "Params": {"X": "param"}}`,
+	expect: `{"RequestId": 1, "Type": "foo","Id":"id", "Request": "frob", "Params": {"X": "param"}}`,
 }, {
 	hdr: &rpc.Header{
 		RequestId: 2,
@@ -121,7 +215,7 @@
 	expect: `{"RequestId": 3, "Response": {"X": "result"}}`,
 }}
 
-func (suite) TestWrite(c *C) {
+func (*suite) TestWrite(c *C) {
 	for i, test := range writeTests {
 		c.Logf("test %d", i)
 		var conn testConn

=== modified file 'rpc/jsoncodec/conn.go'
--- rpc/jsoncodec/conn.go	2013-05-16 17:31:36 +0000
+++ rpc/jsoncodec/conn.go	2013-06-07 17:45:32 +0000
@@ -3,13 +3,12 @@
 import (
 	"code.google.com/p/go.net/websocket"
 	"encoding/json"
-	"launchpad.net/juju-core/rpc"
 	"net"
 )
 
 // NewWebsocket returns an rpc codec that uses the given websocket
 // connection to send and receive messages.
-func NewWebsocket(conn *websocket.Conn) rpc.Codec {
+func NewWebsocket(conn *websocket.Conn) *Codec {
 	return New(wsJSONConn{conn})
 }
 
@@ -31,7 +30,7 @@
 
 // NewNet returns an rpc codec that uses the given net
 // connection to send and receive messages.
-func NewNet(conn net.Conn) rpc.Codec {
+func NewNet(conn net.Conn) *Codec {
 	return New(&netConn{
 		enc:  json.NewEncoder(conn),
 		dec:  json.NewDecoder(conn),

=== modified file 'state/apiserver/apiserver.go'
--- state/apiserver/apiserver.go	2013-06-06 17:09:49 +0000
+++ state/apiserver/apiserver.go	2013-06-07 17:45:32 +0000
@@ -96,6 +96,7 @@
 }
 
 func (srv *Server) serveConn(wsConn *websocket.Conn) error {
+<<<<<<< TREE
 	conn := rpc.NewConn(jsoncodec.NewWebsocket(wsConn))
 	serverError := func(err error) error {
 		if err := common.ServerError(err); err != nil {
@@ -103,6 +104,13 @@
 		}
 		return nil
 	}
+=======
+	codec := jsoncodec.NewWebsocket(wsConn)
+	if log.Debug {
+		codec.SetLogging(true)
+	}
+	conn := rpc.NewConn(codec)
+>>>>>>> MERGE-SOURCE
 	if err := conn.Serve(newStateServer(srv), serverError); err != nil {
 		return err
 	}