This is an automated email from the ASF dual-hosted git repository.
zrhoffman 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 6980d33 Add t3c log for TO response Age and other things (#6386)
6980d33 is described below
commit 6980d3364ed9ec9af081bdf6c919136d51b2c528
Author: Robert O Butts <[email protected]>
AuthorDate: Tue Dec 14 14:21:08 2021 -0700
Add t3c log for TO response Age and other things (#6386)
---
cache-config/t3cutil/getdatacfg.go | 20 +++++++
cache-config/t3cutil/toreq/client.go | 22 ++++++++
cache-config/t3cutil/toreq/client_test.go | 63 ++++++++++++++++++++++
cache-config/t3cutil/toreq/torequtil/torequtil.go | 12 +++++
.../t3cutil/toreq/torequtil/torequtil_test.go | 11 ++++
lib/go-rfc/http.go | 1 +
6 files changed, 129 insertions(+)
diff --git a/cache-config/t3cutil/getdatacfg.go
b/cache-config/t3cutil/getdatacfg.go
index d78163b..a9ddfbe8 100644
--- a/cache-config/t3cutil/getdatacfg.go
+++ b/cache-config/t3cutil/getdatacfg.go
@@ -23,6 +23,7 @@ import (
"errors"
"net"
"net/http"
+ "strconv"
"strings"
"sync"
"time"
@@ -185,6 +186,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
reqHdr = MakeReqHdr(oldCfg.MetaData.GlobalParams)
}
globalParams, reqInf, err :=
toClient.GetGlobalParameters(reqHdr)
+ log.Infoln(toreq.RequestInfoStr(reqInf, "GetGlobalParameters"))
if err != nil {
return nil, errors.New("getting global parameters: " +
err.Error())
}
@@ -242,6 +244,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
reqHdr = MakeReqHdr(oldCfg.MetaData.Servers)
}
servers, reqInf, err := toClient.GetServers(reqHdr)
+ log.Infoln(toreq.RequestInfoStr(reqInf, "GetServers"))
if err != nil {
return errors.New("getting servers: " +
err.Error())
}
@@ -285,6 +288,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
reqHdr =
MakeReqHdr(oldCfg.MetaData.SSLKeys)
}
keys, reqInf, err :=
toClient.GetCDNSSLKeys(tc.CDNName(*server.CDNName), reqHdr)
+ log.Infoln(toreq.RequestInfoStr(reqInf,
"GetCDNSSLKeys("+*server.CDNName+")"))
if err != nil {
return errors.New("getting cdn '" +
*server.CDNName + "': " + err.Error())
}
@@ -310,6 +314,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
reqHdr =
MakeReqHdr(oldCfg.MetaData.DeliveryServices)
}
dses, reqInf, err :=
toClient.GetCDNDeliveryServices(*server.CDNID, reqHdr)
+ log.Infoln(toreq.RequestInfoStr(reqInf,
"GetCDNDeliveryServices("+strconv.Itoa(*server.CDNID)+")"))
if err != nil {
return errors.New("getting delivery
services: " + err.Error())
}
@@ -346,6 +351,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
reqHdr =
MakeReqHdr(oldCfg.MetaData.DeliveryServiceServers)
}
dss, reqInf, err :=
toClient.GetDeliveryServiceServers(nil, nil, *server.CDNName, reqHdr)
+ log.Infoln(toreq.RequestInfoStr(reqInf,
"GetDeliveryServiceServers("+*server.CDNName+")"))
if err != nil {
return errors.New("getting
delivery service servers: " + err.Error())
}
@@ -381,6 +387,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
reqHdr =
MakeReqHdr(oldCfg.MetaData.URISigningKeys[tc.DeliveryServiceName(*ds.XMLID)])
}
keys, reqInf, err :=
toClient.GetURISigningKeys(*ds.XMLID, reqHdr)
+ log.Infoln(toreq.RequestInfoStr(reqInf,
"GetURISigningKeys("+*ds.XMLID+")"))
if err != nil {
if
strings.Contains(strings.ToLower(err.Error()), "not found") {
log.Errorln("Delivery
service '" + *ds.XMLID + "' is uri_signing, but keys not found! Skipping!")
@@ -422,6 +429,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
reqHdr =
MakeReqHdr(oldCfg.MetaData.URLSigKeys[tc.DeliveryServiceName(*ds.XMLID)])
}
keys, reqInf, err :=
toClient.GetURLSigKeys(*ds.XMLID, reqHdr)
+ log.Infoln(toreq.RequestInfoStr(reqInf,
"GetURLSigKeys("+*ds.XMLID+")"))
if err != nil {
if
strings.Contains(strings.ToLower(err.Error()), "not found") {
log.Errorln("Delivery
service '" + *ds.XMLID + "' is url_sig, but keys not found! Skipping!: " +
err.Error())
@@ -464,6 +472,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
reqHdr =
MakeReqHdr(oldCfg.MetaData.ServerParams)
}
params, reqInf, err :=
toClient.GetServerProfileParameters(*server.Profile, reqHdr)
+ log.Infoln(toreq.RequestInfoStr(reqInf,
"GetURLSigKeys("+*server.Profile+")"))
if err != nil {
return errors.New("getting server
profile '" + *server.Profile + "' parameters: " + err.Error())
} else if len(params) == 0 {
@@ -490,6 +499,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
reqHdr = MakeReqHdr(oldCfg.MetaData.CDN)
}
cdn, reqInf, err :=
toClient.GetCDN(tc.CDNName(*server.CDNName), reqHdr)
+ log.Infoln(toreq.RequestInfoStr(reqInf,
"GetCDN("+*server.CDNName+")"))
if err != nil {
return errors.New("getting cdn '" +
*server.CDNName + "': " + err.Error())
}
@@ -513,6 +523,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
reqHdr =
MakeReqHdr(oldCfg.MetaData.Profile)
}
profile, reqInf, err :=
toClient.GetProfileByName(*server.Profile, reqHdr)
+ log.Infoln(toreq.RequestInfoStr(reqInf,
"GetProfileByName("+*server.Profile+")"))
if err != nil {
return errors.New("getting profile '" +
*server.Profile + "': " + err.Error())
}
@@ -536,6 +547,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
reqHdr =
MakeReqHdr(oldCfg.MetaData.Jobs)
}
jobs, reqInf, err := toClient.GetJobs(reqHdr,
*server.CDNName)
+ log.Infoln(toreq.RequestInfoStr(reqInf,
"GetJobs("+*server.CDNName+")"))
if err != nil {
return errors.New("getting jobs: " +
err.Error())
}
@@ -566,6 +578,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
reqHdr = MakeReqHdr(oldCfg.MetaData.CacheGroups)
}
cacheGroups, reqInf, err :=
toClient.GetCacheGroups(reqHdr)
+ log.Infoln(toreq.RequestInfoStr(reqInf,
"GetCacheGroups"))
if err != nil {
return errors.New("getting cachegroups: " +
err.Error())
}
@@ -590,6 +603,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
}
log.Infof("Getting config: ServerCapabilities reqHdr
%+v", reqHdr)
caps, reqInf, err :=
toClient.GetServerCapabilitiesByID(nil, reqHdr) // TODO change to not take a
param; it doesn't use it to request TO anyway.
+ log.Infoln(toreq.RequestInfoStr(reqInf,
"GetServerCapabilitiesByID"))
if err != nil {
log.Errorln("Server Capabilities error,
skipping!")
// return errors.New("getting server caps from
Traffic Ops: " + err.Error())
@@ -615,6 +629,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
reqHdr =
MakeReqHdr(oldCfg.MetaData.DSRequiredCapabilities)
}
caps, reqInf, err :=
toClient.GetDeliveryServiceRequiredCapabilitiesByID(nil, reqHdr)
+ log.Infoln(toreq.RequestInfoStr(reqInf,
"GetDeliveryServiceRequiredCapabilitiesByID"))
if err != nil {
log.Errorln("DS Required Capabilities error,
skipping!")
// return errors.New("getting DS required
capabilities: " + err.Error())
@@ -640,6 +655,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
reqHdr =
MakeReqHdr(oldCfg.MetaData.DeliveryServiceRegexes)
}
dsr, reqInf, err :=
toClient.GetDeliveryServiceRegexes(reqHdr)
+ log.Infoln(toreq.RequestInfoStr(reqInf,
"GetDeliveryServiceRegexes"))
if err != nil {
return errors.New("getting delivery service
regexes: " + err.Error())
}
@@ -664,6 +680,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
reqHdr =
MakeReqHdr(oldCfg.MetaData.CacheKeyConfigParams)
}
params, reqInf, err :=
toClient.GetConfigFileParameters("cachekey.config", reqHdr)
+ log.Infoln(toreq.RequestInfoStr(reqInf,
"GetConfigFileParameters(cachekey.config)"))
if err != nil {
return errors.New("getting cache key
parameters: " + err.Error())
}
@@ -688,6 +705,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
reqHdr =
MakeReqHdr(oldCfg.MetaData.RemapConfigParams)
}
params, reqInf, err :=
toClient.GetConfigFileParameters("remap.config", reqHdr)
+ log.Infoln(toreq.RequestInfoStr(reqInf,
"GetConfigFileParameters(remap.config)"))
if err != nil {
return errors.New("getting cache key
parameters: " + err.Error())
}
@@ -712,6 +730,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
reqHdr =
MakeReqHdr(oldCfg.MetaData.ParentConfigParams)
}
parentConfigParams, reqInf, err :=
toClient.GetConfigFileParameters("parent.config", reqHdr) // TODO make const in
lib/go-atscfg
+ log.Infoln(toreq.RequestInfoStr(reqInf,
"GetConfigFileParameters(parent.config)"))
if err != nil {
return errors.New("getting parent.config
parameters: " + err.Error())
}
@@ -736,6 +755,7 @@ func GetConfigData(toClient *toreq.TOClient, disableProxy
bool, cacheHostName st
reqHdr = MakeReqHdr(oldCfg.MetaData.Topologies)
}
topologies, reqInf, err :=
toClient.GetTopologies(reqHdr)
+ log.Infoln(toreq.RequestInfoStr(reqInf,
"GetTopologies"))
if err != nil {
return errors.New("getting topologies: " +
err.Error())
}
diff --git a/cache-config/t3cutil/toreq/client.go
b/cache-config/t3cutil/toreq/client.go
index f4a32c0..9f85b57 100644
--- a/cache-config/t3cutil/toreq/client.go
+++ b/cache-config/t3cutil/toreq/client.go
@@ -39,6 +39,8 @@ import (
"github.com/apache/trafficcontrol/cache-config/t3cutil/toreq/toreqold"
"github.com/apache/trafficcontrol/cache-config/t3cutil/toreq/torequtil"
"github.com/apache/trafficcontrol/lib/go-log"
+ "github.com/apache/trafficcontrol/lib/go-rfc"
+ "github.com/apache/trafficcontrol/traffic_ops/toclientlib"
toclient "github.com/apache/trafficcontrol/traffic_ops/v4-client"
)
@@ -128,3 +130,23 @@ func IsLatestSupported(toClient *toclient.Session) (bool,
net.Addr, error) {
}
return true, inf.RemoteAddr, nil
}
+
+// RequestInfoStr returns a loggable string with info about the Traffic Ops
request.
+//
+// The returned string does not have a trailing newline, nor anything in the
standard
+// logger prefix (time, level, etc).
+// If the string isn't going to be logged via lib/go-log, it's advisable to
add a timestamp.
+//
+// This is safe to call even if the function returning a ReqInf returned an
error;
+// it checks for nil values in all cases, and the TO Client guarantees even if
a non-nil
+// error is returned, all ReqInf values are either nil or valid.
+//
+func RequestInfoStr(inf toclientlib.ReqInf, reqPath string) string {
+ return fmt.Sprintf(`requestinfo path=%v ip=%v code=%v, date="%v"
age=%v`,
+ reqPath,
+ torequtil.MaybeIPStr(inf.RemoteAddr),
+ inf.StatusCode,
+ torequtil.MaybeHdrStr(inf.RespHeaders, rfc.Date),
+ torequtil.MaybeHdrStr(inf.RespHeaders, rfc.Age),
+ )
+}
diff --git a/cache-config/t3cutil/toreq/client_test.go
b/cache-config/t3cutil/toreq/client_test.go
new file mode 100644
index 0000000..e98a44c
--- /dev/null
+++ b/cache-config/t3cutil/toreq/client_test.go
@@ -0,0 +1,63 @@
+package toreq
+
+/*
+ * 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 (
+ "net"
+ "net/http"
+ "strings"
+ "testing"
+
+ "github.com/apache/trafficcontrol/traffic_ops/toclientlib"
+)
+
+func TestRequestInfoStr(t *testing.T) {
+
+ type Expected struct {
+ Desc string
+ Input toclientlib.ReqInf
+ Path string
+ Contains []string
+ }
+ expecteds := []Expected{
+ {"all_nils", toclientlib.ReqInf{RemoteAddr: nil, StatusCode: 0,
RespHeaders: nil}, "", []string{"code=0"}},
+ {"nil_addr", toclientlib.ReqInf{RemoteAddr: nil, StatusCode:
200, RespHeaders: http.Header{}}, "", []string{"code=200"}},
+ {"zero_code", toclientlib.ReqInf{RemoteAddr:
makeIP("192.0.2.1"), StatusCode: 0, RespHeaders: http.Header{}}, "",
[]string{"code=0"}},
+ {"nil_header", toclientlib.ReqInf{RemoteAddr:
makeIP("192.0.2.1"), StatusCode: 200, RespHeaders: nil}, "",
[]string{"code=200"}},
+ {"ip", toclientlib.ReqInf{RemoteAddr: makeIP("192.0.2.1"),
StatusCode: 200, RespHeaders: http.Header{}}, "", []string{"ip=192.0.2.1"}},
+ {"date", toclientlib.ReqInf{RemoteAddr: makeIP("192.0.2.1"),
StatusCode: 200, RespHeaders: http.Header{"Date": {"Mon, 29 Nov 2021 10:11:12
GMT"}}}, "", []string{`date="Mon, 29 Nov 2021 10:11:12 GMT"`}},
+ {"age", toclientlib.ReqInf{RemoteAddr: makeIP("192.0.2.1"),
StatusCode: 200, RespHeaders: http.Header{"Age": {"4242"}}}, "",
[]string{`age=42`}},
+ {"path", toclientlib.ReqInf{RemoteAddr: makeIP("192.0.2.1"),
StatusCode: 200, RespHeaders: http.Header{"Age": {"4242"}}}, "my-endpoint",
[]string{`path=my-endpoint`}},
+ {"path_age_code_ip_date", toclientlib.ReqInf{RemoteAddr:
makeIP("192.0.2.9"), StatusCode: 206, RespHeaders: http.Header{"Age": {"99"},
"Date": {`some malformed date`}}}, "my-everything-endpoint",
[]string{`path=my-everything-endpoint`, `age=99`, `code=206`, `ip=192.0.2.9`,
`date="some malformed date"`}},
+ }
+
+ for _, expected := range expecteds {
+ t.Run(expected.Desc, func(t *testing.T) {
+ output := RequestInfoStr(expected.Input, expected.Path)
+ for _, expContain := range expected.Contains {
+ if !strings.Contains(output, expContain) {
+ t.Errorf("expected input '%v' path '%v'
to contain '%v' actual '%v'", expected.Input, expected.Path, expContain, output)
+ }
+ }
+ })
+ }
+}
+
+func makeIP(ip string) *net.IPAddr { return &net.IPAddr{IP: net.ParseIP(ip),
Zone: ""} }
diff --git a/cache-config/t3cutil/toreq/torequtil/torequtil.go
b/cache-config/t3cutil/toreq/torequtil/torequtil.go
index cf52e64..fdd51d0 100644
--- a/cache-config/t3cutil/toreq/torequtil/torequtil.go
+++ b/cache-config/t3cutil/toreq/torequtil/torequtil.go
@@ -75,6 +75,18 @@ func MaybeIPStr(addr net.Addr) string {
return ""
}
+// MaybeHdrStr returns the header text if hdr isn't nil, or the empty string
if it is.
+// This is intended for logging, to allow logging with one line, whether a
header object is nil or not.
+//
+// The hdrName must be the canonically-capitalized header name.
+//
+func MaybeHdrStr(hdr http.Header, hdrName string) string {
+ if hdr != nil {
+ return hdr.Get(hdrName)
+ }
+ return ""
+}
+
func StringToCookies(cookiesStr string) []*http.Cookie {
hdr := http.Header{}
hdr.Add("Cookie", cookiesStr)
diff --git a/cache-config/t3cutil/toreq/torequtil/torequtil_test.go
b/cache-config/t3cutil/toreq/torequtil/torequtil_test.go
index 533a0db..b5e2045 100644
--- a/cache-config/t3cutil/toreq/torequtil/torequtil_test.go
+++ b/cache-config/t3cutil/toreq/torequtil/torequtil_test.go
@@ -22,6 +22,7 @@ package torequtil
import (
"errors"
"net"
+ "net/http"
"strings"
"testing"
)
@@ -68,3 +69,13 @@ func TestMaybeIPStr(t *testing.T) {
t.Errorf("MaybeIPStr(nil) expected '192.0.2.1', actual '%v'",
is)
}
}
+
+func TestMaybeHdrStr(t *testing.T) {
+ if is := MaybeHdrStr(nil, "Age"); is != "" {
+ t.Errorf("MaybeHdrStr(nil) expected '', actual '%v'", is)
+ }
+ hdr := http.Header{"Age": {"1001"}}
+ if is := MaybeHdrStr(hdr, "Age"); is != "1001" {
+ t.Errorf("MaybeIPStr(val) expected '1001', actual '%v'", is)
+ }
+}
diff --git a/lib/go-rfc/http.go b/lib/go-rfc/http.go
index 03979fe..2ae1065 100644
--- a/lib/go-rfc/http.go
+++ b/lib/go-rfc/http.go
@@ -40,6 +40,7 @@ const (
Server = "Server" // RFC7231§7.4.2
UserAgent = "User-Agent" // RFC7231§5.5.3
Vary = "Vary" // RFC7231§7.1.4
+ Age = "Age" // RFC7234§5.1
)
// These are (some) valid values for content encoding and MIME types, for
