THRIFT-4985: Refactor logging in Go library
- Add a new Logger type to make logging configurable
- Use the new logger in TSimpleServer and TDebugProtocol
- Remove pointless log in TZlibTransport
- Remove panic recovery from TSimpleServer. Thrift shouldn't catch panics caused by caller-defined RPC handlers.
Client: go
This closes #1906.
diff --git a/lib/go/thrift/debug_protocol.go b/lib/go/thrift/debug_protocol.go
index 57943e0..c33fba8 100644
--- a/lib/go/thrift/debug_protocol.go
+++ b/lib/go/thrift/debug_protocol.go
@@ -21,23 +21,40 @@
import (
"context"
- "log"
+ "fmt"
)
type TDebugProtocol struct {
Delegate TProtocol
LogPrefix string
+ Logger Logger
}
type TDebugProtocolFactory struct {
Underlying TProtocolFactory
LogPrefix string
+ Logger Logger
}
+// NewTDebugProtocolFactory creates a TDebugProtocolFactory.
+//
+// Deprecated: Please use NewTDebugProtocolFactoryWithLogger or the struct
+// itself instead. This version will use the default logger from standard
+// library.
func NewTDebugProtocolFactory(underlying TProtocolFactory, logPrefix string) *TDebugProtocolFactory {
return &TDebugProtocolFactory{
Underlying: underlying,
LogPrefix: logPrefix,
+ Logger: StdLogger(nil),
+ }
+}
+
+// NewTDebugProtocolFactoryWithLogger creates a TDebugProtocolFactory.
+func NewTDebugProtocolFactoryWithLogger(underlying TProtocolFactory, logPrefix string, logger Logger) *TDebugProtocolFactory {
+ return &TDebugProtocolFactory{
+ Underlying: underlying,
+ LogPrefix: logPrefix,
+ Logger: logger,
}
}
@@ -45,223 +62,228 @@
return &TDebugProtocol{
Delegate: t.Underlying.GetProtocol(trans),
LogPrefix: t.LogPrefix,
+ Logger: fallbackLogger(t.Logger),
}
}
+func (tdp *TDebugProtocol) logf(format string, v ...interface{}) {
+ fallbackLogger(tdp.Logger)(fmt.Sprintf(format, v...))
+}
+
func (tdp *TDebugProtocol) WriteMessageBegin(name string, typeId TMessageType, seqid int32) error {
err := tdp.Delegate.WriteMessageBegin(name, typeId, seqid)
- log.Printf("%sWriteMessageBegin(name=%#v, typeId=%#v, seqid=%#v) => %#v", tdp.LogPrefix, name, typeId, seqid, err)
+ tdp.logf("%sWriteMessageBegin(name=%#v, typeId=%#v, seqid=%#v) => %#v", tdp.LogPrefix, name, typeId, seqid, err)
return err
}
func (tdp *TDebugProtocol) WriteMessageEnd() error {
err := tdp.Delegate.WriteMessageEnd()
- log.Printf("%sWriteMessageEnd() => %#v", tdp.LogPrefix, err)
+ tdp.logf("%sWriteMessageEnd() => %#v", tdp.LogPrefix, err)
return err
}
func (tdp *TDebugProtocol) WriteStructBegin(name string) error {
err := tdp.Delegate.WriteStructBegin(name)
- log.Printf("%sWriteStructBegin(name=%#v) => %#v", tdp.LogPrefix, name, err)
+ tdp.logf("%sWriteStructBegin(name=%#v) => %#v", tdp.LogPrefix, name, err)
return err
}
func (tdp *TDebugProtocol) WriteStructEnd() error {
err := tdp.Delegate.WriteStructEnd()
- log.Printf("%sWriteStructEnd() => %#v", tdp.LogPrefix, err)
+ tdp.logf("%sWriteStructEnd() => %#v", tdp.LogPrefix, err)
return err
}
func (tdp *TDebugProtocol) WriteFieldBegin(name string, typeId TType, id int16) error {
err := tdp.Delegate.WriteFieldBegin(name, typeId, id)
- log.Printf("%sWriteFieldBegin(name=%#v, typeId=%#v, id%#v) => %#v", tdp.LogPrefix, name, typeId, id, err)
+ tdp.logf("%sWriteFieldBegin(name=%#v, typeId=%#v, id%#v) => %#v", tdp.LogPrefix, name, typeId, id, err)
return err
}
func (tdp *TDebugProtocol) WriteFieldEnd() error {
err := tdp.Delegate.WriteFieldEnd()
- log.Printf("%sWriteFieldEnd() => %#v", tdp.LogPrefix, err)
+ tdp.logf("%sWriteFieldEnd() => %#v", tdp.LogPrefix, err)
return err
}
func (tdp *TDebugProtocol) WriteFieldStop() error {
err := tdp.Delegate.WriteFieldStop()
- log.Printf("%sWriteFieldStop() => %#v", tdp.LogPrefix, err)
+ tdp.logf("%sWriteFieldStop() => %#v", tdp.LogPrefix, err)
return err
}
func (tdp *TDebugProtocol) WriteMapBegin(keyType TType, valueType TType, size int) error {
err := tdp.Delegate.WriteMapBegin(keyType, valueType, size)
- log.Printf("%sWriteMapBegin(keyType=%#v, valueType=%#v, size=%#v) => %#v", tdp.LogPrefix, keyType, valueType, size, err)
+ tdp.logf("%sWriteMapBegin(keyType=%#v, valueType=%#v, size=%#v) => %#v", tdp.LogPrefix, keyType, valueType, size, err)
return err
}
func (tdp *TDebugProtocol) WriteMapEnd() error {
err := tdp.Delegate.WriteMapEnd()
- log.Printf("%sWriteMapEnd() => %#v", tdp.LogPrefix, err)
+ tdp.logf("%sWriteMapEnd() => %#v", tdp.LogPrefix, err)
return err
}
func (tdp *TDebugProtocol) WriteListBegin(elemType TType, size int) error {
err := tdp.Delegate.WriteListBegin(elemType, size)
- log.Printf("%sWriteListBegin(elemType=%#v, size=%#v) => %#v", tdp.LogPrefix, elemType, size, err)
+ tdp.logf("%sWriteListBegin(elemType=%#v, size=%#v) => %#v", tdp.LogPrefix, elemType, size, err)
return err
}
func (tdp *TDebugProtocol) WriteListEnd() error {
err := tdp.Delegate.WriteListEnd()
- log.Printf("%sWriteListEnd() => %#v", tdp.LogPrefix, err)
+ tdp.logf("%sWriteListEnd() => %#v", tdp.LogPrefix, err)
return err
}
func (tdp *TDebugProtocol) WriteSetBegin(elemType TType, size int) error {
err := tdp.Delegate.WriteSetBegin(elemType, size)
- log.Printf("%sWriteSetBegin(elemType=%#v, size=%#v) => %#v", tdp.LogPrefix, elemType, size, err)
+ tdp.logf("%sWriteSetBegin(elemType=%#v, size=%#v) => %#v", tdp.LogPrefix, elemType, size, err)
return err
}
func (tdp *TDebugProtocol) WriteSetEnd() error {
err := tdp.Delegate.WriteSetEnd()
- log.Printf("%sWriteSetEnd() => %#v", tdp.LogPrefix, err)
+ tdp.logf("%sWriteSetEnd() => %#v", tdp.LogPrefix, err)
return err
}
func (tdp *TDebugProtocol) WriteBool(value bool) error {
err := tdp.Delegate.WriteBool(value)
- log.Printf("%sWriteBool(value=%#v) => %#v", tdp.LogPrefix, value, err)
+ tdp.logf("%sWriteBool(value=%#v) => %#v", tdp.LogPrefix, value, err)
return err
}
func (tdp *TDebugProtocol) WriteByte(value int8) error {
err := tdp.Delegate.WriteByte(value)
- log.Printf("%sWriteByte(value=%#v) => %#v", tdp.LogPrefix, value, err)
+ tdp.logf("%sWriteByte(value=%#v) => %#v", tdp.LogPrefix, value, err)
return err
}
func (tdp *TDebugProtocol) WriteI16(value int16) error {
err := tdp.Delegate.WriteI16(value)
- log.Printf("%sWriteI16(value=%#v) => %#v", tdp.LogPrefix, value, err)
+ tdp.logf("%sWriteI16(value=%#v) => %#v", tdp.LogPrefix, value, err)
return err
}
func (tdp *TDebugProtocol) WriteI32(value int32) error {
err := tdp.Delegate.WriteI32(value)
- log.Printf("%sWriteI32(value=%#v) => %#v", tdp.LogPrefix, value, err)
+ tdp.logf("%sWriteI32(value=%#v) => %#v", tdp.LogPrefix, value, err)
return err
}
func (tdp *TDebugProtocol) WriteI64(value int64) error {
err := tdp.Delegate.WriteI64(value)
- log.Printf("%sWriteI64(value=%#v) => %#v", tdp.LogPrefix, value, err)
+ tdp.logf("%sWriteI64(value=%#v) => %#v", tdp.LogPrefix, value, err)
return err
}
func (tdp *TDebugProtocol) WriteDouble(value float64) error {
err := tdp.Delegate.WriteDouble(value)
- log.Printf("%sWriteDouble(value=%#v) => %#v", tdp.LogPrefix, value, err)
+ tdp.logf("%sWriteDouble(value=%#v) => %#v", tdp.LogPrefix, value, err)
return err
}
func (tdp *TDebugProtocol) WriteString(value string) error {
err := tdp.Delegate.WriteString(value)
- log.Printf("%sWriteString(value=%#v) => %#v", tdp.LogPrefix, value, err)
+ tdp.logf("%sWriteString(value=%#v) => %#v", tdp.LogPrefix, value, err)
return err
}
func (tdp *TDebugProtocol) WriteBinary(value []byte) error {
err := tdp.Delegate.WriteBinary(value)
- log.Printf("%sWriteBinary(value=%#v) => %#v", tdp.LogPrefix, value, err)
+ tdp.logf("%sWriteBinary(value=%#v) => %#v", tdp.LogPrefix, value, err)
return err
}
func (tdp *TDebugProtocol) ReadMessageBegin() (name string, typeId TMessageType, seqid int32, err error) {
name, typeId, seqid, err = tdp.Delegate.ReadMessageBegin()
- log.Printf("%sReadMessageBegin() (name=%#v, typeId=%#v, seqid=%#v, err=%#v)", tdp.LogPrefix, name, typeId, seqid, err)
+ tdp.logf("%sReadMessageBegin() (name=%#v, typeId=%#v, seqid=%#v, err=%#v)", tdp.LogPrefix, name, typeId, seqid, err)
return
}
func (tdp *TDebugProtocol) ReadMessageEnd() (err error) {
err = tdp.Delegate.ReadMessageEnd()
- log.Printf("%sReadMessageEnd() err=%#v", tdp.LogPrefix, err)
+ tdp.logf("%sReadMessageEnd() err=%#v", tdp.LogPrefix, err)
return
}
func (tdp *TDebugProtocol) ReadStructBegin() (name string, err error) {
name, err = tdp.Delegate.ReadStructBegin()
- log.Printf("%sReadStructBegin() (name%#v, err=%#v)", tdp.LogPrefix, name, err)
+ tdp.logf("%sReadStructBegin() (name%#v, err=%#v)", tdp.LogPrefix, name, err)
return
}
func (tdp *TDebugProtocol) ReadStructEnd() (err error) {
err = tdp.Delegate.ReadStructEnd()
- log.Printf("%sReadStructEnd() err=%#v", tdp.LogPrefix, err)
+ tdp.logf("%sReadStructEnd() err=%#v", tdp.LogPrefix, err)
return
}
func (tdp *TDebugProtocol) ReadFieldBegin() (name string, typeId TType, id int16, err error) {
name, typeId, id, err = tdp.Delegate.ReadFieldBegin()
- log.Printf("%sReadFieldBegin() (name=%#v, typeId=%#v, id=%#v, err=%#v)", tdp.LogPrefix, name, typeId, id, err)
+ tdp.logf("%sReadFieldBegin() (name=%#v, typeId=%#v, id=%#v, err=%#v)", tdp.LogPrefix, name, typeId, id, err)
return
}
func (tdp *TDebugProtocol) ReadFieldEnd() (err error) {
err = tdp.Delegate.ReadFieldEnd()
- log.Printf("%sReadFieldEnd() err=%#v", tdp.LogPrefix, err)
+ tdp.logf("%sReadFieldEnd() err=%#v", tdp.LogPrefix, err)
return
}
func (tdp *TDebugProtocol) ReadMapBegin() (keyType TType, valueType TType, size int, err error) {
keyType, valueType, size, err = tdp.Delegate.ReadMapBegin()
- log.Printf("%sReadMapBegin() (keyType=%#v, valueType=%#v, size=%#v, err=%#v)", tdp.LogPrefix, keyType, valueType, size, err)
+ tdp.logf("%sReadMapBegin() (keyType=%#v, valueType=%#v, size=%#v, err=%#v)", tdp.LogPrefix, keyType, valueType, size, err)
return
}
func (tdp *TDebugProtocol) ReadMapEnd() (err error) {
err = tdp.Delegate.ReadMapEnd()
- log.Printf("%sReadMapEnd() err=%#v", tdp.LogPrefix, err)
+ tdp.logf("%sReadMapEnd() err=%#v", tdp.LogPrefix, err)
return
}
func (tdp *TDebugProtocol) ReadListBegin() (elemType TType, size int, err error) {
elemType, size, err = tdp.Delegate.ReadListBegin()
- log.Printf("%sReadListBegin() (elemType=%#v, size=%#v, err=%#v)", tdp.LogPrefix, elemType, size, err)
+ tdp.logf("%sReadListBegin() (elemType=%#v, size=%#v, err=%#v)", tdp.LogPrefix, elemType, size, err)
return
}
func (tdp *TDebugProtocol) ReadListEnd() (err error) {
err = tdp.Delegate.ReadListEnd()
- log.Printf("%sReadListEnd() err=%#v", tdp.LogPrefix, err)
+ tdp.logf("%sReadListEnd() err=%#v", tdp.LogPrefix, err)
return
}
func (tdp *TDebugProtocol) ReadSetBegin() (elemType TType, size int, err error) {
elemType, size, err = tdp.Delegate.ReadSetBegin()
- log.Printf("%sReadSetBegin() (elemType=%#v, size=%#v, err=%#v)", tdp.LogPrefix, elemType, size, err)
+ tdp.logf("%sReadSetBegin() (elemType=%#v, size=%#v, err=%#v)", tdp.LogPrefix, elemType, size, err)
return
}
func (tdp *TDebugProtocol) ReadSetEnd() (err error) {
err = tdp.Delegate.ReadSetEnd()
- log.Printf("%sReadSetEnd() err=%#v", tdp.LogPrefix, err)
+ tdp.logf("%sReadSetEnd() err=%#v", tdp.LogPrefix, err)
return
}
func (tdp *TDebugProtocol) ReadBool() (value bool, err error) {
value, err = tdp.Delegate.ReadBool()
- log.Printf("%sReadBool() (value=%#v, err=%#v)", tdp.LogPrefix, value, err)
+ tdp.logf("%sReadBool() (value=%#v, err=%#v)", tdp.LogPrefix, value, err)
return
}
func (tdp *TDebugProtocol) ReadByte() (value int8, err error) {
value, err = tdp.Delegate.ReadByte()
- log.Printf("%sReadByte() (value=%#v, err=%#v)", tdp.LogPrefix, value, err)
+ tdp.logf("%sReadByte() (value=%#v, err=%#v)", tdp.LogPrefix, value, err)
return
}
func (tdp *TDebugProtocol) ReadI16() (value int16, err error) {
value, err = tdp.Delegate.ReadI16()
- log.Printf("%sReadI16() (value=%#v, err=%#v)", tdp.LogPrefix, value, err)
+ tdp.logf("%sReadI16() (value=%#v, err=%#v)", tdp.LogPrefix, value, err)
return
}
func (tdp *TDebugProtocol) ReadI32() (value int32, err error) {
value, err = tdp.Delegate.ReadI32()
- log.Printf("%sReadI32() (value=%#v, err=%#v)", tdp.LogPrefix, value, err)
+ tdp.logf("%sReadI32() (value=%#v, err=%#v)", tdp.LogPrefix, value, err)
return
}
func (tdp *TDebugProtocol) ReadI64() (value int64, err error) {
value, err = tdp.Delegate.ReadI64()
- log.Printf("%sReadI64() (value=%#v, err=%#v)", tdp.LogPrefix, value, err)
+ tdp.logf("%sReadI64() (value=%#v, err=%#v)", tdp.LogPrefix, value, err)
return
}
func (tdp *TDebugProtocol) ReadDouble() (value float64, err error) {
value, err = tdp.Delegate.ReadDouble()
- log.Printf("%sReadDouble() (value=%#v, err=%#v)", tdp.LogPrefix, value, err)
+ tdp.logf("%sReadDouble() (value=%#v, err=%#v)", tdp.LogPrefix, value, err)
return
}
func (tdp *TDebugProtocol) ReadString() (value string, err error) {
value, err = tdp.Delegate.ReadString()
- log.Printf("%sReadString() (value=%#v, err=%#v)", tdp.LogPrefix, value, err)
+ tdp.logf("%sReadString() (value=%#v, err=%#v)", tdp.LogPrefix, value, err)
return
}
func (tdp *TDebugProtocol) ReadBinary() (value []byte, err error) {
value, err = tdp.Delegate.ReadBinary()
- log.Printf("%sReadBinary() (value=%#v, err=%#v)", tdp.LogPrefix, value, err)
+ tdp.logf("%sReadBinary() (value=%#v, err=%#v)", tdp.LogPrefix, value, err)
return
}
func (tdp *TDebugProtocol) Skip(fieldType TType) (err error) {
err = tdp.Delegate.Skip(fieldType)
- log.Printf("%sSkip(fieldType=%#v) (err=%#v)", tdp.LogPrefix, fieldType, err)
+ tdp.logf("%sSkip(fieldType=%#v) (err=%#v)", tdp.LogPrefix, fieldType, err)
return
}
func (tdp *TDebugProtocol) Flush(ctx context.Context) (err error) {
err = tdp.Delegate.Flush(ctx)
- log.Printf("%sFlush() (err=%#v)", tdp.LogPrefix, err)
+ tdp.logf("%sFlush() (err=%#v)", tdp.LogPrefix, err)
return
}
diff --git a/lib/go/thrift/logger.go b/lib/go/thrift/logger.go
new file mode 100644
index 0000000..c42aac9
--- /dev/null
+++ b/lib/go/thrift/logger.go
@@ -0,0 +1,69 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements. See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership. The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied. See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+ */
+
+package thrift
+
+import (
+ "log"
+ "os"
+ "testing"
+)
+
+// Logger is a simple wrapper of a logging function.
+//
+// In reality the users might actually use different logging libraries, and they
+// are not always compatible with each other.
+//
+// Logger is meant to be a simple common ground that it's easy to wrap whatever
+// logging library they use into.
+//
+// See https://issues.apache.org/jira/browse/THRIFT-4985 for the design
+// discussion behind it.
+type Logger func(msg string)
+
+// NopLogger is a Logger implementation that does nothing.
+func NopLogger(msg string) {}
+
+// StdLogger wraps stdlib log package into a Logger.
+//
+// If logger passed in is nil, it will fallback to use stderr and default flags.
+func StdLogger(logger *log.Logger) Logger {
+ if logger == nil {
+ logger = log.New(os.Stderr, "", log.LstdFlags)
+ }
+ return func(msg string) {
+ logger.Print(msg)
+ }
+}
+
+// TestLogger is a Logger implementation can be used in test codes.
+//
+// It fails the test when being called.
+func TestLogger(tb testing.TB) Logger {
+ return func(msg string) {
+ tb.Errorf("logger called with msg: %q", msg)
+ }
+}
+
+func fallbackLogger(logger Logger) Logger {
+ if logger == nil {
+ return StdLogger(nil)
+ }
+ return logger
+}
diff --git a/lib/go/thrift/simple_server.go b/lib/go/thrift/simple_server.go
index c1ab957..51e3509 100644
--- a/lib/go/thrift/simple_server.go
+++ b/lib/go/thrift/simple_server.go
@@ -20,9 +20,8 @@
package thrift
import (
+ "fmt"
"io"
- "log"
- "runtime/debug"
"sync"
"sync/atomic"
)
@@ -46,6 +45,8 @@
// Headers to auto forward in THeaderProtocol
forwardHeaders []string
+
+ logger Logger
}
func NewTSimpleServer2(processor TProcessor, serverTransport TServerTransport) *TSimpleServer {
@@ -149,6 +150,14 @@
p.forwardHeaders = keys
}
+// SetLogger sets the logger used by this TSimpleServer.
+//
+// If no logger was set before Serve is called, a default logger using standard
+// log library will be used.
+func (p *TSimpleServer) SetLogger(logger Logger) {
+ p.logger = logger
+}
+
func (p *TSimpleServer) innerAccept() (int32, error) {
client, err := p.serverTransport.Accept()
p.mu.Lock()
@@ -165,7 +174,7 @@
go func() {
defer p.wg.Done()
if err := p.processRequests(client); err != nil {
- log.Println("error processing request:", err)
+ p.logger(fmt.Sprintf("error processing request: %v", err))
}
}()
}
@@ -185,6 +194,8 @@
}
func (p *TSimpleServer) Serve() error {
+ p.logger = fallbackLogger(p.logger)
+
err := p.Listen()
if err != nil {
return err
@@ -230,12 +241,6 @@
outputProtocol = p.outputProtocolFactory.GetProtocol(outputTransport)
}
- defer func() {
- if e := recover(); e != nil {
- log.Printf("panic in processor: %v: %s", e, debug.Stack())
- }
- }()
-
if inputTransport != nil {
defer inputTransport.Close()
}
diff --git a/lib/go/thrift/zlib_transport.go b/lib/go/thrift/zlib_transport.go
index f3d4267..e7efdfb 100644
--- a/lib/go/thrift/zlib_transport.go
+++ b/lib/go/thrift/zlib_transport.go
@@ -23,7 +23,6 @@
"compress/zlib"
"context"
"io"
- "log"
)
// TZlibTransportFactory is a factory for TZlibTransport instances
@@ -67,7 +66,6 @@
func NewTZlibTransport(trans TTransport, level int) (*TZlibTransport, error) {
w, err := zlib.NewWriterLevel(trans, level)
if err != nil {
- log.Println(err)
return nil, err
}