This is an automated email from the ASF dual-hosted git repository.
rawlin pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/trafficcontrol.git
The following commit(s) were added to refs/heads/master by this push:
new 6d1aa80 Fix TO log format for 3rd party libs (#3589)
6d1aa80 is described below
commit 6d1aa8030c832f0c5420c69a5dda7590438eace9
Author: Robert Butts <[email protected]>
AuthorDate: Thu May 30 16:06:22 2019 -0600
Fix TO log format for 3rd party libs (#3589)
Fixes TO Go logging of Riak and ReverseProxy, which weren't properly
adding the prefix and date format of lib/go-log.
Fixes it by adding a func to create a new wrapper Logger, which
writes to the given logger with the standard log.Printf funcs,
properly setting the time and prefix.
Fixes #3587
---
CHANGELOG.md | 1 +
lib/go-log/log.go | 70 +++++++++---------------
lib/go-log/standardlogger.go | 48 ++++++++++++++++
lib/go-log/standardlogger_test.go | 69 +++++++++++++++++++++++
traffic_ops/traffic_ops_golang/routing/routes.go | 35 ++++--------
5 files changed, 153 insertions(+), 70 deletions(-)
diff --git a/CHANGELOG.md b/CHANGELOG.md
index 97dedc2..e1d0a6c 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -49,6 +49,7 @@ The format is based on [Keep a
Changelog](http://keepachangelog.com/en/1.0.0/).
- Upgraded Traffic Portal to AngularJS 1.7.8
- Issue 3275: Improved the snapshot diff performance and experience.
- Issue #3605: Fixed Traffic Monitor custom ports in health polling URL.
+- Issue 3587: Fixed Traffic Ops Golang reverse proxy and Riak logs to be
consistent with the format of other error logs.
## [3.0.0] - 2018-10-30
### Added
diff --git a/lib/go-log/log.go b/lib/go-log/log.go
index 593b46a..1470a2e 100644
--- a/lib/go-log/log.go
+++ b/lib/go-log/log.go
@@ -72,56 +72,36 @@ func Init(eventW, errW, warnW, infoW, debugW
io.WriteCloser) {
initLogger(&Event, &eventCloser, eventW, "", 0)
}
-const timeFormat = time.RFC3339Nano
-const stackFrame = 3
-
-func Errorf(format string, v ...interface{}) {
- if Error == nil {
- return
- }
- Error.Output(stackFrame, time.Now().Format(timeFormat)+":
"+fmt.Sprintf(format, v...))
-}
-func Errorln(v ...interface{}) {
- if Error == nil {
- return
- }
- Error.Output(stackFrame, time.Now().Format(timeFormat)+":
"+fmt.Sprintln(v...))
-}
-func Warnf(format string, v ...interface{}) {
- if Warning == nil {
+func logf(logger *log.Logger, format string, v ...interface{}) {
+ if logger == nil {
return
}
- Warning.Output(stackFrame, time.Now().Format(timeFormat)+":
"+fmt.Sprintf(format, v...))
+ logger.Output(stackFrame, time.Now().Format(timeFormat)+":
"+fmt.Sprintf(format, v...))
}
-func Warnln(v ...interface{}) {
- if Warning == nil {
- return
- }
- Warning.Output(stackFrame, time.Now().Format(timeFormat)+":
"+fmt.Sprintln(v...))
-}
-func Infof(format string, v ...interface{}) {
- if Info == nil {
- return
- }
- Info.Output(stackFrame, time.Now().Format(timeFormat)+":
"+fmt.Sprintf(format, v...))
-}
-func Infoln(v ...interface{}) {
- if Info == nil {
- return
- }
- Info.Output(stackFrame, time.Now().Format(timeFormat)+":
"+fmt.Sprintln(v...))
-}
-func Debugf(format string, v ...interface{}) {
- if Debug == nil {
+
+func logln(logger *log.Logger, v ...interface{}) {
+ if logger == nil {
return
}
- Debug.Output(stackFrame, time.Now().Format(timeFormat)+":
"+fmt.Sprintf(format, v...))
+ logger.Output(stackFrame, time.Now().Format(timeFormat)+":
"+fmt.Sprintln(v...))
}
-func Debugln(v ...interface{}) {
- if Debug == nil {
- return
- }
- Debug.Output(stackFrame, time.Now().Format(timeFormat)+":
"+fmt.Sprintln(v...))
+
+const timeFormat = time.RFC3339Nano
+const stackFrame = 3
+
+func Errorf(format string, v ...interface{}) { logf(Error, format, v...) }
+func Errorln(v ...interface{}) { logln(Error, v...) }
+func Warnf(format string, v ...interface{}) { logf(Warning, format, v...) }
+func Warnln(v ...interface{}) { logln(Warning, v...) }
+func Infof(format string, v ...interface{}) { logf(Info, format, v...) }
+func Infoln(v ...interface{}) { logln(Info, v...) }
+func Debugf(format string, v ...interface{}) { logf(Debug, format, v...) }
+func Debugln(v ...interface{}) { logln(Debug, v...) }
+
+const eventFormat = "%.3f %s"
+
+func eventTime(t time.Time) float64 {
+ return float64(t.Unix()) + (float64(t.Nanosecond()) / 1e9)
}
// event log entries (TM event.log, TR access.log, etc)
@@ -130,7 +110,7 @@ func Eventf(t time.Time, format string, v ...interface{}) {
return
}
// 1484001185.287 ...
- Event.Printf("%.3f %s",
float64(t.Unix())+(float64(t.Nanosecond())/1e9), fmt.Sprintf(format, v...))
+ Event.Printf(eventFormat, eventTime(t), fmt.Sprintf(format, v...))
}
// EventfRaw writes to the event log with no prefix.
diff --git a/lib/go-log/standardlogger.go b/lib/go-log/standardlogger.go
new file mode 100644
index 0000000..71c775d
--- /dev/null
+++ b/lib/go-log/standardlogger.go
@@ -0,0 +1,48 @@
+package log
+
+/*
+ * 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.
+ */
+
+import (
+ "log"
+ "strings"
+)
+
+// StandardLogger returns a new Logger which will write the appropriate prefix
for standard log Printf calls.
+// This allows the given logger to prefix correctly when passed to third-party
or standard library functions which only know about the standard Logger
interface.
+// It does this by wrapping logger's error print as a writer, and sets that as
the new Logger's io.Writer.
+//
+// prefix is a prefix to add, which will be added immediately before messages,
but after any existing prefix on logger and the timestamp.
+//
+func StandardLogger(logger *log.Logger, prefix string) *log.Logger {
+ return log.New(&standardLoggerWriter{realLogger: logger, prefix:
prefix}, "", 0)
+}
+
+type standardLoggerWriter struct {
+ realLogger *log.Logger
+ prefix string
+}
+
+// Write writes to writer's underlying log, in the standard log format (note
this is not the Event log format).
+// The writer.realLogger may be nil, in which case this does nothing.
+// This always returns len(p) and nil, claiming it successfully wrote even if
it didn't.
+func (writer *standardLoggerWriter) Write(p []byte) (n int, err error) {
+ logln(writer.realLogger, writer.prefix+strings.TrimSpace(string(p)))
+ return len(p), nil
+}
diff --git a/lib/go-log/standardlogger_test.go
b/lib/go-log/standardlogger_test.go
new file mode 100644
index 0000000..bf2422b
--- /dev/null
+++ b/lib/go-log/standardlogger_test.go
@@ -0,0 +1,69 @@
+package log
+
+/*
+ * 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.
+ */
+
+import (
+ "bytes"
+ "log"
+ "strings"
+ "testing"
+ "time"
+)
+
+func TestStandardLogger(t *testing.T) {
+ buf := &bytes.Buffer{}
+ realLogPrefix := "a-real-log-prefix: "
+ logger := log.New(buf, realLogPrefix, log.Lshortfile)
+
+ sPrefix := "a-standard-logger-prefix: "
+ sLogger := StandardLogger(logger, sPrefix)
+
+ msg := "a-message"
+ sLogger.Printf(msg + "\n") // newline, to verify a double-newline isn't
printed.
+
+ actual := buf.String()
+
+ if !strings.HasPrefix(actual, realLogPrefix) {
+ t.Errorf("expected prefix '%v' actual '%v'\n", realLogPrefix,
actual)
+ }
+
+ actualFields := strings.Fields(actual)
+ if len(actualFields) < 4 {
+ t.Fatalf("expected fields >4 (prefix, line, time, msg} actual
%v '''%v'''\n", len(actualFields), actual)
+ }
+
+ timeField := actualFields[2]
+ if len(timeField) > 0 {
+ timeField = timeField[:len(timeField)-1] // timestamp ends with
:, strip it for parsing
+ }
+
+ actualTime, err := time.Parse(time.RFC3339Nano, timeField)
+ if err != nil {
+ t.Fatalf("expected 3rd field is RFC3339 nano format, actual
'%v'\n", timeField)
+ }
+ if actualTime.After(time.Now().Add(time.Minute)) ||
actualTime.Before(time.Now().Add(time.Minute*-1)) {
+ t.Errorf("expected 3rd field is RFC3339 nano format around now
'%v', actual '%v'\n", time.Now(), actualTime)
+ }
+}
+
+func TestStandardLoggerNil(t *testing.T) {
+ // test that a nil logger doesn't panic
+ StandardLogger(nil, "").Println("foo")
+}
diff --git a/traffic_ops/traffic_ops_golang/routing/routes.go
b/traffic_ops/traffic_ops_golang/routing/routes.go
index 532d73c..fe59806 100644
--- a/traffic_ops/traffic_ops_golang/routing/routes.go
+++ b/traffic_ops/traffic_ops_golang/routing/routes.go
@@ -23,15 +23,13 @@ import (
"crypto/tls"
"encoding/json"
"errors"
- "io"
- "log"
"net"
"net/http"
"net/http/httputil"
"runtime"
"time"
- tclog "github.com/apache/trafficcontrol/lib/go-log"
+ "github.com/apache/trafficcontrol/lib/go-log"
"github.com/apache/trafficcontrol/lib/go-tc"
"github.com/apache/trafficcontrol/traffic_ops/traffic_ops_golang/about"
"github.com/apache/trafficcontrol/traffic_ops/traffic_ops_golang/api"
@@ -56,6 +54,7 @@ import (
"github.com/apache/trafficcontrol/traffic_ops/traffic_ops_golang/federations"
"github.com/apache/trafficcontrol/traffic_ops/traffic_ops_golang/hwinfo"
"github.com/apache/trafficcontrol/traffic_ops/traffic_ops_golang/login"
+ "github.com/apache/trafficcontrol/traffic_ops/traffic_ops_golang/origin"
"github.com/apache/trafficcontrol/traffic_ops/traffic_ops_golang/parameter"
"github.com/apache/trafficcontrol/traffic_ops/traffic_ops_golang/physlocation"
"github.com/apache/trafficcontrol/traffic_ops/traffic_ops_golang/ping"
@@ -73,7 +72,6 @@ import (
"github.com/apache/trafficcontrol/traffic_ops/traffic_ops_golang/urisigning"
"github.com/apache/trafficcontrol/traffic_ops/traffic_ops_golang/user"
- "github.com/apache/trafficcontrol/traffic_ops/traffic_ops_golang/origin"
"github.com/basho/riak-go-client"
"github.com/jmoiron/sqlx"
)
@@ -451,7 +449,7 @@ func MemoryStatsHandler() http.HandlerFunc {
bytes, err := json.Marshal(stats)
if err != nil {
- tclog.Errorln("unable to marshal stats: " + err.Error())
+ log.Errorln("unable to marshal stats: " + err.Error())
handleErrs(http.StatusInternalServerError,
errors.New("marshalling error"))
return
}
@@ -467,7 +465,7 @@ func DBStatsHandler(db *sqlx.DB) http.HandlerFunc {
bytes, err := json.Marshal(stats)
if err != nil {
- tclog.Errorln("unable to marshal stats: " + err.Error())
+ log.Errorln("unable to marshal stats: " + err.Error())
handleErrs(http.StatusInternalServerError,
errors.New("marshalling error"))
return
}
@@ -492,25 +490,12 @@ func rootHandler(d ServerData) http.Handler {
rp := httputil.NewSingleHostReverseProxy(d.URL)
rp.Transport = tr
- var errorLogger interface{}
- errorLogger, err := tclog.GetLogWriter(d.Config.ErrorLog())
- if err != nil {
- tclog.Errorln("could not create error log writer for proxy: ",
err)
- }
- if errorLogger != nil {
- rp.ErrorLog = log.New(errorLogger.(io.Writer), "proxy error: ",
log.Ldate|log.Ltime|log.Lmicroseconds|log.LUTC) //if we don't provide a logger
to the reverse proxy it logs to stdout/err and is lost when ran by a script.
- riak.SetErrorLogger(log.New(errorLogger.(io.Writer), "riak
error: ", log.Ldate|log.Ltime|log.Lmicroseconds|log.LUTC))
- }
- var infoLogger interface{}
- infoLogger, err = tclog.GetLogWriter(d.Config.InfoLog())
- if err != nil {
- tclog.Errorln("could not create info log writer for proxy: ",
err)
- }
- if infoLogger != nil {
- riak.SetLogger(log.New(infoLogger.(io.Writer), "riak info: ",
log.Ldate|log.Ltime|log.Lmicroseconds|log.LUTC))
- }
- tclog.Debugf("our reverseProxy: %++v\n", rp)
- tclog.Debugf("our reverseProxy's transport: %++v\n", tr)
+ rp.ErrorLog = log.StandardLogger(log.Error, "proxy error: ")
+ riak.SetErrorLogger(log.StandardLogger(log.Error, "riak error: "))
+ riak.SetLogger(log.StandardLogger(log.Info, "riak info: "))
+
+ log.Debugf("our reverseProxy: %++v\n", rp)
+ log.Debugf("our reverseProxy's transport: %++v\n", tr)
loggingProxyHandler := wrapAccessLog(d.Secrets[0], rp)
managerHandler := CreateThrottledHandler(loggingProxyHandler,
d.BackendMaxConnections["mojolicious"])
