Add log verbosity levels (#241)

* Add verbocity levels for all log commands

Signed-off-by: Maya Barnea <[email protected]>

* add log verbosity to readme

Signed-off-by: Maya Barnea <[email protected]>

* set default value for logger verbosity to INFO

Signed-off-by: Maya Barnea <[email protected]>

* fix lint problem

Signed-off-by: Maya Barnea <[email protected]>

---------

Signed-off-by: Maya Barnea <[email protected]>

Author: mayabar

README.md

@@ -189,7 +189,11 @@ In addition, as we are using klog, the following parameters are available:
 - `skip_headers`: if true, avoid header prefixes in the log messages
 - `skip_log_headers`: if true, avoid headers when opening log files (no effect when -logtostderr=true)
 - `stderrthreshold`: logs at or above this threshold go to stderr when writing to files and stderr (no effect when -logtostderr=true or -alsologtostderr=true) (default 2)
-- `v`: number for the log level verbosity
+- `v`: number for the log level verbosity. Supported levels:
+  - Warning (1) - warning messages
+  - Info (2) - general application messages, e.g., loaded configuration content, which responses dataset was loaded, etc.
+  - Debug (4) - debugging messages, e.g. /completions and /chat/completions request received, load/unload lora request processed, etc.
+  - Trace (5) - highest verbosity, e.g. detailed messages on completions request handling and request queue processing, etc.
 - `vmodule`: comma-separated list of pattern=N settings for file-filtered logging
 
 ## Environment variables

cmd/llm-d-inference-sim/main.go

@@ -24,6 +24,7 @@ import (
 	"k8s.io/klog/v2"
 
 	"github.com/llm-d/llm-d-inference-sim/cmd/signals"
+	"github.com/llm-d/llm-d-inference-sim/pkg/common/logging"
 	vllmsim "github.com/llm-d/llm-d-inference-sim/pkg/llm-d-inference-sim"
 )
 
@@ -33,11 +34,11 @@ func main() {
 	ctx := klog.NewContext(context.Background(), logger)
 	ctx = signals.SetupSignalHandler(ctx)
 
-	logger.Info("Starting vLLM simulator")
+	logger.V(logging.INFO).Info("Starting vLLM simulator")
 
 	vllmSim, err := vllmsim.New(logger)
 	if err != nil {
-		logger.Error(err, "Failed to create vLLM simulator")
+		logger.Error(err, "failed to create vLLM simulator")
 		return
 	}
 	if err := vllmSim.Start(ctx); err != nil {

pkg/common/config.go

@@ -767,6 +767,11 @@ func ParseCommandParamsAndLoadConfig() (*Configuration, error) {
 	klog.InitFlags(flagSet)
 	f.AddGoFlagSet(flagSet)
 
+	// set default value for logger verbosity to INFO
+	if err := flagSet.Set("v", "2"); err != nil {
+		return nil, err
+	}
+
 	if err := f.Parse(os.Args[1:]); err != nil {
 		if err == pflag.ErrHelp {
 			// --help - exit without printing an error message

pkg/common/logging/levels.go

@@ -0,0 +1,24 @@
+/*
+Copyright 2025 The llm-d-inference-sim Authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package logging
+
+const (
+	WARN  = 1
+	INFO  = 2
+	DEBUG = 4
+	TRACE = 5
+)

pkg/common/publisher.go

@@ -25,6 +25,7 @@ import (
 	"sync/atomic"
 	"time"
 
+	"github.com/llm-d/llm-d-inference-sim/pkg/common/logging"
 	zmq "github.com/pebbe/zmq4"
 	"github.com/vmihailenco/msgpack/v5"
 	"k8s.io/klog/v2"
@@ -93,7 +94,7 @@ func (p *Publisher) PublishEvent(ctx context.Context, topic string, batch interf
 		return fmt.Errorf("failed to send message to topic %s: %w", topic, err)
 	}
 
-	logger.Info("Published event batch", "topic", topic, "seq", seq)
+	logger.V(logging.TRACE).Info("Published event batch", "topic", topic, "seq", seq)
 	return nil
 }
 

pkg/common/utils.go

@@ -23,6 +23,7 @@ import (
 
 	"github.com/go-logr/logr"
 	"github.com/google/uuid"
+	"github.com/llm-d/llm-d-inference-sim/pkg/common/logging"
 )
 
 // Definition of buckets for time-to-first-token and time-per-output-token metrics, each value is an upper boundary of a bucket
@@ -149,6 +150,6 @@ func WriteToChannel[T any](channel chan T, object T, logger logr.Logger, channel
 	select {
 	case channel <- object:
 	default:
-		logger.V(1).Info("failed to write to", "channel", channelName)
+		logger.V(logging.WARN).Info("failed to write to", "channel", channelName)
 	}
 }

pkg/dataset/custom_dataset.go

@@ -33,6 +33,7 @@ import (
 
 	"github.com/go-logr/logr"
 	"github.com/llm-d/llm-d-inference-sim/pkg/common"
+	"github.com/llm-d/llm-d-inference-sim/pkg/common/logging"
 	openaiserverapi "github.com/llm-d/llm-d-inference-sim/pkg/openai-server-api"
 )
 
@@ -80,7 +81,7 @@ func (d *CustomDataset) downloadDataset(ctx context.Context, url string, path st
 		}
 	}()
 
-	d.logger.Info("Using dataset-url", "dataset-url", url)
+	d.logger.V(logging.INFO).Info("Using dataset-url", "dataset-url", url)
 	resp, err := http.Get(url)
 	if err != nil {
 		return err
@@ -181,9 +182,9 @@ func (pr *progressReader) logProgress(pct int) {
 	speed := float64(pr.downloaded) / (1024 * 1024 * elapsedTime)
 	remainingTime := float64(pr.total-pr.downloaded) / (float64(pr.downloaded) / elapsedTime)
 	if pct != 100 {
-		pr.logger.Info(fmt.Sprintf("Download progress: %d%%, Speed: %.2f MB/s, Remaining time: %.2fs", pct, speed, remainingTime))
+		pr.logger.V(logging.INFO).Info("Dataset download progress", "%", pct, "speed (MB/s)", speed, "remaining time (s)", remainingTime)
 	} else {
-		pr.logger.Info(fmt.Sprintf("Download completed: 100%%, Average Speed: %.2f MB/s, Total time: %.2fs", speed, elapsedTime))
+		pr.logger.V(logging.INFO).Info("Download completed", "average speed (MB/s)", speed, "total time (s)", elapsedTime)
 	}
 }
 
@@ -248,7 +249,7 @@ func (d *CustomDataset) getRecordsCount() (int, error) {
 }
 
 func (d *CustomDataset) loadDatabaseInMemory(path string) error {
-	d.logger.Info("Loading database into memory...")
+	d.logger.V(logging.INFO).Info("Loading database into memory...")
 	start := time.Now()
 
 	// Create in-memory database
@@ -301,7 +302,7 @@ func (d *CustomDataset) loadDatabaseInMemory(path string) error {
 	}
 
 	loadTime := time.Since(start)
-	d.logger.Info("Database loaded into memory", "load_time", loadTime.String())
+	d.logger.V(logging.INFO).Info("Database loaded into memory", "load_time", loadTime.String())
 	return nil
 }
 
@@ -354,9 +355,9 @@ func (d *CustomDataset) connectToDB(path string, useInMemory bool) error {
 	}
 
 	if useInMemory {
-		d.logger.Info("In-memory database connected successfully", "path", path, "records count", count)
+		d.logger.V(logging.INFO).Info("In-memory database connected successfully", "path", path, "records count", count)
 	} else {
-		d.logger.Info("Database connected successfully", "path", path, "records count", count)
+		d.logger.V(logging.INFO).Info("Database connected successfully", "path", path, "records count", count)
 	}
 	return nil
 }
@@ -368,7 +369,7 @@ func (d *CustomDataset) Init(ctx context.Context, logger logr.Logger, path strin
 	}
 	d.hasWarned = false
 	if url == "" {
-		d.logger.Info("Using dataset from", "path", path)
+		d.logger.V(logging.INFO).Info("Using dataset from", "path", path)
 		return d.connectToDB(path, useInMemory)
 	}
 	_, err := os.Stat(path)
@@ -386,7 +387,7 @@ func (d *CustomDataset) Init(ctx context.Context, logger logr.Logger, path strin
 			return fmt.Errorf("failed to download dataset: %w", err)
 		}
 	}
-	d.logger.Info("Using dataset path", "dataset-path", path)
+	d.logger.V(logging.INFO).Info("Using dataset path", "dataset-path", path)
 
 	return d.connectToDB(path, useInMemory)
 }
@@ -448,7 +449,7 @@ func (d *CustomDataset) query(query string, nTokens int, random *common.Random)
 	rows, err := d.db.Query(query)
 	if err != nil {
 		if !d.hasWarned {
-			d.logger.Error(err, "Failed to query database. Ensure dataset file is still valid. Will generate random tokens instead.")
+			d.logger.Error(err, "failed to query database. Ensure dataset file is still valid. Will generate random tokens instead.")
 			d.hasWarned = true
 		}
 		return [][]string{GenPresetRandomTokens(random, nTokens)}, nil
@@ -472,7 +473,7 @@ func (d *CustomDataset) GenerateTokens(req openaiserverapi.CompletionRequest, nT
 	// filter out results according to finish reason
 	var filteredTokensList [][]string
 	if finishReason != LengthFinishReason && finishReason != StopFinishReason {
-		d.logger.Error(errors.New("unknown finish reason"), "Unexpected finish reason", "reason", finishReason)
+		d.logger.Error(errors.New("unknown finish reason"), "unexpected finish reason", "reason", finishReason)
 	}
 	for _, tokens := range tokensList {
 		if finishReason == StopFinishReason && len(tokens) <= nTokens {

pkg/kv-cache/block_cache.go

@@ -73,7 +73,7 @@ func newBlockCache(config *common.Configuration, logger logr.Logger, usageChan c
 func (bc *blockCache) start(ctx context.Context) {
 	err := bc.eventSender.Run(ctx)
 	if err != nil {
-		bc.logger.Info("sender stopped with error", "error", err)
+		bc.logger.Error(err, "Sender stopped with error")
 	}
 }
 

pkg/kv-cache/kv_cache.go

@@ -22,6 +22,7 @@ import (
 
 	"github.com/go-logr/logr"
 	"github.com/llm-d/llm-d-inference-sim/pkg/common"
+	"github.com/llm-d/llm-d-inference-sim/pkg/common/logging"
 	openaiserverapi "github.com/llm-d/llm-d-inference-sim/pkg/openai-server-api"
 	"github.com/llm-d/llm-d-kv-cache-manager/pkg/kvcache/kvblock"
 	"github.com/llm-d/llm-d-kv-cache-manager/pkg/tokenization"
@@ -63,7 +64,7 @@ func (h *KVCacheHelper) Run(ctx context.Context) {
 }
 
 func (h *KVCacheHelper) OnRequestStart(vllmReq openaiserverapi.CompletionRequest) error {
-	h.logger.Info("KV cache - process request")
+	h.logger.V(logging.TRACE).Info("KV cache - process request")
 
 	prompt := vllmReq.GetPrompt()
 	modelName := vllmReq.GetModel()
@@ -72,13 +73,13 @@ func (h *KVCacheHelper) OnRequestStart(vllmReq openaiserverapi.CompletionRequest
 	// tokenize the input
 	tokens, _, err := h.tokenizer.Encode(prompt, modelName)
 	if err != nil {
-		h.logger.Info("Prompt tokenization failed", "error", err.Error())
+		h.logger.Error(err, "prompt tokenization failed")
 		return err
 	}
 
 	// get block keys
 	blockKeys := h.tokensProcessor.TokensToKVBlockKeys(tokens, modelName)
-	h.logger.Info("found tokens", "tokens", tokens, "block-keys", blockKeys)
+	h.logger.V(logging.TRACE).Info("Found tokens", "tokens", tokens, "block-keys", blockKeys)
 
 	blockHashes := make([]uint64, len(blockKeys))
 	for i, key := range blockKeys {

pkg/kv-cache/kv_cache_sender.go

@@ -22,6 +22,7 @@ import (
 
 	"github.com/go-logr/logr"
 	"github.com/llm-d/llm-d-inference-sim/pkg/common"
+	"github.com/llm-d/llm-d-inference-sim/pkg/common/logging"
 	"github.com/llm-d/llm-d-kv-cache-manager/pkg/kvcache/kvevents"
 	"github.com/vmihailenco/msgpack/v5"
 )
@@ -70,15 +71,15 @@ func (s *KVEventSender) Run(ctx context.Context) error {
 		case <-ctx.Done():
 			// Exiting, discard remaining events if any
 			if len(s.batch) > 0 {
-				s.logger.Info("Existing, discard remaining events", "num of events", len(s.batch))
+				s.logger.V(logging.INFO).Info("Exiting, discard remaining events", "num of events", len(s.batch))
 			}
 			return ctx.Err()
 
 		case eventData, ok := <-s.eventChan:
 			if !ok {
 				// Channel closed, discard remaining events and exit
 				if len(s.batch) > 0 {
-					s.logger.Info("Channel closed, discard remaining events", "num of events", len(s.batch))
+					s.logger.V(logging.INFO).Info("Channel closed, discard remaining events", "num of events", len(s.batch))
 				}
 				return nil
 			}