You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@trafficcontrol.apache.org by ra...@apache.org on 2022/03/14 22:20:52 UTC

[trafficcontrol] branch master updated: Adding access.log to Traffic Monitor (#6620)

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 c95689e  Adding access.log to Traffic Monitor (#6620)
c95689e is described below

commit c95689eef090c36df50ce4dd4b8f3909ce968d45
Author: Srijeet Chatterjee <30...@users.noreply.github.com>
AuthorDate: Mon Mar 14 16:20:35 2022 -0600

    Adding access.log to Traffic Monitor (#6620)
    
    * Adding access.log to Traffic Monitor
    
    * code review fixes
    
    * fix nil ptr, time format
    
    * code review
    
    * fix debug
---
 .github/actions/tm-integration-tests/entrypoint.sh |  1 +
 CHANGELOG.md                                       |  1 +
 .../roles/traffic-monitor/defaults/main.yml        |  1 +
 .../templates/traffic_monitor.cfg.j2               |  1 +
 .../traffic_monitor/traffic_monitor.cfg            |  1 +
 infrastructure/cdn-in-a-box/variables.env          |  1 +
 lib/go-log/log.go                                  | 32 +++++++++++------
 traffic_monitor/build/traffic_monitor.logrotate    | 10 ++++++
 traffic_monitor/conf/traffic_monitor.cfg           |  1 +
 traffic_monitor/config/config.go                   | 15 ++++++++
 traffic_monitor/config/config_test.go              |  2 ++
 traffic_monitor/datareq/datareq.go                 | 41 +++++++++++++++++++---
 .../tests/_integration/tm/Dockerfile_run.sh        |  1 +
 traffic_monitor/traffic_monitor.go                 | 14 ++++++++
 14 files changed, 108 insertions(+), 14 deletions(-)

diff --git a/.github/actions/tm-integration-tests/entrypoint.sh b/.github/actions/tm-integration-tests/entrypoint.sh
index 676e2ae..a9dad03 100755
--- a/.github/actions/tm-integration-tests/entrypoint.sh
+++ b/.github/actions/tm-integration-tests/entrypoint.sh
@@ -129,6 +129,7 @@ cat > ./traffic_monitor.cfg <<- EOF
       "max_events": 200,
       "health_flush_interval_ms": 20,
       "stat_flush_interval_ms": 20,
+      "log_location_access": null,
       "log_location_event": null,
       "log_location_error": "err.log",
       "log_location_warning": "warn.log",
diff --git a/CHANGELOG.md b/CHANGELOG.md
index 3ff373d..b21fa30 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -11,6 +11,7 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/en/1.0.0/).
 - Traffic Monitor config option `distributed_polling` which enables the ability for Traffic Monitor to poll a subset of the CDN and divide into "local peer groups" and "distributed peer groups". Traffic Monitors in the same group are local peers, while Traffic Monitors in other groups are distibuted peers. Each TM group polls the same set of cachegroups and gets availability data for the other cachegroups from other TM groups. This allows each TM to be responsible for polling a subset of [...]
 - Added support for a new Traffic Ops GLOBAL profile parameter -- `tm_query_status_override` -- to override which status of Traffic Monitors to query (default: ONLINE).
 - Traffic Router: Add support for `file`-protocol URLs for the `geolocation.polling.url` for the Geolocation database.
+- Traffic Monitor: Add support for `access.log` to TM.
 - Added functionality for login to provide a Bearer token and for that token to be later used for authorization.
 
 ### Fixed
diff --git a/infrastructure/ansible/roles/traffic-monitor/defaults/main.yml b/infrastructure/ansible/roles/traffic-monitor/defaults/main.yml
index 5915623..022f99c 100644
--- a/infrastructure/ansible/roles/traffic-monitor/defaults/main.yml
+++ b/infrastructure/ansible/roles/traffic-monitor/defaults/main.yml
@@ -33,6 +33,7 @@ tm_log_location_error: "{{ tm_log_dir }}/traffic_monitor.log"
 tm_log_location_warning: "{{ tm_log_dir }}/traffic_monitor.log"
 tm_log_location_info: "null"
 tm_log_location_debug: "null"
+tm_log_location_access: "{{ tm_log_dir }}/access.log"
 tm_log_location_event: "{{ tm_log_dir }}/event.log"
 tm_stat_flush_interval_ms: 20
 tm_serve_read_timeout_ms: 10000
diff --git a/infrastructure/ansible/roles/traffic-monitor/templates/traffic_monitor.cfg.j2 b/infrastructure/ansible/roles/traffic-monitor/templates/traffic_monitor.cfg.j2
index 2e3aa42..37c9021 100644
--- a/infrastructure/ansible/roles/traffic-monitor/templates/traffic_monitor.cfg.j2
+++ b/infrastructure/ansible/roles/traffic-monitor/templates/traffic_monitor.cfg.j2
@@ -18,6 +18,7 @@
         "max_events": {{ tm_max_events }},
         "health_flush_interval_ms": {{ tm_health_flush_interval_ms }},
         "stat_flush_interval_ms": {{ tm_stat_flush_interval_ms }},
+        "log_location_access": "{{ tm_log_location_access }}",
         "log_location_event": "{{ tm_log_location_event }}",
         "log_location_error": "{{ tm_log_location_error }}",
         "log_location_warning": "{{ tm_log_location_warning }}",
diff --git a/infrastructure/cdn-in-a-box/traffic_monitor/traffic_monitor.cfg b/infrastructure/cdn-in-a-box/traffic_monitor/traffic_monitor.cfg
index c2b1604..d36e7e6 100644
--- a/infrastructure/cdn-in-a-box/traffic_monitor/traffic_monitor.cfg
+++ b/infrastructure/cdn-in-a-box/traffic_monitor/traffic_monitor.cfg
@@ -6,6 +6,7 @@
 	"max_events": 200,
 	"health_flush_interval_ms": 20,
 	"stat_flush_interval_ms": 20,
+	"log_location_access": "$TM_LOG_ACCESS",
 	"log_location_event": "$TM_LOG_EVENT",
 	"log_location_error": "$TM_LOG_ERROR",
 	"log_location_warning": "$TM_LOG_WARNING",
diff --git a/infrastructure/cdn-in-a-box/variables.env b/infrastructure/cdn-in-a-box/variables.env
index e283f99..e9ef966 100644
--- a/infrastructure/cdn-in-a-box/variables.env
+++ b/infrastructure/cdn-in-a-box/variables.env
@@ -73,6 +73,7 @@ TM_PORT=80
 TM_EMAIL=tmonitor@cdn.example.com
 TM_PASSWORD=jhdslvhdfsuklvfhsuvlhs
 TM_USER=tmon
+TM_LOG_ACCESS=stdout
 TM_LOG_EVENT=stdout
 TM_LOG_ERROR=stdout
 TM_LOG_WARNING=stdout
diff --git a/lib/go-log/log.go b/lib/go-log/log.go
index 8484472..0b53a1e 100644
--- a/lib/go-log/log.go
+++ b/lib/go-log/log.go
@@ -29,16 +29,18 @@ import (
 )
 
 var (
-	Debug       *log.Logger
-	Info        *log.Logger
-	Warning     *log.Logger
-	Error       *log.Logger
-	Event       *log.Logger
-	debugCloser io.Closer
-	infoCloser  io.Closer
-	warnCloser  io.Closer
-	errCloser   io.Closer
-	eventCloser io.Closer
+	Debug        *log.Logger
+	Info         *log.Logger
+	Warning      *log.Logger
+	Error        *log.Logger
+	Event        *log.Logger
+	Access       *log.Logger
+	debugCloser  io.Closer
+	infoCloser   io.Closer
+	warnCloser   io.Closer
+	errCloser    io.Closer
+	eventCloser  io.Closer
+	accessCloser io.Closer
 )
 
 func initLogger(logger **log.Logger, oldLogCloser *io.Closer, newLogWriter io.WriteCloser, logPrefix string, logFlags int) {
@@ -84,6 +86,10 @@ func Init(eventW, errW, warnW, infoW, debugW io.WriteCloser) {
 	initLogger(&Event, &eventCloser, eventW, EventPrefix, EventFlags)
 }
 
+func InitAccess(accessW io.WriteCloser) {
+	initLogger(&Access, &accessCloser, accessW, EventPrefix, EventFlags)
+}
+
 // Logf should generally be avoided, use the built-in Init or InitCfg and Errorf, Warnln, etc functions instead.
 // It logs to the given logger, in the same format as the standard log functions.
 // This should only be used in rare and unusual circumstances when the standard loggers and functions can't.
@@ -122,6 +128,12 @@ func eventTime(t time.Time) float64 {
 	return float64(t.Unix()) + (float64(t.Nanosecond()) / 1e9)
 }
 
+func Accessln(v ...interface{}) {
+	if Access != nil {
+		Access.Println(v...)
+	}
+}
+
 // event log entries (TM event.log, TR access.log, etc)
 func Eventf(t time.Time, format string, v ...interface{}) {
 	if Event == nil {
diff --git a/traffic_monitor/build/traffic_monitor.logrotate b/traffic_monitor/build/traffic_monitor.logrotate
index b52c013..ae3ca3f 100644
--- a/traffic_monitor/build/traffic_monitor.logrotate
+++ b/traffic_monitor/build/traffic_monitor.logrotate
@@ -34,3 +34,13 @@
         rotate 5
         copytruncate
 }
+
+/opt/traffic_monitor/var/log/access.log {
+        compress
+        maxage 30
+        missingok
+        nomail
+        size 10M
+        rotate 5
+        copytruncate
+}
diff --git a/traffic_monitor/conf/traffic_monitor.cfg b/traffic_monitor/conf/traffic_monitor.cfg
index 11cc255..8380c2c 100644
--- a/traffic_monitor/conf/traffic_monitor.cfg
+++ b/traffic_monitor/conf/traffic_monitor.cfg
@@ -8,6 +8,7 @@
 	"distributed_polling": false,
 	"health_flush_interval_ms": 20,
 	"stat_flush_interval_ms": 20,
+	"log_location_access": "/opt/traffic_monitor/var/log/access.log",
 	"log_location_event": "/opt/traffic_monitor/var/log/event.log",
 	"log_location_error": "/opt/traffic_monitor/var/log/traffic_monitor.log",
 	"log_location_warning": "/opt/traffic_monitor/var/log/traffic_monitor.log",
diff --git a/traffic_monitor/config/config.go b/traffic_monitor/config/config.go
index 3a76fe8..98a4d9b 100644
--- a/traffic_monitor/config/config.go
+++ b/traffic_monitor/config/config.go
@@ -22,6 +22,8 @@ package config
 import (
 	"encoding/json"
 	"errors"
+	"fmt"
+	"io"
 	"io/ioutil"
 	"strings"
 	"time"
@@ -112,6 +114,7 @@ type Config struct {
 	LogLocationInfo              string          `json:"log_location_info"`
 	LogLocationDebug             string          `json:"log_location_debug"`
 	LogLocationEvent             string          `json:"log_location_event"`
+	LogLocationAccess            string          `json:"log_location_access"`
 	ServeReadTimeout             time.Duration   `json:"-"`
 	ServeWriteTimeout            time.Duration   `json:"-"`
 	StaticFileDir                string          `json:"static_file_dir"`
@@ -132,6 +135,17 @@ func (c Config) WarningLog() log.LogLocation { return log.LogLocation(c.LogLocat
 func (c Config) InfoLog() log.LogLocation    { return log.LogLocation(c.LogLocationInfo) }
 func (c Config) DebugLog() log.LogLocation   { return log.LogLocation(c.LogLocationDebug) }
 func (c Config) EventLog() log.LogLocation   { return log.LogLocation(c.LogLocationEvent) }
+func (c Config) AccessLog() log.LogLocation  { return log.LogLocation(c.LogLocationAccess) }
+
+func GetAccessLogWriter(cfg Config) (io.WriteCloser, error) {
+	accessLoc := cfg.AccessLog()
+
+	accessW, err := log.GetLogWriter(accessLoc)
+	if err != nil {
+		return nil, fmt.Errorf("getting log access writer %v: %v", accessLoc, err)
+	}
+	return accessW, nil
+}
 
 // DefaultConfig is the default configuration for the application, if no configuration file is given, or if a given config setting doesn't exist in the config file.
 var DefaultConfig = Config{
@@ -149,6 +163,7 @@ var DefaultConfig = Config{
 	LogLocationInfo:              LogLocationNull,
 	LogLocationDebug:             LogLocationNull,
 	LogLocationEvent:             LogLocationStdout,
+	LogLocationAccess:            LogLocationNull,
 	ServeReadTimeout:             10 * time.Second,
 	ServeWriteTimeout:            10 * time.Second,
 	StaticFileDir:                StaticFileDir,
diff --git a/traffic_monitor/config/config_test.go b/traffic_monitor/config/config_test.go
index 935aab3..d2bc667 100644
--- a/traffic_monitor/config/config_test.go
+++ b/traffic_monitor/config/config_test.go
@@ -34,6 +34,7 @@ const exampleTMConfig = `
 	"stat_flush_interval_ms": 1000,
 	"stat_polling": false,
 	"distributed_polling": true,
+	"log_location_access": "access.log",
 	"log_location_event": "event.log",
 	"log_location_error": "error.log",
 	"log_location_warning": "warning.log",
@@ -62,6 +63,7 @@ const exampleBadTMConfig = `
 	"stat_flush_interval_ms": 1000,
 	"stat_polling": true,
 	"distributed_polling": true,
+	"log_location_access": "access.log",
 	"log_location_event": "event.log",
 	"log_location_error": "error.log",
 	"log_location_warning": "warning.log",
diff --git a/traffic_monitor/datareq/datareq.go b/traffic_monitor/datareq/datareq.go
index c339b4a..42244d6 100644
--- a/traffic_monitor/datareq/datareq.go
+++ b/traffic_monitor/datareq/datareq.go
@@ -31,6 +31,7 @@ import (
 
 	"github.com/apache/trafficcontrol/lib/go-log"
 	"github.com/apache/trafficcontrol/lib/go-rfc"
+	"github.com/apache/trafficcontrol/lib/go-util"
 	"github.com/apache/trafficcontrol/traffic_monitor/config"
 	"github.com/apache/trafficcontrol/traffic_monitor/health"
 	"github.com/apache/trafficcontrol/traffic_monitor/peer"
@@ -286,24 +287,56 @@ func WrapAgeErr(errorCount threadsafe.Uint, f func() ([]byte, time.Time, error),
 	}
 }
 
+func accessLogTime(t time.Time) float64 {
+	return float64(t.UnixMilli()) / 1000.0
+}
+
+func accessLogStr(
+	timestamp time.Time, // prefix
+	remoteAddress string, // chi
+	reqMethod string, // cqhm
+	reqPath string, // url
+	reqRawQuery string,
+	statusCode int, // pssc
+	respSize int, // b
+	reqServeTimeMs int, // ttms
+	userAgent string, // uas
+) string {
+	return fmt.Sprintf("%.3f chi=%s cqhm=%s url=\"%s?%s\" pssc=%d b=%d ttms=%d uas=\"%s\"",
+		accessLogTime(timestamp),
+		remoteAddress,
+		reqMethod,
+		reqPath,
+		reqRawQuery,
+		statusCode,
+		respSize,
+		reqServeTimeMs,
+		userAgent)
+}
+
 // WrapUnpolledCheck wraps an http.HandlerFunc, returning ServiceUnavailable if all caches have't been polled; else, calling the wrapped func. Once all caches have been polled, we never return a 503 again, even if the CRConfig has been changed and new, unpolled caches exist. This is because, before those new caches existed in the CRConfig, they weren't being routed to, so it doesn't break anything to continue not routing to them until they're polled, while still serving polled caches as  [...]
 func wrapUnpolledCheck(unpolledCaches threadsafe.UnpolledCaches, errorCount threadsafe.Uint, f http.HandlerFunc) http.HandlerFunc {
 	polledAll := false
 	polledLocal := false
 	return func(w http.ResponseWriter, r *http.Request) {
+		start := time.Now()
+		iw := &util.Interceptor{W: w}
+		defer func() {
+			log.Accessln(accessLogStr(time.Now(), r.RemoteAddr, r.Method, r.URL.Path, r.URL.RawQuery, iw.Code, iw.ByteCount, int(time.Now().Sub(start)/time.Millisecond), r.UserAgent()))
+		}()
 		if !polledAll || !polledLocal {
 			polledAll = !unpolledCaches.Any()
 			polledLocal = !unpolledCaches.AnyDirectlyPolled()
 			rawOrLocal := r.URL.Query().Has("raw") || r.URL.Query().Has("local")
 			if (!rawOrLocal && !polledAll) || (rawOrLocal && !polledLocal) {
 				HandleErr(errorCount, r.URL.EscapedPath(), fmt.Errorf("service still starting, some caches unpolled: %v", unpolledCaches.UnpolledCaches()))
-				w.WriteHeader(http.StatusServiceUnavailable)
-				log.Write(w, []byte("Service Unavailable"), r.URL.EscapedPath())
+				iw.WriteHeader(http.StatusServiceUnavailable)
+				log.Write(iw, []byte("Service Unavailable"), r.URL.EscapedPath())
 				return
 			}
 		}
-		w.Header().Set(rfc.PermissionsPolicy, "interest-cohort=()")
-		f(w, r)
+		iw.Header().Set(rfc.PermissionsPolicy, "interest-cohort=()")
+		f(iw, r)
 	}
 }
 
diff --git a/traffic_monitor/tests/_integration/tm/Dockerfile_run.sh b/traffic_monitor/tests/_integration/tm/Dockerfile_run.sh
index b762f99..e895b48 100755
--- a/traffic_monitor/tests/_integration/tm/Dockerfile_run.sh
+++ b/traffic_monitor/tests/_integration/tm/Dockerfile_run.sh
@@ -45,6 +45,7 @@ init() {
 				"max_events": 200,
 				"health_flush_interval_ms": 20,
 				"stat_flush_interval_ms": 20,
+				"log_location_access": "/opt/traffic_monitor/var/log/access.log",
 				"log_location_event": "/opt/traffic_monitor/var/log/event.log",
 				"log_location_error": "/opt/traffic_monitor/var/log/traffic_monitor.log",
 				"log_location_warning": "/opt/traffic_monitor/var/log/traffic_monitor.log",
diff --git a/traffic_monitor/traffic_monitor.go b/traffic_monitor/traffic_monitor.go
index 23d5c18..5d31bc5 100644
--- a/traffic_monitor/traffic_monitor.go
+++ b/traffic_monitor/traffic_monitor.go
@@ -38,6 +38,15 @@ var GitRevision = "No Git Revision Specified. Please build with '-X main.GitRevi
 // BuildTimestamp is the time the app was built. The app SHOULD always be built with this set via the `-X` flag.
 var BuildTimestamp = "No Build Timestamp Specified. Please build with '-X main.BuildTimestamp=`date +'%Y-%M-%dT%H:%M:%S'`"
 
+func InitAccessCfg(cfg config.Config) error {
+	accessW, err := config.GetAccessLogWriter(cfg)
+	if err != nil {
+		return err
+	}
+	log.InitAccess(accessW)
+	return nil
+}
+
 func main() {
 	runtime.GOMAXPROCS(runtime.NumCPU())
 
@@ -68,6 +77,11 @@ func main() {
 		os.Exit(1)
 	}
 
+	if err := InitAccessCfg(cfg); err != nil {
+		fmt.Printf("Error starting service: failed to create access log writer: %v\n", err)
+		os.Exit(1)
+	}
+
 	if cfg.ShortHostnameOverride != "" {
 		staticData.Hostname = cfg.ShortHostnameOverride
 	}