db: less logging when opening a database connection

chdb/db.go

@@ -38,10 +38,9 @@ func New(ctx context.Context, dbConfigPath string) (*ClickHouse, error) {
 }
 
 func setupClickhouse(ctx context.Context, configFile string) (*ClickHouse, error) {
-
 	log := logger.FromContext(ctx)
 
-	log.InfoContext(ctx, "opening config", "file", configFile)
+	log.DebugContext(ctx, "opening ch config", "file", configFile)
 
 	dbFile, err := os.Open(configFile)
 	if err != nil {
@@ -76,6 +75,7 @@ func open(ctx context.Context, cfg DBConfig) (clickhouse.Conn, error) {
 
 	conn, err := clickhouse.Open(&clickhouse.Options{
 		Addr:     []string{cfg.Host + ":9000"},
+		Protocol: clickhouse.Native,
 		Auth: clickhouse.Auth{
 			Database: cfg.Database,
 			Username: "default",
@@ -93,9 +93,9 @@ func open(ctx context.Context, cfg DBConfig) (clickhouse.Conn, error) {
 			Method: clickhouse.CompressionLZ4,
 		},
 		DialTimeout:          time.Second * 5,
-		MaxOpenConns:         5,
+		MaxOpenConns:         8,
-		MaxIdleConns:         5,
+		MaxIdleConns:         3,
-		ConnMaxLifetime:      time.Duration(10) * time.Minute,
+		ConnMaxLifetime:      5 * time.Minute,
 		ConnOpenStrategy:     clickhouse.ConnOpenInOrder,
 		BlockBufferSize:      10,
 		MaxCompressionBuffer: 10240,

go.mod

@@ -12,11 +12,11 @@ require (
 	github.com/hashicorp/go-retryablehttp v0.7.7
 	github.com/labstack/echo-contrib v0.17.2
 	github.com/labstack/echo/v4 v4.13.3
-	github.com/samber/slog-echo v1.14.8
+	github.com/samber/slog-echo v1.15.0
 	github.com/spf13/cobra v1.8.1
 	github.com/stretchr/testify v1.10.0
 	go.ntppool.org/api v0.3.4
-	go.ntppool.org/common v0.3.1
+	go.ntppool.org/common v0.3.2-0.20250103130152-f6d160a7f8f4
 	go.opentelemetry.io/contrib/instrumentation/github.com/labstack/echo/otelecho v0.58.0
 	go.opentelemetry.io/contrib/instrumentation/net/http/httptrace/otelhttptrace v0.58.0
 	go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.58.0
@@ -58,7 +58,7 @@ require (
 	github.com/prometheus/procfs v0.15.1 // indirect
 	github.com/remychantenay/slog-otel v1.3.2 // indirect
 	github.com/samber/lo v1.47.0 // indirect
-	github.com/samber/slog-multi v1.2.4 // indirect
+	github.com/samber/slog-multi v1.3.3 // indirect
 	github.com/segmentio/asm v1.2.0 // indirect
 	github.com/shopspring/decimal v1.4.0 // indirect
 	github.com/spf13/pflag v1.0.5 // indirect
@@ -89,11 +89,11 @@ require (
 	golang.org/x/crypto v0.31.0 // indirect
 	golang.org/x/mod v0.22.0 // indirect
 	golang.org/x/net v0.33.0 // indirect
-	golang.org/x/sys v0.28.0 // indirect
+	golang.org/x/sys v0.29.0 // indirect
 	golang.org/x/text v0.21.0 // indirect
-	golang.org/x/time v0.8.0 // indirect
+	golang.org/x/time v0.9.0 // indirect
-	google.golang.org/genproto/googleapis/api v0.0.0-20241223144023-3abc09e42ca8 // indirect
+	google.golang.org/genproto/googleapis/api v0.0.0-20250102185135-69823020774d // indirect
-	google.golang.org/genproto/googleapis/rpc v0.0.0-20241223144023-3abc09e42ca8 // indirect
+	google.golang.org/genproto/googleapis/rpc v0.0.0-20250102185135-69823020774d // indirect
 	google.golang.org/grpc v1.69.2 // indirect
 	google.golang.org/protobuf v1.36.1 // indirect
 )

go.sum

@@ -104,10 +104,10 @@ github.com/rogpeppe/go-internal v1.13.1/go.mod h1:uMEvuHeurkdAXX61udpOXGD/AzZDWN
 github.com/russross/blackfriday/v2 v2.1.0/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM=
 github.com/samber/lo v1.47.0 h1:z7RynLwP5nbyRscyvcD043DWYoOcYRv3mV8lBeqOCLc=
 github.com/samber/lo v1.47.0/go.mod h1:RmDH9Ct32Qy3gduHQuKJ3gW1fMHAnE/fAzQuf6He5cU=
-github.com/samber/slog-echo v1.14.8 h1:R7RF2LWEepsKtC7i6A6o9peS3Rz5HO8+H8OD+8mPD1I=
+github.com/samber/slog-echo v1.15.0 h1:xzdHyyM9bTyQpEFIGHi6oERY1puUh5zYxiRhOhzT4MA=
-github.com/samber/slog-echo v1.14.8/go.mod h1:K21nbusPmai/MYm8PFactmZoFctkMmkeaTdXXyvhY1c=
+github.com/samber/slog-echo v1.15.0/go.mod h1:K21nbusPmai/MYm8PFactmZoFctkMmkeaTdXXyvhY1c=
-github.com/samber/slog-multi v1.2.4 h1:k9x3JAWKJFPKffx+oXZ8TasaNuorIW4tG+TXxkt6Ry4=
+github.com/samber/slog-multi v1.3.3 h1:qhFXaYdW73FIWLt8SrXMXfPwY58NpluzKDwRdPvhWWY=
-github.com/samber/slog-multi v1.2.4/go.mod h1:ACuZ5B6heK57TfMVkVknN2UZHoFfjCwRxR0Q2OXKHlo=
+github.com/samber/slog-multi v1.3.3/go.mod h1:ACuZ5B6heK57TfMVkVknN2UZHoFfjCwRxR0Q2OXKHlo=
 github.com/segmentio/asm v1.2.0 h1:9BQrFxC+YOHJlTlHGkTrFWf59nbL3XnCoFLTwDCI7ys=
 github.com/segmentio/asm v1.2.0/go.mod h1:BqMnlJP91P8d+4ibuonYZw9mfnzI9HfxselHZr5aAcs=
 github.com/shopspring/decimal v1.4.0 h1:bxl37RwXBklmTi0C79JfXCEBD1cqqHt0bbgBAGFp81k=
@@ -138,10 +138,8 @@ github.com/yuin/goldmark v1.2.1/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9dec
 go.mongodb.org/mongo-driver v1.11.4/go.mod h1:PTSz5yu21bkT/wXpkS7WR5f0ddqw5quethTUn9WM+2g=
 go.ntppool.org/api v0.3.4 h1:KeRyFhIRkjJwZif7hkpqEDEBmukyYGiOi2Fd6j3UzQ0=
 go.ntppool.org/api v0.3.4/go.mod h1:LFLAwnrc/JyjzKnjgf8tCOJhps6oFIjuledS3PCx7xc=
-go.ntppool.org/common v0.3.0 h1:IuSmyjEhI1F3tr5kc5MqlR4cy5y0o5f3EKvC7Koc6rs=
+go.ntppool.org/common v0.3.2-0.20250103130152-f6d160a7f8f4 h1:ku0m24CFP9UL8MZbcW01M7pqqnyCgzYTvLw74Uw2BYA=
-go.ntppool.org/common v0.3.0/go.mod h1:25pUt3YUusF1MY0nsljjskcMMeTvKZszVvNsubvWhSM=
+go.ntppool.org/common v0.3.2-0.20250103130152-f6d160a7f8f4/go.mod h1:1SKjFBH9AL7Fj2S0zy41isHzV6dTC+6yIKD5QDtX8aY=
-go.ntppool.org/common v0.3.1 h1:JaJpS3m8oAc9jH0yhHYJnjOC+RUzxx/F+EDe0QON4eQ=
-go.ntppool.org/common v0.3.1/go.mod h1:1SKjFBH9AL7Fj2S0zy41isHzV6dTC+6yIKD5QDtX8aY=
 go.opentelemetry.io/auto/sdk v1.1.0 h1:cH53jehLUN6UFLY71z+NDOiNJqDdPRaXzTel0sJySYA=
 go.opentelemetry.io/auto/sdk v1.1.0/go.mod h1:3wSPjt5PWp2RhlCcmmOial7AvC4DQqZb7a7wCow3W8A=
 go.opentelemetry.io/contrib/bridges/otelslog v0.8.0 h1:G3sKsNueSdxuACINFxKrQeimAIst0A5ytA2YJH+3e1c=
@@ -229,8 +227,8 @@ golang.org/x/sys v0.0.0-20210423082822-04245dca01da/go.mod h1:h1NjWce9XRLGQEsW7w
 golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
-golang.org/x/sys v0.28.0 h1:Fksou7UEQUWlKvIdsqzJmUmCX3cZuD2+P3XyyzwMhlA=
+golang.org/x/sys v0.29.0 h1:TPYlXGxvx1MGTn2GiZDhnjPA9wZzZeGKHHmKhHYvgaU=
-golang.org/x/sys v0.28.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
+golang.org/x/sys v0.29.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
 golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=
@@ -238,8 +236,8 @@ golang.org/x/text v0.3.6/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=
 golang.org/x/text v0.3.7/go.mod h1:u+2+/6zg+i71rQMx5EYifcz6MCKuco9NR6JIITiCfzQ=
 golang.org/x/text v0.21.0 h1:zyQAAkrwaneQ066sspRyJaG9VNi/YJ1NfzcGB3hZ/qo=
 golang.org/x/text v0.21.0/go.mod h1:4IBbMaMmOPCJ8SecivzSH54+73PCFmPWxNTLm+vZkEQ=
-golang.org/x/time v0.8.0 h1:9i3RxcPv3PZnitoVGMPDKZSq1xW1gK1Xy3ArNOGZfEg=
+golang.org/x/time v0.9.0 h1:EsRrnYcQiGH+5FfbgvV4AP7qEZstoyrHB0DzarOQ4ZY=
-golang.org/x/time v0.8.0/go.mod h1:3BpzKBy/shNhVucY/MWOyx10tF3SFh9QdLuxbVysPQM=
+golang.org/x/time v0.9.0/go.mod h1:3BpzKBy/shNhVucY/MWOyx10tF3SFh9QdLuxbVysPQM=
 golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
 golang.org/x/tools v0.0.0-20191119224855-298f0cb1881e/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
 golang.org/x/tools v0.0.0-20200619180055-7c47624df98f/go.mod h1:EkVYQZoAsY45+roYkvgYkIh4xh/qjgUK9TdY2XT94GE=
@@ -248,10 +246,10 @@ golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8T
 golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
 golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
 golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
-google.golang.org/genproto/googleapis/api v0.0.0-20241223144023-3abc09e42ca8 h1:st3LcW/BPi75W4q1jJTEor/QWwbNlPlDG0JTn6XhZu0=
+google.golang.org/genproto/googleapis/api v0.0.0-20250102185135-69823020774d h1:H8tOf8XM88HvKqLTxe755haY6r1fqqzLbEnfrmLXlSA=
-google.golang.org/genproto/googleapis/api v0.0.0-20241223144023-3abc09e42ca8/go.mod h1:klhJGKFyG8Tn50enBn7gizg4nXGXJ+jqEREdCWaPcV4=
+google.golang.org/genproto/googleapis/api v0.0.0-20250102185135-69823020774d/go.mod h1:2v7Z7gP2ZUOGsaFyxATQSRoBnKygqVq2Cwnvom7QiqY=
-google.golang.org/genproto/googleapis/rpc v0.0.0-20241223144023-3abc09e42ca8 h1:TqExAhdPaB60Ux47Cn0oLV07rGnxZzIsaRhQaqS666A=
+google.golang.org/genproto/googleapis/rpc v0.0.0-20250102185135-69823020774d h1:xJJRGY7TJcvIlpSrN3K6LAWgNFUILlO+OMAqtg9aqnw=
-google.golang.org/genproto/googleapis/rpc v0.0.0-20241223144023-3abc09e42ca8/go.mod h1:lcTa1sDdWEIHMWlITnIczmw5w60CF9ffkb8Z+DVmmjA=
+google.golang.org/genproto/googleapis/rpc v0.0.0-20250102185135-69823020774d/go.mod h1:3ENsm/5D1mzDyhpzeRi1NR784I0BcofWBoSc5QqqMK4=
 google.golang.org/grpc v1.69.2 h1:U3S9QEtbXC0bYNvRtcoklF3xGtLViumSYxWykJS+7AU=
 google.golang.org/grpc v1.69.2/go.mod h1:vyjdE6jLBI76dgpDojsFGNaHlxdjXN9ghpnd2o7JGZ4=
 google.golang.org/protobuf v1.26.0-rc.1/go.mod h1:jlhhOSvTdKEhbULTjvd4ARK9grFBp09yW+WbY/TyQbw=

ntpdb/dbconn.go

@@ -1,14 +1,15 @@
 package ntpdb
 
 import (
+	"context"
 	"database/sql"
 	"database/sql/driver"
 	"fmt"
-	"log"
 	"os"
 	"time"
 
 	"github.com/go-sql-driver/mysql"
+	"go.ntppool.org/common/logger"
 	"gopkg.in/yaml.v3"
 )
 
@@ -22,9 +23,10 @@ type DBConfig struct {
 	Pass string `default:"" flag:"pass"`
 }
 
-func OpenDB(configFile string) (*sql.DB, error) {
+func OpenDB(ctx context.Context, configFile string) (*sql.DB, error) {
+	log := logger.FromContext(ctx)
 
-	dbconn := sql.OpenDB(Driver{CreateConnectorFunc: createConnector(configFile)})
+	dbconn := sql.OpenDB(Driver{CreateConnectorFunc: createConnector(ctx, configFile)})
 
 	dbconn.SetConnMaxLifetime(time.Minute * 3)
 	dbconn.SetMaxOpenConns(8)
@@ -32,17 +34,17 @@ func OpenDB(configFile string) (*sql.DB, error) {
 
 	err := dbconn.Ping()
 	if err != nil {
-		log.Printf("Could not connect to database: %s", err)
+		log.DebugContext(ctx, "could not connect to database: %s", "err", err)
 		return nil, err
 	}
 
 	return dbconn, nil
 }
 
-func createConnector(configFile string) CreateConnectorFunc {
+func createConnector(ctx context.Context, configFile string) CreateConnectorFunc {
+	log := logger.FromContext(ctx)
 	return func() (driver.Connector, error) {
-
+		log.DebugContext(ctx, "opening db config file", "filename", configFile)
-		log.Printf("opening config file %s", configFile)
 
 		dbFile, err := os.Open(configFile)
 		if err != nil {

server/graph_image.go

@@ -107,6 +107,7 @@ func (srv *Server) fetchGraph(ctx context.Context, serverIP string) (string, []b
 
 	client := retryablehttp.NewClient()
 	client.Logger = log
+
 	client.HTTPClient.Transport = otelhttp.NewTransport(
 		client.HTTPClient.Transport,
 		otelhttp.WithClientTrace(func(ctx context.Context) *httptrace.ClientTrace {

server/history.go

@@ -145,7 +145,8 @@ func (srv *Server) history(c echo.Context) error {
 	ctx, span := tracing.Tracer().Start(c.Request().Context(), "history")
 	defer span.End()
 
-	// just cache for a short time by default
+	// set a reasonable default cache time; adjusted later for
+	// happy path common responses
 	c.Response().Header().Set("Cache-Control", "public,max-age=240")
 
 	mode := paramHistoryMode(c.Param("mode"))
@@ -316,13 +317,7 @@ func (srv *Server) historyJSON(ctx context.Context, c echo.Context, server ntpdb
 		}
 	}
 
-	if len(history.LogScores) == 0 ||
+	setHistoryCacheControl(c, history)
-		history.LogScores[len(history.LogScores)-1].Ts.After(time.Now().Add(-8*time.Hour)) {
-		// cache for longer if data hasn't updated for a while
-		c.Request().Header.Set("Cache-Control", "s-maxage=3600,max-age=1800")
-	} else {
-		c.Request().Header.Set("Cache-Control", "s-maxage=300,max-age=240")
-	}
 
 	return c.JSON(http.StatusOK, res)
 }
@@ -390,9 +385,26 @@ func (srv *Server) historyCSV(ctx context.Context, c echo.Context, history *logs
 
 	// log.Info("entries", "count", len(history.LogScores), "out_bytes", b.Len())
 
-	c.Response().Header().Set("Cache-Control", "s-maxage=150,max-age=120")
+	setHistoryCacheControl(c, history)
+
 	c.Response().Header().Set("Content-Disposition", "inline")
 	// Chrome and Firefox force-download text/csv files, so use text/plain
 	// https://bugs.chromium.org/p/chromium/issues/detail?id=152911
 	return c.Blob(http.StatusOK, "text/plain", b.Bytes())
 }
+
+func setHistoryCacheControl(c echo.Context, history *logscores.LogScoreHistory) {
+	hdr := c.Response().Header()
+	if len(history.LogScores) == 0 ||
+		// cache for longer if data hasn't updated for a while; or we didn't
+		// find any.
+		(time.Now().Add(-8 * time.Hour).After(history.LogScores[len(history.LogScores)-1].Ts)) {
+		hdr.Set("Cache-Control", "s-maxage=3600,max-age=1800")
+	} else {
+		if len(history.LogScores) == 1 {
+			hdr.Set("Cache-Control", "s-maxage=60,max-age=35")
+		} else {
+			hdr.Set("Cache-Control", "s-maxage=240,max-age=120")
+		}
+	}
+}

server/server.go

@@ -53,7 +53,7 @@ func NewServer(ctx context.Context, configFile string) (*Server, error) {
 	if err != nil {
 		return nil, fmt.Errorf("clickhouse open: %w", err)
 	}
-	db, err := ntpdb.OpenDB(configFile)
+	db, err := ntpdb.OpenDB(ctx, configFile)
 	if err != nil {
 		return nil, fmt.Errorf("mysql open: %w", err)
 	}
@@ -284,7 +284,7 @@ func healthHandler(srv *Server, log *slog.Logger) func(w http.ResponseWriter, re
 		g, ctx := errgroup.WithContext(ctx)
 
 		stats := srv.db.Stats()
-		if stats.OpenConnections > 5 {
+		if stats.OpenConnections > 3 {
 			log.InfoContext(ctx, "health requests", "url", req.URL.String(), "stats", stats)
 		}
 
@@ -293,16 +293,27 @@ func healthHandler(srv *Server, log *slog.Logger) func(w http.ResponseWriter, re
 			log.InfoContext(ctx, "db reset request", "err", err, "reset", reset)
 
 			if err == nil && reset {
+				// this feature was to debug some specific problem
 				log.InfoContext(ctx, "setting idle db conns to zero")
+				srv.db.SetConnMaxLifetime(30 * time.Second)
 				srv.db.SetMaxIdleConns(0)
-				srv.db.SetConnMaxLifetime(5 * time.Second)
+				srv.db.SetMaxIdleConns(4)
 			}
 		}
 
 		g.Go(func() error {
 			err := srv.ch.Scores.Ping(ctx)
 			if err != nil {
-				log.WarnContext(ctx, "ch ping", "err", err)
+				log.WarnContext(ctx, "ch scores ping", "err", err)
+				return err
+			}
+			return nil
+		})
+
+		g.Go(func() error {
+			err := srv.ch.Logs.Ping(ctx)
+			if err != nil {
+				log.WarnContext(ctx, "ch logs ping", "err", err)
 				return err
 			}
 			return nil