use new logger (#861)

* use new logger. also fix #860

* fix fortio/proxy#181 + cover deprecated LogAndCall

* latest cli/log

* test LogAndCall with EchoHandler

* linter

* avoid infinite recursion

* show all done at end of tsv download

* released version of log,cli,scli + updates others + linter fix

fhttp/http_server.go

@@ -86,9 +86,17 @@ func QueryArg(r *http.Request, key string) string {
 
 // EchoHandler is an http server handler echoing back the input.
 func EchoHandler(w http.ResponseWriter, r *http.Request) {
+	// EchoHandler is an http server handler echoing back the input.
 	if log.LogVerbose() {
-		log.LogRequest(r, "Echo") // will also print headers
+		log.LogAndCall("Echo", func(w http.ResponseWriter, r *http.Request) {
+			echoHandler(w, r)
+		})(w, r)
+		return
 	}
+	echoHandler(w, r)
+}
+
+func echoHandler(w http.ResponseWriter, r *http.Request) {
 	defaultParams := DefaultEchoServerParams.Get()
 	hasQuestionMark := strings.Contains(r.RequestURI, "?")
 	if !hasQuestionMark && len(defaultParams) > 0 {
@@ -487,11 +495,11 @@ func ServeTCP(port, debugPath string) (*http.ServeMux, *net.TCPAddr) {
 // SetupPPROF add pprof to the mux (mirror the init() of http pprof).
 func SetupPPROF(mux *http.ServeMux) {
 	log.Warnf("pprof endpoints enabled on /debug/pprof/*")
-	mux.HandleFunc("/debug/pprof/", LogAndCall("pprof:index", pprof.Index))
-	mux.HandleFunc("/debug/pprof/cmdline", LogAndCall("pprof:cmdline", pprof.Cmdline))
-	mux.HandleFunc("/debug/pprof/profile", LogAndCall("pprof:profile", pprof.Profile))
-	mux.HandleFunc("/debug/pprof/symbol", LogAndCall("pprof:symbol", pprof.Symbol))
-	mux.HandleFunc("/debug/pprof/trace", LogAndCall("pprof:trace", pprof.Trace))
+	mux.HandleFunc("/debug/pprof/", log.LogAndCall("pprof:index", pprof.Index))
+	mux.HandleFunc("/debug/pprof/cmdline", log.LogAndCall("pprof:cmdline", pprof.Cmdline))
+	mux.HandleFunc("/debug/pprof/profile", log.LogAndCall("pprof:profile", pprof.Profile))
+	mux.HandleFunc("/debug/pprof/symbol", log.LogAndCall("pprof:symbol", pprof.Symbol))
+	mux.HandleFunc("/debug/pprof/trace", log.LogAndCall("pprof:trace", pprof.Trace))
 }
 
 // -- Fetch er (simple http proxy) --
@@ -601,18 +609,15 @@ func RedirectToHTTPS(port string) net.Addr {
 	return HTTPServerWithHandler("https redirector", port, http.HandlerFunc(RedirectToHTTPSHandler))
 }
 
-// LogAndCall wraps an HTTP handler to log the request first.
+// Deprecated: use fortio.org/log.LogAndCall().
 func LogAndCall(msg string, hf http.HandlerFunc) http.HandlerFunc {
-	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		log.LogRequest(r, msg)
-		hf(w, r)
-	})
+	return log.LogAndCall(msg, hf)
 }
 
 // LogAndCallNoArg is LogAndCall for functions not needing the response/request args.
+// Short cut for:
+//
+//	log.LogAndCall(msg, func(_ http.ResponseWriter, _ *http.Request) { f() })
 func LogAndCallNoArg(msg string, f func()) http.HandlerFunc {
-	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		log.LogRequest(r, msg)
-		f()
-	})
+	return log.LogAndCall(msg, func(_ http.ResponseWriter, _ *http.Request) { f() })
 }

fhttp/http_test.go

@@ -1445,6 +1445,22 @@ func TestLogAndCallNoArg(t *testing.T) {
 	}
 }
 
+func TestLogAndCallDeprecated(t *testing.T) {
+	mux, addrN := HTTPServer("test call no arg", "0")
+	called := false
+	mux.HandleFunc("/testing123/logAndCall",
+		LogAndCall("test log and call", func(http.ResponseWriter, *http.Request) { called = true }))
+	addr := addrN.(*net.TCPAddr)
+	url := fmt.Sprintf("localhost:%d/testing123/logAndCall", addr.Port)
+	code, data := Fetch(&HTTPOptions{URL: url})
+	if code != 200 {
+		t.Errorf("error fetching %s: %v %s", url, code, DebugSummary(data, 256))
+	}
+	if !called {
+		t.Errorf("handler side effect not detected")
+	}
+}
+
 func TestRedirector(t *testing.T) {
 	addr := RedirectToHTTPS(":0")
 	relativeURL := "/foo/bar?some=param&anotherone"

go.mod

@@ -4,10 +4,10 @@ go 1.18
 
 require (
 	fortio.org/assert v1.2.0
-	fortio.org/cli v1.4.2
+	fortio.org/cli v1.5.0
 	fortio.org/dflag v1.7.0
-	fortio.org/log v1.11.0
-	fortio.org/scli v1.12.1
+	fortio.org/log v1.12.0
+	fortio.org/scli v1.13.0
 	fortio.org/sets v1.0.3
 	fortio.org/testscript v0.3.1
 	fortio.org/version v1.0.3
@@ -28,11 +28,12 @@ require (
 //)
 
 require (
+	fortio.org/struct2env v0.4.0 // indirect
 	github.com/fsnotify/fsnotify v1.7.0 // indirect
 	golang.org/x/exp v0.0.0-20231110203233-9a3e6036ecaa // indirect
 	golang.org/x/sys v0.14.0 // indirect
 	golang.org/x/text v0.14.0 // indirect
 	golang.org/x/tools v0.15.0 // indirect
-	google.golang.org/genproto/googleapis/rpc v0.0.0-20231106174013-bbf56f31fb17 // indirect
+	google.golang.org/genproto/googleapis/rpc v0.0.0-20231120223509-83a465c0220f // indirect
 	google.golang.org/protobuf v1.31.0 // indirect
 )

go.sum

@@ -1,15 +1,17 @@
 fortio.org/assert v1.2.0 h1:XscfvR8yp4xW7OMCvNbCsieRFDxlwdEcb69+JZRp6LA=
 fortio.org/assert v1.2.0/go.mod h1:039mG+/iYDPO8Ibx8TrNuJCm2T2SuhwRI3uL9nHTTls=
-fortio.org/cli v1.4.2 h1:pCYVPk5FpQuJtD31f9CG8sdgoTOWdv9Gls8As/MLJhU=
-fortio.org/cli v1.4.2/go.mod h1:VGqFDEKpA6u3NbTM3aSz2lZfAYKnGaszl1pLxbBhxsY=
+fortio.org/cli v1.5.0 h1:hKiXZ6jWzLHCVInrRm8F3BI3nyj0EpM5rAYFUp/d8gs=
+fortio.org/cli v1.5.0/go.mod h1:Tp7AypudP1mJomTUN/J/vlOTlZDWTMsok09MMyA99ow=
 fortio.org/dflag v1.7.0 h1:4Vpo5hMly0rx9VMuyBaDGFK1Mx2S3qjxx1iAIA3KBgU=
 fortio.org/dflag v1.7.0/go.mod h1:FUxv/s3DXhCpy7GsuZa4FJWLR92gsYvG3ylkia8MbBM=
-fortio.org/log v1.11.0 h1:w7ueGPGbXz0A3+ApMz/5Q9gwEMrwSo/ohTlLo2Um6dU=
-fortio.org/log v1.11.0/go.mod h1:u/8/2lyczXq52aT5Nw6reD+3cR6m/EbS2jBiIYhgiTU=
-fortio.org/scli v1.12.1 h1:F+E6dPOCskBXpYNDJIU12tzY4Y8r1qTHa5Ge/CTLZtA=
-fortio.org/scli v1.12.1/go.mod h1:CkLJR1sT9rZGsvVC9eouE1K0Ee4+p0lChiwO6Vw04lo=
+fortio.org/log v1.12.0 h1:5Yg4pL9Pp0jcWeJYixm2xikMCldVaSDMgDFDmQJZfho=
+fortio.org/log v1.12.0/go.mod h1:1tMBG/Elr6YqjmJCWiejJp2FPvXg7/9UAN0Rfpkyt1o=
+fortio.org/scli v1.13.0 h1:iVxjSx5ng827RvBfZQCtn6GGiPr71NcYkw80jQ2Pmik=
+fortio.org/scli v1.13.0/go.mod h1:LSXkC8KIIvT8YhD1dgVKPgmzSrotT/nepPwyZ+I04p8=
 fortio.org/sets v1.0.3 h1:HzewdGjH69YmyW06yzplL35lGr+X4OcqQt0qS6jbaO4=
 fortio.org/sets v1.0.3/go.mod h1:QZVj0r6KP/ZD9ebySW9SgxVNy/NjghUfyHW9NN+WU+4=
+fortio.org/struct2env v0.4.0 h1:k5alSOTf3YHiB3MuacjDHQ3YhVWvNZ95ZP/a6MqvyLo=
+fortio.org/struct2env v0.4.0/go.mod h1:lENUe70UwA1zDUCX+8AsO663QCFqYaprk5lnPhjD410=
 fortio.org/testscript v0.3.1 h1:MmRO64AsmzaU1KlYMzAbotJIMKRGxD1XXssJnBRiMGQ=
 fortio.org/testscript v0.3.1/go.mod h1:7OJ+U4avooRNqc7p/VHKJadYgj9fA6+N0SbGU8FVWGs=
 fortio.org/version v1.0.3 h1:5gJ3plj6isAOMq52cI5ifo4cC+QHmJF76Wevc5Cp4x0=
@@ -34,8 +36,8 @@ golang.org/x/text v0.14.0/go.mod h1:18ZOQIKpY8NJVqYksKHtTdi31H5itFRjB5/qKTNYzSU=
 golang.org/x/tools v0.15.0 h1:zdAyfUGbYmuVokhzVmghFl2ZJh5QhcfebBgmVPFYA+8=
 golang.org/x/tools v0.15.0/go.mod h1:hpksKq4dtpQWS1uQ61JkdqWM3LscIS6Slf+VVkm+wQk=
 golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
-google.golang.org/genproto/googleapis/rpc v0.0.0-20231106174013-bbf56f31fb17 h1:Jyp0Hsi0bmHXG6k9eATXoYtjd6e2UzZ1SCn/wIupY14=
-google.golang.org/genproto/googleapis/rpc v0.0.0-20231106174013-bbf56f31fb17/go.mod h1:oQ5rr10WTTMvP4A36n8JpR1OrO1BEiV4f78CneXZxkA=
+google.golang.org/genproto/googleapis/rpc v0.0.0-20231120223509-83a465c0220f h1:ultW7fxlIvee4HYrtnaRPon9HpEgFk5zYpmfMgtKB5I=
+google.golang.org/genproto/googleapis/rpc v0.0.0-20231120223509-83a465c0220f/go.mod h1:L9KNLi232K1/xB6f7AlSX692koaRnKaWSR0stBki0Yc=
 google.golang.org/grpc v1.59.0 h1:Z5Iec2pjwb+LEOqzpB2MR12/eKFhDPhuqW91O+4bwUk=
 google.golang.org/grpc v1.59.0/go.mod h1:aUPDwccQo6OTjy7Hct4AfBPD1GptF4fyUjIkQ9YtF98=
 google.golang.org/protobuf v1.26.0-rc.1/go.mod h1:jlhhOSvTdKEhbULTjvd4ARK9grFBp09yW+WbY/TyQbw=

rapi/data.go

@@ -147,7 +147,11 @@ func GetDataURL(r *http.Request) string {
 		if len(proto) == 0 {
 			proto = "http"
 		}
-		url = proto + "://" + r.Host
+		fwdHost := r.Header.Get("X-Forwarded-Host")
+		if len(fwdHost) == 0 {
+			fwdHost = r.Host
+		}
+		url = proto + "://" + fwdHost
 	}
 	return url + uiPath + DataDir // base has been cleaned of trailing / in fortio_main
 }

ui/templates/browse.html

@@ -18,6 +18,7 @@
 <h1>Φορτίο (fortio) v{{.Version}}{{.Extra}}</h1>
 <script src="{{.Version}}/static/js/fortio_chart.js"></script>
 <script>
+const RAPI_DATA_DIR='data/'
 var res
 var data
 function fortio_load(url) {
@@ -30,7 +31,7 @@ <h1>Φορτίο (fortio) v{{.Version}}{{.Extra}}</h1>
     return
   }
   if (list.length == 1) {
-    fetch(rapi.DataDir+url).then(doc => doc.json()).then((out) => {
+    fetch(RAPI_DATA_DIR+url).then(doc => doc.json()).then((out) => {
       res = out
       data = fortioResultToJsChartData(res)
       showChart(data)
@@ -42,12 +43,12 @@ <h1>Φορτίο (fortio) v{{.Version}}{{.Extra}}</h1>
     urldiv.innerHTML = "Multiple runs (URL is a permalink)..."
     if (list.length == 2) {
       var urlA = list[0].value
-      var dataPromiseA = fetch(rapi.DataDir+urlA)
+      var dataPromiseA = fetch(RAPI_DATA_DIR+urlA)
           .then(response => response.json())
           .then(fortioResult => fortioResultToJsChartData(fortioResult))
 
       var urlB = list[1].value
-      var dataPromiseB = fetch(rapi.DataDir+urlB)
+      var dataPromiseB = fetch(RAPI_DATA_DIR+urlB)
           .then(response => response.json())
           .then(fortioResult => fortioResultToJsChartData(fortioResult))
 
@@ -62,7 +63,7 @@ <h1>Φορτίο (fortio) v{{.Version}}{{.Extra}}</h1>
       for (var i = 0, len = list.length; i < len; i++) {
         var v = list[len-i-1].value;
         (function (idx, u) {
-          promises.push(fetch(rapi.DataDir+u).then(doc => doc.json()).then((out) => {
+          promises.push(fetch(RAPI_DATA_DIR+u).then(doc => doc.json()).then((out) => {
             fortioAddToMultiResult(idx, out)
           }))
         })(i, v)

ui/uihandler.go

@@ -101,9 +101,9 @@ const (
 //
 //nolint:funlen, nestif // should be refactored indeed (TODO)
 func Handler(w http.ResponseWriter, r *http.Request) {
-	log.LogRequest(r, "UI")
+	// logging of request and response is done by log.LogAndCall in mux setup
 	if r.Method != http.MethodPost && r.Method != http.MethodGet {
-		// method is already logged by LogRequest so we just return (for HEAD etc... see Issue#830)
+		// method will be logged by LogAndCall so we just return (for HEAD etc... see Issue#830)
 		return
 	}
 	mode := menu
@@ -323,7 +323,7 @@ type ChartOptions struct {
 
 // BrowseHandler handles listing and rendering the JSON results.
 func BrowseHandler(w http.ResponseWriter, r *http.Request) {
-	log.LogRequest(r, "Browse")
+	// logging of request and response is done by log.LogAndCall in mux setup
 	path := r.URL.Path
 	if (path != uiPath) && (path != (uiPath + "browse")) {
 		if strings.HasPrefix(path, "/fortio") {
@@ -387,8 +387,7 @@ func BrowseHandler(w http.ResponseWriter, r *http.Request) {
 
 // LogAndAddCacheControl logs the request and wrapps an HTTP handler to add a Cache-Control header for static files.
 func LogAndAddCacheControl(h http.Handler) http.Handler {
-	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		log.LogRequest(r, "Static")
+	return log.LogAndCall("static", func(w http.ResponseWriter, r *http.Request) {
 		path := r.URL.Path
 		if path == faviconPath {
 			r.URL.Path = "/static/img" + faviconPath // fortio/version expected to be stripped already
@@ -439,7 +438,7 @@ func Sync(out io.Writer, u string, datadir string) bool {
 
 // SyncHandler handles syncing/downloading from tsv url.
 func SyncHandler(w http.ResponseWriter, r *http.Request) {
-	log.LogRequest(r, "Sync")
+	// logging of request and response is done by log.LogAndCall in mux setup
 	flusher, ok := w.(http.Flusher)
 	if !ok {
 		log.Fatalf("expected http.ResponseWriter to be an http.Flusher")
@@ -518,6 +517,7 @@ func processTSV(ctx context.Context, w http.ResponseWriter, client *fhttp.Client
 		_, _ = w.Write([]byte(fmt.Sprintf("</tr><script>setPB(%d)</script>\n", i+2)))
 		flusher.Flush()
 	}
+	_, _ = w.Write([]byte("</table><p>All done!\n"))
 }
 
 // ListBucketResult is the minimum we need out of s3 xml results.
@@ -676,7 +676,7 @@ func Serve(hook bincommon.FortioHook, cfg *ServerConfig) bool {
 	debugPath = cfg.DebugPath
 	echoPath = fhttp.EchoDebugPath(debugPath)
 	metricsPath = getMetricsPath(debugPath)
-	mux.HandleFunc(uiPath, Handler)
+	mux.HandleFunc(uiPath, log.LogAndCall("UI", Handler))
 	fetchPath = uiPath + fetchURI
 	// For backward compatibility with http:// only fetcher
 	mux.Handle(fetchPath, http.StripPrefix(fetchPath, http.HandlerFunc(fhttp.FetcherHandler)))
@@ -709,13 +709,13 @@ func Serve(hook bincommon.FortioHook, cfg *ServerConfig) bool {
 	if err != nil {
 		log.Critf("Unable to parse browse template: %v", err)
 	} else {
-		mux.HandleFunc(uiPath+"browse", BrowseHandler)
+		mux.HandleFunc(uiPath+"browse", log.LogAndCall("browse", BrowseHandler))
 	}
 	syncTemplate, err = template.ParseFS(templateFS, "templates/sync.html", "templates/header.html")
 	if err != nil {
 		log.Critf("Unable to parse sync template: %v", err)
 	} else {
-		mux.HandleFunc(uiPath+"sync", SyncHandler)
+		mux.HandleFunc(uiPath+"sync", log.LogAndCall("Sync", SyncHandler))
 	}
 	dflagsPath := uiPath + "flags"
 	dflagSetURL := dflagsPath + "/set"