From fe778de27bbec9170f187440b923451871cc764f Mon Sep 17 00:00:00 2001 From: Benjamin Cane Date: Thu, 23 Nov 2023 09:17:54 -0700 Subject: [PATCH 1/4] Adding some small log additions --- pkg/app/server.go | 17 ++++++++++++++--- 1 file changed, 14 insertions(+), 3 deletions(-) diff --git a/pkg/app/server.go b/pkg/app/server.go index 67846fc..bbb6857 100644 --- a/pkg/app/server.go +++ b/pkg/app/server.go @@ -48,9 +48,8 @@ func (srv *Server) middleware(n httprouter.Handle) httprouter.Handle { "method": r.Method, "remote-addr": r.RemoteAddr, "http-protocol": r.Proto, - "headers": r.Header, "content-length": r.ContentLength, - }).Debugf("HTTP Request to %s", r.URL) + }).Debugf("HTTP Request to %s received", r.URL) // Verify if PProf if isPProf.MatchString(r.URL.Path) && !srv.cfg.GetBool("enable_pprof") { @@ -58,8 +57,8 @@ func (srv *Server) middleware(n httprouter.Handle) httprouter.Handle { "method": r.Method, "remote-addr": r.RemoteAddr, "http-protocol": r.Proto, - "headers": r.Header, "content-length": r.ContentLength, + "duration": time.Since(now).Seconds(), }).Debugf("Request to PProf Address failed, PProf disabled") w.WriteHeader(http.StatusForbidden) @@ -70,6 +69,13 @@ func (srv *Server) middleware(n httprouter.Handle) httprouter.Handle { // Call registered handler n(w, r, ps) srv.stats.Srv.WithLabelValues(r.URL.Path).Observe(time.Since(now).Seconds()) + srv.log.WithFields(logrus.Fields{ + "method": r.Method, + "remote-addr": r.RemoteAddr, + "http-protocol": r.Proto, + "content-length": r.ContentLength, + "duration": time.Since(now).Seconds(), + }).Debugf("HTTP Request to %s complete", r.URL) } } @@ -145,5 +151,10 @@ func (srv *Server) runWASM(module, handler string, rq []byte) ([]byte, error) { // Return results srv.stats.Wasm.WithLabelValues(fmt.Sprintf("%s:%s", module, handler)).Observe(time.Since(now).Seconds()) + srv.log.WithFields(logrus.Fields{ + "module": module, + "handler": handler, + "duration": time.Since(now).Seconds(), + }).Debugf("WASM Module Executed") return rsp, nil } From a4a720a30352125293290e8ef45c79c081337388 Mon Sep 17 00:00:00 2001 From: Benjamin Cane Date: Thu, 23 Nov 2023 09:50:50 -0700 Subject: [PATCH 2/4] Updating metrics from Seconds to Milliseconds --- pkg/app/app.go | 15 +++++++++------ pkg/app/server.go | 16 ++++++++-------- 2 files changed, 17 insertions(+), 14 deletions(-) diff --git a/pkg/app/app.go b/pkg/app/app.go index f125cef..43c9817 100644 --- a/pkg/app/app.go +++ b/pkg/app/app.go @@ -328,14 +328,15 @@ func (srv *Server) Run() error { }, PostFunc: func(r callbacks.CallbackResult) { // Measure Callback Execution time and counts - srv.stats.Callbacks.WithLabelValues(fmt.Sprintf("%s:%s", r.Namespace, r.Operation)).Observe(r.EndTime.Sub(r.StartTime).Seconds()) + srv.stats.Callbacks.WithLabelValues(fmt.Sprintf("%s:%s", r.Namespace, r.Operation)).Observe(float64(r.EndTime.Sub(r.StartTime).Milliseconds())) // Debug logging of callback results srv.log.WithFields(logrus.Fields{ "namespace": r.Namespace, "operation": r.Operation, "error": r.Err, - }).Debugf("Callback returned result after %f seconds", r.EndTime.Sub(r.StartTime).Seconds()) + "duration": r.EndTime.Sub(r.StartTime).Milliseconds(), + }).Debugf("Callback returned result after %f milliseconds", r.EndTime.Sub(r.StartTime).Milliseconds()) // Trace logging of callback results srv.log.WithFields(logrus.Fields{ @@ -343,14 +344,16 @@ func (srv *Server) Run() error { "operation": r.Operation, "input": r.Input, "error": r.Err, - }).Tracef("Callback returned result after %f seconds with output - %s", r.EndTime.Sub(r.StartTime).Seconds(), r.Output) + "duration": r.EndTime.Sub(r.StartTime).Milliseconds(), + }).Tracef("Callback returned result after %f milliseconds with output - %s", r.EndTime.Sub(r.StartTime).Milliseconds(), r.Output) // Log Callback failures as warnings if r.Err != nil { srv.log.WithFields(logrus.Fields{ "namespace": r.Namespace, "operation": r.Operation, - }).Warnf("Callback call resulted in error after %f seconds - %s", r.EndTime.Sub(r.StartTime).Seconds(), r.Err) + "duration": r.EndTime.Sub(r.StartTime).Milliseconds(), + }).Warnf("Callback call resulted in error after %f milliseconds - %s", r.EndTime.Sub(r.StartTime).Millimilliseconds(), r.Err) } }, }) @@ -508,10 +511,10 @@ func (srv *Server) Run() error { srv.log.Tracef("Executing Scheduled Function %s", fname) _, err := srv.runWASM(fname, "handler", []byte("")) if err != nil { - srv.stats.Tasks.WithLabelValues(fname).Observe(time.Since(now).Seconds()) + srv.stats.Tasks.WithLabelValues(fname).Observe(time.Since(now).Milliseconds()) return err } - srv.stats.Tasks.WithLabelValues(fname).Observe(time.Since(now).Seconds()) + srv.stats.Tasks.WithLabelValues(fname).Observe(time.Since(now).Milliseconds()) return nil }, }) diff --git a/pkg/app/server.go b/pkg/app/server.go index bbb6857..cb20c99 100644 --- a/pkg/app/server.go +++ b/pkg/app/server.go @@ -58,23 +58,23 @@ func (srv *Server) middleware(n httprouter.Handle) httprouter.Handle { "remote-addr": r.RemoteAddr, "http-protocol": r.Proto, "content-length": r.ContentLength, - "duration": time.Since(now).Seconds(), + "duration": time.Since(now).Milliseconds(), }).Debugf("Request to PProf Address failed, PProf disabled") w.WriteHeader(http.StatusForbidden) - srv.stats.Srv.WithLabelValues(r.URL.Path).Observe(time.Since(now).Seconds()) + srv.stats.Srv.WithLabelValues(r.URL.Path).Observe(time.Since(now).Milliseconds()) return } // Call registered handler n(w, r, ps) - srv.stats.Srv.WithLabelValues(r.URL.Path).Observe(time.Since(now).Seconds()) + srv.stats.Srv.WithLabelValues(r.URL.Path).Observe(time.Since(now).Milliseconds()) srv.log.WithFields(logrus.Fields{ "method": r.Method, "remote-addr": r.RemoteAddr, "http-protocol": r.Proto, "content-length": r.ContentLength, - "duration": time.Since(now).Seconds(), + "duration": time.Since(now).Milliseconds(), }).Debugf("HTTP Request to %s complete", r.URL) } } @@ -138,23 +138,23 @@ func (srv *Server) runWASM(module, handler string, rq []byte) ([]byte, error) { // Fetch Module and run with payload m, err := srv.engine.Module(module) if err != nil { - srv.stats.Wasm.WithLabelValues(fmt.Sprintf("%s:%s", module, handler)).Observe(time.Since(now).Seconds()) + srv.stats.Wasm.WithLabelValues(fmt.Sprintf("%s:%s", module, handler)).Observe(time.Since(now).Milliseconds()) return []byte(""), fmt.Errorf("unable to load wasi environment - %s", err) } // Execute the WASM Handler rsp, err := m.Run(handler, rq) if err != nil { - srv.stats.Wasm.WithLabelValues(fmt.Sprintf("%s:%s", module, handler)).Observe(time.Since(now).Seconds()) + srv.stats.Wasm.WithLabelValues(fmt.Sprintf("%s:%s", module, handler)).Observe(time.Since(now).Milliseconds()) return rsp, fmt.Errorf("failed to execute wasm module - %s", err) } // Return results - srv.stats.Wasm.WithLabelValues(fmt.Sprintf("%s:%s", module, handler)).Observe(time.Since(now).Seconds()) + srv.stats.Wasm.WithLabelValues(fmt.Sprintf("%s:%s", module, handler)).Observe(time.Since(now).Milliseconds()) srv.log.WithFields(logrus.Fields{ "module": module, "handler": handler, - "duration": time.Since(now).Seconds(), + "duration": time.Since(now).Milliseconds(), }).Debugf("WASM Module Executed") return rsp, nil } From 02a1ab219ba7d5230df158d748b5a2db7975ad48 Mon Sep 17 00:00:00 2001 From: Benjamin Cane Date: Thu, 23 Nov 2023 09:55:34 -0700 Subject: [PATCH 3/4] Fixing float to decimal --- pkg/app/app.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/pkg/app/app.go b/pkg/app/app.go index 43c9817..5efd9ef 100644 --- a/pkg/app/app.go +++ b/pkg/app/app.go @@ -336,7 +336,7 @@ func (srv *Server) Run() error { "operation": r.Operation, "error": r.Err, "duration": r.EndTime.Sub(r.StartTime).Milliseconds(), - }).Debugf("Callback returned result after %f milliseconds", r.EndTime.Sub(r.StartTime).Milliseconds()) + }).Debugf("Callback returned result after %d milliseconds", r.EndTime.Sub(r.StartTime).Milliseconds()) // Trace logging of callback results srv.log.WithFields(logrus.Fields{ @@ -345,7 +345,7 @@ func (srv *Server) Run() error { "input": r.Input, "error": r.Err, "duration": r.EndTime.Sub(r.StartTime).Milliseconds(), - }).Tracef("Callback returned result after %f milliseconds with output - %s", r.EndTime.Sub(r.StartTime).Milliseconds(), r.Output) + }).Tracef("Callback returned result after %d milliseconds with output - %s", r.EndTime.Sub(r.StartTime).Milliseconds(), r.Output) // Log Callback failures as warnings if r.Err != nil { @@ -353,7 +353,7 @@ func (srv *Server) Run() error { "namespace": r.Namespace, "operation": r.Operation, "duration": r.EndTime.Sub(r.StartTime).Milliseconds(), - }).Warnf("Callback call resulted in error after %f milliseconds - %s", r.EndTime.Sub(r.StartTime).Millimilliseconds(), r.Err) + }).Warnf("Callback call resulted in error after %d milliseconds - %s", r.EndTime.Sub(r.StartTime).Millimilliseconds(), r.Err) } }, }) From 8312882ec43813a6564ae2d54d53f98a712ad42f Mon Sep 17 00:00:00 2001 From: Benjamin Cane Date: Thu, 23 Nov 2023 10:00:32 -0700 Subject: [PATCH 4/4] Fixing missing floats --- pkg/app/app.go | 12 ++++++------ pkg/app/server.go | 10 +++++----- 2 files changed, 11 insertions(+), 11 deletions(-) diff --git a/pkg/app/app.go b/pkg/app/app.go index 5efd9ef..859d8c1 100644 --- a/pkg/app/app.go +++ b/pkg/app/app.go @@ -335,7 +335,7 @@ func (srv *Server) Run() error { "namespace": r.Namespace, "operation": r.Operation, "error": r.Err, - "duration": r.EndTime.Sub(r.StartTime).Milliseconds(), + "duration": r.EndTime.Sub(r.StartTime).Milliseconds(), }).Debugf("Callback returned result after %d milliseconds", r.EndTime.Sub(r.StartTime).Milliseconds()) // Trace logging of callback results @@ -344,7 +344,7 @@ func (srv *Server) Run() error { "operation": r.Operation, "input": r.Input, "error": r.Err, - "duration": r.EndTime.Sub(r.StartTime).Milliseconds(), + "duration": r.EndTime.Sub(r.StartTime).Milliseconds(), }).Tracef("Callback returned result after %d milliseconds with output - %s", r.EndTime.Sub(r.StartTime).Milliseconds(), r.Output) // Log Callback failures as warnings @@ -352,8 +352,8 @@ func (srv *Server) Run() error { srv.log.WithFields(logrus.Fields{ "namespace": r.Namespace, "operation": r.Operation, - "duration": r.EndTime.Sub(r.StartTime).Milliseconds(), - }).Warnf("Callback call resulted in error after %d milliseconds - %s", r.EndTime.Sub(r.StartTime).Millimilliseconds(), r.Err) + "duration": r.EndTime.Sub(r.StartTime).Milliseconds(), + }).Warnf("Callback call resulted in error after %d milliseconds - %s", r.EndTime.Sub(r.StartTime).Milliseconds(), r.Err) } }, }) @@ -511,10 +511,10 @@ func (srv *Server) Run() error { srv.log.Tracef("Executing Scheduled Function %s", fname) _, err := srv.runWASM(fname, "handler", []byte("")) if err != nil { - srv.stats.Tasks.WithLabelValues(fname).Observe(time.Since(now).Milliseconds()) + srv.stats.Tasks.WithLabelValues(fname).Observe(float64(time.Since(now).Milliseconds())) return err } - srv.stats.Tasks.WithLabelValues(fname).Observe(time.Since(now).Milliseconds()) + srv.stats.Tasks.WithLabelValues(fname).Observe(float64(time.Since(now).Milliseconds())) return nil }, }) diff --git a/pkg/app/server.go b/pkg/app/server.go index cb20c99..01b88cc 100644 --- a/pkg/app/server.go +++ b/pkg/app/server.go @@ -62,13 +62,13 @@ func (srv *Server) middleware(n httprouter.Handle) httprouter.Handle { }).Debugf("Request to PProf Address failed, PProf disabled") w.WriteHeader(http.StatusForbidden) - srv.stats.Srv.WithLabelValues(r.URL.Path).Observe(time.Since(now).Milliseconds()) + srv.stats.Srv.WithLabelValues(r.URL.Path).Observe(float64(time.Since(now).Milliseconds())) return } // Call registered handler n(w, r, ps) - srv.stats.Srv.WithLabelValues(r.URL.Path).Observe(time.Since(now).Milliseconds()) + srv.stats.Srv.WithLabelValues(r.URL.Path).Observe(float64(time.Since(now).Milliseconds())) srv.log.WithFields(logrus.Fields{ "method": r.Method, "remote-addr": r.RemoteAddr, @@ -138,19 +138,19 @@ func (srv *Server) runWASM(module, handler string, rq []byte) ([]byte, error) { // Fetch Module and run with payload m, err := srv.engine.Module(module) if err != nil { - srv.stats.Wasm.WithLabelValues(fmt.Sprintf("%s:%s", module, handler)).Observe(time.Since(now).Milliseconds()) + srv.stats.Wasm.WithLabelValues(fmt.Sprintf("%s:%s", module, handler)).Observe(float64(time.Since(now).Milliseconds())) return []byte(""), fmt.Errorf("unable to load wasi environment - %s", err) } // Execute the WASM Handler rsp, err := m.Run(handler, rq) if err != nil { - srv.stats.Wasm.WithLabelValues(fmt.Sprintf("%s:%s", module, handler)).Observe(time.Since(now).Milliseconds()) + srv.stats.Wasm.WithLabelValues(fmt.Sprintf("%s:%s", module, handler)).Observe(float64(time.Since(now).Milliseconds())) return rsp, fmt.Errorf("failed to execute wasm module - %s", err) } // Return results - srv.stats.Wasm.WithLabelValues(fmt.Sprintf("%s:%s", module, handler)).Observe(time.Since(now).Milliseconds()) + srv.stats.Wasm.WithLabelValues(fmt.Sprintf("%s:%s", module, handler)).Observe(float64(time.Since(now).Milliseconds())) srv.log.WithFields(logrus.Fields{ "module": module, "handler": handler,