diff --git a/pkg/app/app.go b/pkg/app/app.go index f125cef..859d8c1 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 %d 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 %d 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 %d milliseconds - %s", r.EndTime.Sub(r.StartTime).Milliseconds(), 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(float64(time.Since(now).Milliseconds())) return err } - srv.stats.Tasks.WithLabelValues(fname).Observe(time.Since(now).Seconds()) + 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 67846fc..01b88cc 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,18 +57,25 @@ 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).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(float64(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(float64(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).Milliseconds(), + }).Debugf("HTTP Request to %s complete", r.URL) } } @@ -132,18 +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(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).Seconds()) + 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).Seconds()) + 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, + "duration": time.Since(now).Milliseconds(), + }).Debugf("WASM Module Executed") return rsp, nil }