Merge pull request #234 from EUMETNET/issue_233_avoid_excessive_request_logging

Avoid excessive request logging

Author: jo-asplin-met-no

datastore/datastore/README.md

@@ -153,9 +153,10 @@ The following environment variables are supported:
 | `ENABLE_SSL`        | No  | `disable`          | Weather to use ssl for connection |
 | `DYNAMICTIME`     | No  | `true`             | Whether the valid time range is _dynamic_ or _static_ (defined below). |
 | `LOTIME`          | No  | `86400`            | The _earliest_ valid time as seconds to be either [1] subtracted from the current time (if the valid time range is _dynamic_) or [2] added to UNIX epoch (1970-01-01T00:00:00Z) (if the valid time range is _static_). In the case of a _static_ valid time range, the `LOTIME` can optionally be specified as an ISO-8601 datetime of the exact form `2023-10-10T00:00:00Z`. |
-| `HITIME`          | No  | `-600`               | Same as `LOTIME`, but for the _latest_ valid time. Note a default leeway of 10 minutes into the future to reduce risk of missing visual observations. |
+| `HITIME`          | No  | `-600`             | Same as `LOTIME`, but for the _latest_ valid time. Note a default leeway of 10 minutes into the future to reduce risk of missing visual observations. |
 | `CLEANUPINTERVAL` | No  | `86400`            | The minimum time duration in seconds between automatic cleanups (like removing obsolete observations from the physical store). |
 | `PUTOBSLIMIT`     | No  | `100000`           | Maximum number of observations allowed in a single call to `PutObservations`. |
+| `LOGREQSTATS`     | No  | `false`            | Whether request stats (like client IP and processing time) will be logged using log.Printf(). |
 
 **TODO:** Ensure that these variables are [passed properly](https://docs.docker.com/compose/environment-variables/set-environment-variables/) to the relevant `docker compose`
 commands. Any secrets should be passed using a [special mechanism](https://docs.docker.com/compose/use-secrets/), etc.

datastore/datastore/main/main.go

@@ -8,21 +8,24 @@ import (
 	"datastore/storagebackend"
 	"datastore/storagebackend/postgresql"
 	"fmt"
-	"github.com/prometheus/client_golang/prometheus"
-	"github.com/prometheus/client_golang/prometheus/collectors"
-	"github.com/prometheus/client_golang/prometheus/promhttp"
 	"log"
 	"net"
+	"strings"
 	"time"
 
+	"github.com/prometheus/client_golang/prometheus"
+	"github.com/prometheus/client_golang/prometheus/collectors"
+	"github.com/prometheus/client_golang/prometheus/promhttp"
+
 	// gRPC
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/health"
 	"google.golang.org/grpc/health/grpc_health_v1"
 	"google.golang.org/grpc/peer"
 
 	// Monitoring
-	"datastore/metrics"
+	promservermetrics "datastore/metrics"
+
 	grpcprometheus "github.com/grpc-ecosystem/go-grpc-middleware/providers/prometheus"
 
 	_ "expvar"
@@ -44,22 +47,6 @@ func createStorageBackend() (storagebackend.StorageBackend, error) {
 
 func main() {
 
-	reqTimeLogger := func(
-		ctx context.Context, req interface{}, info *grpc.UnaryServerInfo,
-		handler grpc.UnaryHandler) (interface{}, error) {
-		start := time.Now()
-		resp, err := handler(ctx, req)
-		reqTime := time.Since(start)
-		if info.FullMethod != "/grpc.health.v1.Health/Check" {
-			var clientIp = "unknown"
-			if p, ok := peer.FromContext(ctx); ok {
-				clientIp = p.Addr.String()
-			}
-			log.Printf("time for method %q: %d ms. Client ip: %s", info.FullMethod, reqTime.Milliseconds(), clientIp)
-		}
-		return resp, err
-	}
-
 	grpcMetrics := grpcprometheus.NewServerMetrics(
 		grpcprometheus.WithServerHandlingTimeHistogram(
 			grpcprometheus.WithHistogramBuckets([]float64{0.001, 0.01, 0.1, 0.3, 0.6, 1, 3, 6, 9, 20, 30, 60, 90, 120}),
@@ -77,15 +64,45 @@ func main() {
 
 	go promservermetrics.TrackUptime()
 
-	// create gRPC server with middleware
-	server := grpc.NewServer(
-		grpc.ChainUnaryInterceptor(
-			reqTimeLogger,
+	// define RPC interceptor to log request time and client IP
+	reqStatsLogger := func(
+		ctx context.Context, req interface{}, info *grpc.UnaryServerInfo,
+		handler grpc.UnaryHandler) (interface{}, error) {
+		start := time.Now()
+		resp, err := handler(ctx, req)
+		reqTime := time.Since(start)
+		if info.FullMethod != "/grpc.health.v1.Health/Check" {
+			var clientIp = "unknown"
+			if p, ok := peer.FromContext(ctx); ok {
+				clientIp = p.Addr.String()
+			}
+			log.Printf(
+				"time for method %q: %d ms. Client ip: %s",
+				info.FullMethod, reqTime.Milliseconds(), clientIp)
+		}
+		return resp, err
+	}
+
+	// define RPC interceptors to use
+	interceptors := func() []grpc.UnaryServerInterceptor {
+		// initialize with standard interceptors
+		icpts := []grpc.UnaryServerInterceptor{
 			promservermetrics.InFlightRequestInterceptor,
 			promservermetrics.ResponseSizeUnaryInterceptor,
 			grpcMetrics.UnaryServerInterceptor(),
-		),
-	)
+		}
+
+		// optionally prepend interceptor to log request stats (WARNING: may potentially use a lot
+		// of disk space, so disabled by default)
+		logReqStats := strings.ToLower(common.Getenv("LOGREQSTATS", "false"))
+		if (logReqStats != "false") && (logReqStats != "no") && (logReqStats != "0") {
+			icpts = append([]grpc.UnaryServerInterceptor{reqStatsLogger}, icpts...)
+		}
+		return icpts
+	}
+
+	// create gRPC server with middleware
+	server := grpc.NewServer(grpc.ChainUnaryInterceptor(interceptors()...))
 
 	grpcMetrics.InitializeMetrics(server)
 	grpc_health_v1.RegisterHealthServer(server, health.NewServer())

datastore/datastore/storagebackend/postgresql/putobservations.go

@@ -571,7 +571,7 @@ type tsInfo struct {
 // PutObservations ... (see documentation in StorageBackend interface)
 func (sbe *PostgreSQL) PutObservations(request *datastore.PutObsRequest) (codes.Code, string) {
 
-	log.Printf("Entered PutObservations with %v observations...", len(request.Observations))
+	//log.Printf("Entered PutObservations with %v observations...", len(request.Observations))
 
 	// reject call if # of observations exceeds limit
 	if len(request.Observations) > putObsLimit {

docker-compose.yml

@@ -58,6 +58,7 @@ services:
       - HITIME=$HITIME
       - CLEANUPINTERVAL=$CLEANUPINTERVAL
       - PUTOBSLIMIT=$PUTOBSLIMIT
+      - LOGREQSTATS=true
     restart: on-failure
     healthcheck:
       test: