Small log additions and moving metrics from Seconds to Milliseconds

pkg/app/app.go

@@ -328,29 +328,32 @@
 		},
 		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{
 				"namespace": r.Namespace,
 				"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 @@
 							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
 						},
 					})

pkg/app/server.go

@@ -48,28 +48,34 @@ 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") {
 			srv.log.WithFields(logrus.Fields{
 				"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
 }