From de79f568ba300e410950cdf042e9d0f8c3f11e66 Mon Sep 17 00:00:00 2001 From: "eduardo.villani" Date: Fri, 17 Apr 2026 15:25:35 -0300 Subject: [PATCH 1/6] chore(FN1-6398): reduce log noise by changing verbose Info logs to Debug Downgrade several high-frequency Info logs to Debug to reduce production log noise. Change orphaned room cleanup log from Info to Warn since it indicates a data inconsistency worth monitoring. Co-Authored-By: Claude Opus 4.6 --- .../adapters/runtime/kubernetes/game_room_convert.go | 10 +++++----- internal/api/handlers/operations_handler.go | 2 +- internal/core/operations/healthcontroller/executor.go | 8 ++++---- internal/core/operations/rooms/remove/executor.go | 6 +++--- .../operations/schedulers/switchversion/executor.go | 2 +- .../core/services/events/events_forwarder_service.go | 2 +- internal/core/services/rooms/room_manager.go | 4 ++-- .../operationexecution/operation_execution_worker.go | 2 +- 8 files changed, 18 insertions(+), 18 deletions(-) diff --git a/internal/adapters/runtime/kubernetes/game_room_convert.go b/internal/adapters/runtime/kubernetes/game_room_convert.go index 78279179..79046a99 100644 --- a/internal/adapters/runtime/kubernetes/game_room_convert.go +++ b/internal/adapters/runtime/kubernetes/game_room_convert.go @@ -300,10 +300,10 @@ func convertPodStatus(pod *v1.Pod) game_room.InstanceStatus { switch pod.Status.Phase { case v1.PodSucceeded: // Completed pods should not be considered available; treat as terminating - zap.L().Info("pod phase -> instance status mapping", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("phase", string(pod.Status.Phase)), zap.String("mappedTo", game_room.InstanceTerminating.String())) + zap.L().Debug("pod phase -> instance status mapping", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("phase", string(pod.Status.Phase)), zap.String("mappedTo", game_room.InstanceTerminating.String())) return game_room.InstanceStatus{Type: game_room.InstanceTerminating, Description: "PodSucceeded"} case v1.PodFailed: - zap.L().Info("pod phase -> instance status mapping", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("phase", string(pod.Status.Phase)), zap.String("mappedTo", game_room.InstanceError.String())) + zap.L().Debug("pod phase -> instance status mapping", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("phase", string(pod.Status.Phase)), zap.String("mappedTo", game_room.InstanceError.String())) return game_room.InstanceStatus{Type: game_room.InstanceError, Description: "PodFailed"} case v1.PodUnknown: // Unknown pods should not be treated as available @@ -335,7 +335,7 @@ func convertPodStatus(pod *v1.Pod) game_room.InstanceStatus { // If container is terminated, classify based on the termination reason if state.Terminated != nil { if state.Terminated.Reason == "Completed" || state.Terminated.ExitCode == 0 { - zap.L().Info( + zap.L().Debug( "container terminated successfully; mapping to terminating", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("container", containerStatus.Name), @@ -385,10 +385,10 @@ func convertPodStatus(pod *v1.Pod) game_room.InstanceStatus { // This allows us to catch container-level errors even for Running/Pending pods switch pod.Status.Phase { case v1.PodPending: - zap.L().Info("pod phase -> instance status mapping", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("phase", string(pod.Status.Phase)), zap.String("mappedTo", game_room.InstancePending.String())) + zap.L().Debug("pod phase -> instance status mapping", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("phase", string(pod.Status.Phase)), zap.String("mappedTo", game_room.InstancePending.String())) return game_room.InstanceStatus{Type: game_room.InstancePending, Description: ""} case v1.PodRunning: - zap.L().Info("pod phase -> instance status mapping", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("phase", string(pod.Status.Phase)), zap.String("mappedTo", game_room.InstanceReady.String())) + zap.L().Debug("pod phase -> instance status mapping", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("phase", string(pod.Status.Phase)), zap.String("mappedTo", game_room.InstanceReady.String())) return game_room.InstanceStatus{Type: game_room.InstanceReady, Description: ""} default: // Handle any future pod phases that might be added to Kubernetes diff --git a/internal/api/handlers/operations_handler.go b/internal/api/handlers/operations_handler.go index 3b45f80b..e94c5611 100644 --- a/internal/api/handlers/operations_handler.go +++ b/internal/api/handlers/operations_handler.go @@ -125,7 +125,7 @@ func (h *OperationsHandler) CancelOperation(ctx context.Context, request *api.Ca func (h *OperationsHandler) GetOperation(ctx context.Context, request *api.GetOperationRequest) (*api.GetOperationResponse, error) { handlerLogger := h.logger.With(zap.String(logs.LogFieldSchedulerName, request.GetSchedulerName()), zap.String(logs.LogFieldOperationID, request.GetOperationId())) - handlerLogger.Info("received request to get operation by id") + handlerLogger.Debug("received request to get operation by id") op, _, err := h.operationManager.GetOperation(ctx, request.GetSchedulerName(), request.GetOperationId()) if err != nil { if errors.Is(err, portsErrors.ErrNotFound) { diff --git a/internal/core/operations/healthcontroller/executor.go b/internal/core/operations/healthcontroller/executor.go index f522ffb9..7e67a543 100644 --- a/internal/core/operations/healthcontroller/executor.go +++ b/internal/core/operations/healthcontroller/executor.go @@ -119,7 +119,7 @@ func (ex *Executor) Execute(ctx context.Context, op *operation.Operation, defini reportCurrentNumberOfRooms(scheduler.Game, scheduler.Name, len(availableRooms)) if len(expiredRooms) > 0 { - logger.Sugar().Infof("found %v expired rooms to be deleted", len(expiredRooms)) + logger.Sugar().Debugf("found %v expired rooms to be deleted", len(expiredRooms)) err = ex.enqueueRemoveExpiredRooms(ctx, op, logger, expiredRooms) if err != nil { logger.Error("could not enqueue operation to delete expired rooms", zap.Error(err)) @@ -187,7 +187,7 @@ func (ex *Executor) tryEnsureCorrectRoomsOnStorage(ctx context.Context, op *oper continue } - logger.Sugar().Infof("removed nonexistent room from instance and game room storage: %s", gameRoomID) + logger.Sugar().Warnf("removed nonexistent room from instance and game room storage: %s", gameRoomID) } } @@ -228,7 +228,7 @@ func (ex *Executor) ensureDesiredAmountOfInstances(ctx context.Context, op *oper msgToAppend = "current amount of rooms is equal to desired amount, no changes needed" } - logger.Info(msgToAppend) + logger.Debug(msgToAppend) ex.setTookAction(def, tookAction) if tookAction { ex.operationManager.AppendOperationEventToExecutionHistory(ctx, op, msgToAppend) @@ -445,7 +445,7 @@ func GetDesiredNumberOfRooms( } } - logger.Sugar().Infof("[GetDesiredNumberOfRooms] desired %d, current %d, isRollingUpdating %t", desiredNumber, len(availableRooms), isRollingUpdating) + logger.Sugar().Debugf("[GetDesiredNumberOfRooms] desired %d, current %d, isRollingUpdating %t", desiredNumber, len(availableRooms), isRollingUpdating) return } diff --git a/internal/core/operations/rooms/remove/executor.go b/internal/core/operations/rooms/remove/executor.go index db396e5f..ae187262 100644 --- a/internal/core/operations/rooms/remove/executor.go +++ b/internal/core/operations/rooms/remove/executor.go @@ -80,7 +80,7 @@ func (e *Executor) Execute(ctx context.Context, op *operation.Operation, definit removeDefinition := definition.(*Definition) if len(removeDefinition.RoomsIDs) > 0 { - logger.Info("start removing rooms", zap.Strings("RoomIDs", removeDefinition.RoomsIDs)) + logger.Debug("start removing rooms", zap.Strings("RoomIDs", removeDefinition.RoomsIDs)) err := e.removeRoomsByIDs(ctx, op.SchedulerName, removeDefinition.RoomsIDs, op, removeDefinition.Reason) if err != nil { reportDeletionFailedTotal(op.SchedulerName, op.ID) @@ -97,7 +97,7 @@ func (e *Executor) Execute(ctx context.Context, op *operation.Operation, definit } if removeDefinition.Amount > 0 { - logger.Info("start removing rooms", zap.Int("amount", removeDefinition.Amount)) + logger.Debug("start removing rooms", zap.Int("amount", removeDefinition.Amount)) err := e.removeRoomsByAmount(ctx, logger, op.SchedulerName, removeDefinition.Amount, op, removeDefinition.Reason) if err != nil { reportDeletionFailedTotal(op.SchedulerName, op.ID) @@ -108,7 +108,7 @@ func (e *Executor) Execute(ctx context.Context, op *operation.Operation, definit e.operationManager.AppendOperationEventToExecutionHistory(ctx, op, fmt.Sprintf("removed %d rooms", removeDefinition.Amount)) } - logger.Info("finished deleting rooms") + logger.Debug("finished deleting rooms") return nil } diff --git a/internal/core/operations/schedulers/switchversion/executor.go b/internal/core/operations/schedulers/switchversion/executor.go index a9c39e1f..04832f29 100644 --- a/internal/core/operations/schedulers/switchversion/executor.go +++ b/internal/core/operations/schedulers/switchversion/executor.go @@ -81,7 +81,7 @@ func (ex *Executor) Execute(ctx context.Context, op *operation.Operation, defini return updateSchedulerErr } - logger.Info("scheduler update finishes with success") + logger.Debug("scheduler update finishes with success") return nil } diff --git a/internal/core/services/events/events_forwarder_service.go b/internal/core/services/events/events_forwarder_service.go index ac42cafd..afe56b0e 100644 --- a/internal/core/services/events/events_forwarder_service.go +++ b/internal/core/services/events/events_forwarder_service.go @@ -308,7 +308,7 @@ func (es *EventsForwarderService) isValidationRoom(ctx context.Context, event *e } if gameRoom.IsValidationRoom { - es.logger.Info(fmt.Sprintf("not producing events for room \"%s\", scheduler \"%s\" since it's a validation room", gameRoom.ID, gameRoom.SchedulerID)) + es.logger.Debug(fmt.Sprintf("not producing events for room \"%s\", scheduler \"%s\" since it's a validation room", gameRoom.ID, gameRoom.SchedulerID)) } return gameRoom.IsValidationRoom, nil diff --git a/internal/core/services/rooms/room_manager.go b/internal/core/services/rooms/room_manager.go index e6f0f42f..6f2c1539 100644 --- a/internal/core/services/rooms/room_manager.go +++ b/internal/core/services/rooms/room_manager.go @@ -185,7 +185,7 @@ func (m *RoomManager) UpdateRoomInstance(ctx context.Context, gameRoomInstance * } func (m *RoomManager) CleanRoomState(ctx context.Context, schedulerName, roomId string) error { - m.Logger.Sugar().Infof("Cleaning room \"%v\", scheduler \"%v\"", roomId, schedulerName) + m.Logger.Sugar().Debugf("Cleaning room \"%v\", scheduler \"%v\"", roomId, schedulerName) err := m.RoomStorage.DeleteRoom(ctx, schedulerName, roomId) if err != nil && !errors.Is(err, porterrors.ErrNotFound) { return fmt.Errorf("failed to delete room state: %w", err) @@ -201,7 +201,7 @@ func (m *RoomManager) CleanRoomState(ctx context.Context, schedulerName, roomId SchedulerID: schedulerName, }) - m.Logger.Info("cleaning room success") + m.Logger.Debug("cleaning room success") return nil } diff --git a/internal/core/worker/operationexecution/operation_execution_worker.go b/internal/core/worker/operationexecution/operation_execution_worker.go index b36961e0..f90a0ded 100644 --- a/internal/core/worker/operationexecution/operation_execution_worker.go +++ b/internal/core/worker/operationexecution/operation_execution_worker.go @@ -210,7 +210,7 @@ func (w *OperationExecutionWorker) rollbackOperation(ctx context.Context, op *op loopLogger.Error("operation rollback failed", zap.Error(rollbackErr)) w.operationManager.AppendOperationEventToExecutionHistory(ctx, op, fmt.Sprintf("Operation rollback flow execution failed, reason: %s", rollbackErr.Error())) } else { - loopLogger.Info("successfully rolled back operation") + loopLogger.Debug("successfully rolled back operation") w.operationManager.AppendOperationEventToExecutionHistory(ctx, op, "Operation rollback flow execution finished with success") } } From 5667a81b3ca3adf9ad5a2968d3a6b35d862d249f Mon Sep 17 00:00:00 2001 From: "eduardo.villani" Date: Thu, 23 Apr 2026 14:19:55 -0300 Subject: [PATCH 2/6] chore: lower more logs --- .../adapters/runtime/kubernetes/game_room_convert.go | 2 +- .../core/operations/healthcontroller/executor.go | 4 ++-- internal/core/operations/rooms/add/executor.go | 6 +++++- internal/core/operations/rooms/remove/executor.go | 2 +- .../operations/schedulers/newversion/executor.go | 4 ++-- .../operations/schedulers/switchversion/executor.go | 2 +- internal/core/services/workers/workers_manager.go | 4 ++-- .../core/services/workers/workers_manager_test.go | 4 ++-- .../operationexecution/operation_execution_worker.go | 8 ++++---- .../worker/runtimewatcher/runtime_watcher_worker.go | 12 ++++++------ 10 files changed, 26 insertions(+), 22 deletions(-) diff --git a/internal/adapters/runtime/kubernetes/game_room_convert.go b/internal/adapters/runtime/kubernetes/game_room_convert.go index 79046a99..2e331662 100644 --- a/internal/adapters/runtime/kubernetes/game_room_convert.go +++ b/internal/adapters/runtime/kubernetes/game_room_convert.go @@ -303,7 +303,7 @@ func convertPodStatus(pod *v1.Pod) game_room.InstanceStatus { zap.L().Debug("pod phase -> instance status mapping", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("phase", string(pod.Status.Phase)), zap.String("mappedTo", game_room.InstanceTerminating.String())) return game_room.InstanceStatus{Type: game_room.InstanceTerminating, Description: "PodSucceeded"} case v1.PodFailed: - zap.L().Debug("pod phase -> instance status mapping", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("phase", string(pod.Status.Phase)), zap.String("mappedTo", game_room.InstanceError.String())) + zap.L().Error("pod phase -> instance status mapping", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("phase", string(pod.Status.Phase)), zap.String("mappedTo", game_room.InstanceError.String())) return game_room.InstanceStatus{Type: game_room.InstanceError, Description: "PodFailed"} case v1.PodUnknown: // Unknown pods should not be treated as available diff --git a/internal/core/operations/healthcontroller/executor.go b/internal/core/operations/healthcontroller/executor.go index 7e67a543..0d092f03 100644 --- a/internal/core/operations/healthcontroller/executor.go +++ b/internal/core/operations/healthcontroller/executor.go @@ -310,7 +310,7 @@ func (ex *Executor) enqueueRemoveExpiredRooms(ctx context.Context, op *operation } msgToAppend := fmt.Sprintf("created operation (id: %s) to remove expired %v rooms.", removeOperation.ID, len(roomsIDs)) - logger.Info(msgToAppend) + logger.Debug(msgToAppend) ex.operationManager.AppendOperationEventToExecutionHistory(ctx, op, msgToAppend) return nil @@ -510,7 +510,7 @@ func IsRollingUpdating( } if schedulerCache[room.Version].IsMajorVersion(scheduler) { - logger.Info( + logger.Debug( "Rolling update detected, system has rooms with a major version of difference", zap.String("activeScheduler", scheduler.Spec.Version), zap.String("nonActiveSchedulerFound", room.Version), diff --git a/internal/core/operations/rooms/add/executor.go b/internal/core/operations/rooms/add/executor.go index 72337977..c78d25fc 100644 --- a/internal/core/operations/rooms/add/executor.go +++ b/internal/core/operations/rooms/add/executor.go @@ -163,7 +163,11 @@ func (ex *Executor) Execute(ctx context.Context, op *operation.Operation, defini ex.operationManager.AppendOperationEventToExecutionHistory(ctx, op, ErrMajorityRooms.Error()) return ErrMajorityRooms default: - executionLogger.Sugar().Infof("added rooms successfully with errors: %d and success: %d of amount: %d", errCount, successCount, amount) + if errCount == 0 { + executionLogger.Sugar().Debugf("added rooms successfully with errors: %d and success: %d of amount: %d", errCount, successCount, amount) + } else { + executionLogger.Sugar().Infof("added rooms successfully with errors: %d and success: %d of amount: %d", errCount, successCount, amount) + } ex.operationManager.AppendOperationEventToExecutionHistory(ctx, op, fmt.Sprintf("added %d rooms", amount)) return nil } diff --git a/internal/core/operations/rooms/remove/executor.go b/internal/core/operations/rooms/remove/executor.go index ae187262..cbc33430 100644 --- a/internal/core/operations/rooms/remove/executor.go +++ b/internal/core/operations/rooms/remove/executor.go @@ -138,7 +138,7 @@ func (e *Executor) removeRoomsByAmount(ctx context.Context, logger *zap.Logger, return err } - logger.Info("removing rooms by amount sorting by version", + logger.Debug("removing rooms by amount sorting by version", zap.Array("rooms:", zapcore.ArrayMarshalerFunc(func(enc zapcore.ArrayEncoder) error { for _, room := range rooms { enc.AppendString(fmt.Sprintf("%s-%s-%s", room.ID, room.Version, room.Status.String())) diff --git a/internal/core/operations/schedulers/newversion/executor.go b/internal/core/operations/schedulers/newversion/executor.go index 88cf7739..2c34ca38 100644 --- a/internal/core/operations/schedulers/newversion/executor.go +++ b/internal/core/operations/schedulers/newversion/executor.go @@ -127,8 +127,8 @@ func (ex *Executor) Execute(ctx context.Context, op *operation.Operation, defini } ex.operationManager.AppendOperationEventToExecutionHistory(ctx, op, fmt.Sprintf(enqueuedSwitchVersionMessageTemplate, switchOpID)) - logger.Sugar().Infof("new scheduler version created: %s, is major: %t", newScheduler.Spec.Version, isSchedulerMajorVersion) - logger.Sugar().Infof("%s operation succeded, %s operation enqueued to continue scheduler update process, switching to version %s", opDef.Name(), switchversion.OperationName, newScheduler.Spec.Version) + logger.Sugar().Debug("new scheduler version created: %s, is major: %t", newScheduler.Spec.Version, isSchedulerMajorVersion) + logger.Sugar().Debug("%s operation succeded, %s operation enqueued to continue scheduler update process, switching to version %s", opDef.Name(), switchversion.OperationName, newScheduler.Spec.Version) return nil } diff --git a/internal/core/operations/schedulers/switchversion/executor.go b/internal/core/operations/schedulers/switchversion/executor.go index 04832f29..f694d88f 100644 --- a/internal/core/operations/schedulers/switchversion/executor.go +++ b/internal/core/operations/schedulers/switchversion/executor.go @@ -56,7 +56,7 @@ func (ex *Executor) Execute(ctx context.Context, op *operation.Operation, defini zap.String(logs.LogFieldOperationPhase, "Execute"), zap.String(logs.LogFieldOperationID, op.ID), ) - logger.Info("start switching scheduler active version") + logger.Debug("start switching scheduler active version") updateDefinition, ok := definition.(*Definition) if !ok { diff --git a/internal/core/services/workers/workers_manager.go b/internal/core/services/workers/workers_manager.go index f28ae115..e2ed5354 100644 --- a/internal/core/services/workers/workers_manager.go +++ b/internal/core/services/workers/workers_manager.go @@ -134,14 +134,14 @@ func (w *WorkersManager) SyncWorkers(ctx context.Context) error { desirableWorkers := w.getDesirableWorkers(schedulers) for name, worker := range desirableWorkers { w.startWorker(ctx, name, worker) - w.logger.Info("new operation worker running", zap.String("scheduler", name)) + w.logger.Debug("new operation worker running", zap.String("scheduler", name)) reportWorkerStart(name, w.builder.ComponentName) } dispensableWorkers := w.getDispensableWorkers(schedulers) for name, worker := range dispensableWorkers { worker.Stop(ctx) - w.logger.Info("canceling operation worker", zap.String("scheduler", name)) + w.logger.Debug("canceling operation worker", zap.String("scheduler", name)) reportWorkerStop(name, w.builder.ComponentName) } diff --git a/internal/core/services/workers/workers_manager_test.go b/internal/core/services/workers/workers_manager_test.go index 3359999f..a0e14cbf 100644 --- a/internal/core/services/workers/workers_manager_test.go +++ b/internal/core/services/workers/workers_manager_test.go @@ -107,7 +107,7 @@ func TestStart(t *testing.T) { }, time.Second, 100*time.Millisecond) assertLogMessages(t, recorded, map[zapcore.Level][]string{ - zap.InfoLevel: {"new operation worker running"}, + zap.DebugLevel: {"new operation worker running"}, }) // guarantees we finish the process. @@ -293,7 +293,7 @@ func TestStart(t *testing.T) { }, 5*time.Second, 100*time.Millisecond) assertLogMessages(t, recorded, map[zapcore.Level][]string{ - zap.InfoLevel: {"new operation worker running"}, + zap.DebugLevel: {"new operation worker running"}, }) // guarantees we finish the process. diff --git a/internal/core/worker/operationexecution/operation_execution_worker.go b/internal/core/worker/operationexecution/operation_execution_worker.go index f90a0ded..87f90ab7 100644 --- a/internal/core/worker/operationexecution/operation_execution_worker.go +++ b/internal/core/worker/operationexecution/operation_execution_worker.go @@ -200,7 +200,7 @@ func (w *OperationExecutionWorker) executeOperationFlow(operationID string) erro } func (w *OperationExecutionWorker) rollbackOperation(ctx context.Context, op *operation.Operation, def operations.Definition, executionErr error, loopLogger *zap.Logger, executor operations.Executor) { - loopLogger.Info("rolling back operation") + loopLogger.Debug("rolling back operation") w.operationManager.AppendOperationEventToExecutionHistory(ctx, op, "Starting operation rollback") rollbackErr := w.executeRollbackCollectingLatencyMetrics(op.DefinitionName, func() error { return executor.Rollback(ctx, op, def, executionErr) @@ -333,7 +333,7 @@ func (w *OperationExecutionWorker) AbortOngoingOperations(ctx context.Context) { } func (w *OperationExecutionWorker) Stop(_ context.Context) { - w.logger.Info("stopping operation execution worker") + w.logger.Debug("stopping operation execution worker") defer w.isStopping.Store(false) defer w.cancelWorkerContext() @@ -352,12 +352,12 @@ func (w *OperationExecutionWorker) Stop(_ context.Context) { defer w.abortingOperationsGroup.Done() if len(w.operationsToAbort) == 0 { - w.logger.Info("no operations to abort, worker stopping") + w.logger.Debug("no operations to abort, worker stopping") return } w.AbortOngoingOperations(context.Background()) - w.logger.Info("operations aborted, worker stopping") + w.logger.Debug("operations aborted, worker stopping") } func (w *OperationExecutionWorker) IsRunning() bool { diff --git a/internal/core/worker/runtimewatcher/runtime_watcher_worker.go b/internal/core/worker/runtimewatcher/runtime_watcher_worker.go index 9e8c6123..3de70bf0 100644 --- a/internal/core/worker/runtimewatcher/runtime_watcher_worker.go +++ b/internal/core/worker/runtimewatcher/runtime_watcher_worker.go @@ -83,7 +83,7 @@ func (w *runtimeWatcherWorker) spawnUpdateRoomWatchers(resultChan chan game_room go func(goroutineNumber int) { defer w.workerWaitGroup.Done() goroutineLogger := w.logger.With(zap.Int("goroutine", goroutineNumber)) - goroutineLogger.Info("Starting event processing goroutine") + goroutineLogger.Debug("Starting event processing goroutine") for { select { case event, ok := <-resultChan: @@ -102,7 +102,7 @@ func (w *runtimeWatcherWorker) spawnUpdateRoomWatchers(resultChan chan game_room reportEventProcessingStatus(event, true) } case <-w.ctx.Done(): - w.logger.Info("context closed, exiting update rooms watcher") + w.logger.Debug("context closed, exiting update rooms watcher") return } } @@ -172,7 +172,7 @@ func (w *runtimeWatcherWorker) spawnWatchers( } func (w *runtimeWatcherWorker) Start(ctx context.Context) error { - w.logger.Info("starting runtime watcher", zap.String("scheduler", w.scheduler.Name)) + w.logger.Debug("starting runtime watcher", zap.String("scheduler", w.scheduler.Name)) watcher, err := w.runtime.WatchGameRoomInstances(ctx, w.scheduler) if err != nil { return fmt.Errorf("failed to start watcher: %w", err) @@ -182,10 +182,10 @@ func (w *runtimeWatcherWorker) Start(ctx context.Context) error { defer w.cancelFunc() w.spawnWatchers(watcher.ResultChan()) - w.logger.Info("spawned all goroutines", zap.String("scheduler", w.scheduler.Name)) + w.logger.Debug("spawned all goroutines", zap.String("scheduler", w.scheduler.Name)) w.workerWaitGroup.Wait() - w.logger.Info("wait group ended, all goroutines stopped", zap.String("scheduler", w.scheduler.Name)) + w.logger.Debug("wait group ended, all goroutines stopped", zap.String("scheduler", w.scheduler.Name)) watcher.Stop() return nil } @@ -199,7 +199,7 @@ func (w *runtimeWatcherWorker) Stop(_ context.Context) { if w.logger != nil { // Ensure logger is available if w.scheduler != nil { - w.logger.Info("stopping runtime watcher", zap.String(logs.LogFieldSchedulerName, w.scheduler.Name)) + w.logger.Debug("stopping runtime watcher", zap.String(logs.LogFieldSchedulerName, w.scheduler.Name)) } else { w.logger.Error("stopping runtime watcher: scheduler field was nil at stop") } From d878eb9ef8d6658858308b63dafb07c72106b1aa Mon Sep 17 00:00:00 2001 From: "eduardo.villani" Date: Thu, 23 Apr 2026 14:32:10 -0300 Subject: [PATCH 3/6] fix: use Debugf instead of Debug for format string logs Co-Authored-By: Claude Opus 4.6 --- internal/core/operations/schedulers/newversion/executor.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/internal/core/operations/schedulers/newversion/executor.go b/internal/core/operations/schedulers/newversion/executor.go index 2c34ca38..c828e77a 100644 --- a/internal/core/operations/schedulers/newversion/executor.go +++ b/internal/core/operations/schedulers/newversion/executor.go @@ -127,8 +127,8 @@ func (ex *Executor) Execute(ctx context.Context, op *operation.Operation, defini } ex.operationManager.AppendOperationEventToExecutionHistory(ctx, op, fmt.Sprintf(enqueuedSwitchVersionMessageTemplate, switchOpID)) - logger.Sugar().Debug("new scheduler version created: %s, is major: %t", newScheduler.Spec.Version, isSchedulerMajorVersion) - logger.Sugar().Debug("%s operation succeded, %s operation enqueued to continue scheduler update process, switching to version %s", opDef.Name(), switchversion.OperationName, newScheduler.Spec.Version) + logger.Sugar().Debugf("new scheduler version created: %s, is major: %t", newScheduler.Spec.Version, isSchedulerMajorVersion) + logger.Sugar().Debugf("%s operation succeded, %s operation enqueued to continue scheduler update process, switching to version %s", opDef.Name(), switchversion.OperationName, newScheduler.Spec.Version) return nil } From c0738dd8f481d540d4c3356aef08a3538ae18aa5 Mon Sep 17 00:00:00 2001 From: "eduardo.villani" Date: Thu, 23 Apr 2026 15:06:14 -0300 Subject: [PATCH 4/6] fix: stabilize flaky TestStart by using AnyTimes and DebugLevel observer Co-Authored-By: Claude Opus 4.6 --- .../services/workers/workers_manager_test.go | 39 ++++++++++++------- 1 file changed, 24 insertions(+), 15 deletions(-) diff --git a/internal/core/services/workers/workers_manager_test.go b/internal/core/services/workers/workers_manager_test.go index a0e14cbf..945b0538 100644 --- a/internal/core/services/workers/workers_manager_test.go +++ b/internal/core/services/workers/workers_manager_test.go @@ -52,7 +52,7 @@ var ( ) func BeforeTest(t *testing.T) { - core, observer := observer.New(zap.InfoLevel) + core, observer := observer.New(zap.DebugLevel) zl := zap.New(core) zap.ReplaceGlobals(zl) recorded = observer @@ -86,7 +86,7 @@ func TestStart(t *testing.T) { End: 10000, }, }, - }, nil) + }, nil).AnyTimes() workersManager := NewWorkersManager(workerBuilder, configs, schedulerStorage, nil) @@ -281,7 +281,7 @@ func TestStart(t *testing.T) { End: 10000, }, }, - }, nil) + }, nil).AnyTimes() require.Eventually(t, func() bool { if len(workersManager.CurrentWorkers) > 0 { @@ -325,18 +325,26 @@ func TestStart(t *testing.T) { ctx, cancelFn := context.WithCancel(context.Background()) configs.EXPECT().GetDuration(syncWorkersIntervalPath).Return(time.Second) configs.EXPECT().GetDuration(WorkersStopTimeoutDurationPath).Return(10 * time.Second) - schedulerStorage.EXPECT().GetAllSchedulers(ctx).Times(3).Return([]*entities.Scheduler{ - { - Name: "zooba-us", - Game: "zooba", - State: entities.StateCreating, - RollbackVersion: "1.0.0", - PortRange: &port.PortRange{ - Start: 1, - End: 10000, + + // Use a flag to switch the return value after workers are started. + removeSchedulers := false + schedulerStorage.EXPECT().GetAllSchedulers(ctx).DoAndReturn(func(_ context.Context) ([]*entities.Scheduler, error) { + if removeSchedulers { + return []*entities.Scheduler{}, nil + } + return []*entities.Scheduler{ + { + Name: "zooba-us", + Game: "zooba", + State: entities.StateCreating, + RollbackVersion: "1.0.0", + PortRange: &port.PortRange{ + Start: 1, + End: 10000, + }, }, - }, - }, nil) + }, nil + }).AnyTimes() workersManager := NewWorkersManager(workerBuilder, configs, schedulerStorage, nil) @@ -354,7 +362,8 @@ func TestStart(t *testing.T) { require.Contains(t, workersManager.CurrentWorkers, "zooba-us") - schedulerStorage.EXPECT().GetAllSchedulers(ctx).Return([]*entities.Scheduler{}, nil) + // Signal that schedulers should be removed on the next sync. + removeSchedulers = true // wait until the workers are stopped. require.Eventually(t, func() bool { From 4502ca1ac703e12c53fcbcc3e053dc95bed84beb Mon Sep 17 00:00:00 2001 From: "eduardo.villani" Date: Fri, 24 Apr 2026 16:03:33 -0300 Subject: [PATCH 5/6] fix: handle empty pod phase as pending instead of error When a pod is freshly created, K8s hasn't set the phase yet and it comes as an empty string. The default branch in convertPodStatus was mapping this to InstanceError, causing unnecessary log noise and incorrect room status. Now treats empty phase as InstancePending. Also fixes PodFailed log level from Error back to Warn (accidentally promoted in 5667a81b). Co-Authored-By: Claude Opus 4.6 --- internal/adapters/runtime/kubernetes/game_room_convert.go | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/internal/adapters/runtime/kubernetes/game_room_convert.go b/internal/adapters/runtime/kubernetes/game_room_convert.go index 2e331662..083bd442 100644 --- a/internal/adapters/runtime/kubernetes/game_room_convert.go +++ b/internal/adapters/runtime/kubernetes/game_room_convert.go @@ -303,7 +303,7 @@ func convertPodStatus(pod *v1.Pod) game_room.InstanceStatus { zap.L().Debug("pod phase -> instance status mapping", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("phase", string(pod.Status.Phase)), zap.String("mappedTo", game_room.InstanceTerminating.String())) return game_room.InstanceStatus{Type: game_room.InstanceTerminating, Description: "PodSucceeded"} case v1.PodFailed: - zap.L().Error("pod phase -> instance status mapping", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("phase", string(pod.Status.Phase)), zap.String("mappedTo", game_room.InstanceError.String())) + zap.L().Warn("pod phase -> instance status mapping", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("phase", string(pod.Status.Phase)), zap.String("mappedTo", game_room.InstanceError.String())) return game_room.InstanceStatus{Type: game_room.InstanceError, Description: "PodFailed"} case v1.PodUnknown: // Unknown pods should not be treated as available @@ -390,6 +390,8 @@ func convertPodStatus(pod *v1.Pod) game_room.InstanceStatus { case v1.PodRunning: zap.L().Debug("pod phase -> instance status mapping", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("phase", string(pod.Status.Phase)), zap.String("mappedTo", game_room.InstanceReady.String())) return game_room.InstanceStatus{Type: game_room.InstanceReady, Description: ""} + case "": // fresh pod, K8s hasn't set phase yet — treat as pending + return game_room.InstanceStatus{Type: game_room.InstancePending} default: // Handle any future pod phases that might be added to Kubernetes zap.L().Warn("unexpected pod phase; mapping to error", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("phase", string(pod.Status.Phase)), zap.String("mappedTo", game_room.InstanceError.String())) From c56a9626d9a4fe74ec4d14154602cd4dbed32bdc Mon Sep 17 00:00:00 2001 From: "eduardo.villani" Date: Fri, 24 Apr 2026 16:08:00 -0300 Subject: [PATCH 6/6] test: add comprehensive convertPodStatus tests + add description to empty phase Adds tests for: empty phase, PodFailed, PodSucceeded, PodUnknown, pod deletion, container terminated (success/error), running without ready condition. Also adds "PodPhaseNotSet" description to the empty phase case. Co-Authored-By: Claude Opus 4.6 --- .../runtime/kubernetes/game_room_convert.go | 2 +- .../kubernetes/game_room_convert_test.go | 96 +++++++++++++++++++ 2 files changed, 97 insertions(+), 1 deletion(-) diff --git a/internal/adapters/runtime/kubernetes/game_room_convert.go b/internal/adapters/runtime/kubernetes/game_room_convert.go index 083bd442..e74448b8 100644 --- a/internal/adapters/runtime/kubernetes/game_room_convert.go +++ b/internal/adapters/runtime/kubernetes/game_room_convert.go @@ -391,7 +391,7 @@ func convertPodStatus(pod *v1.Pod) game_room.InstanceStatus { zap.L().Debug("pod phase -> instance status mapping", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("phase", string(pod.Status.Phase)), zap.String("mappedTo", game_room.InstanceReady.String())) return game_room.InstanceStatus{Type: game_room.InstanceReady, Description: ""} case "": // fresh pod, K8s hasn't set phase yet — treat as pending - return game_room.InstanceStatus{Type: game_room.InstancePending} + return game_room.InstanceStatus{Type: game_room.InstancePending, Description: "PodPhaseNotSet"} default: // Handle any future pod phases that might be added to Kubernetes zap.L().Warn("unexpected pod phase; mapping to error", zap.String("pod", pod.Namespace+"/"+pod.Name), zap.String("phase", string(pod.Status.Phase)), zap.String("mappedTo", game_room.InstanceError.String())) diff --git a/internal/adapters/runtime/kubernetes/game_room_convert_test.go b/internal/adapters/runtime/kubernetes/game_room_convert_test.go index aa45d86a..650c840f 100644 --- a/internal/adapters/runtime/kubernetes/game_room_convert_test.go +++ b/internal/adapters/runtime/kubernetes/game_room_convert_test.go @@ -789,6 +789,102 @@ func TestConvertPodStatus(t *testing.T) { Description: "RunContainerError: failed to find executable", }, }, + "empty phase fresh pod": { + pod: &v1.Pod{ + Status: v1.PodStatus{ + Phase: "", + }, + }, + expectedStatus: game_room.InstanceStatus{ + Type: game_room.InstancePending, + Description: "PodPhaseNotSet", + }, + }, + "pod failed": { + pod: &v1.Pod{ + Status: v1.PodStatus{ + Phase: v1.PodFailed, + }, + }, + expectedStatus: game_room.InstanceStatus{ + Type: game_room.InstanceError, + Description: "PodFailed", + }, + }, + "pod succeeded": { + pod: &v1.Pod{ + Status: v1.PodStatus{ + Phase: v1.PodSucceeded, + }, + }, + expectedStatus: game_room.InstanceStatus{ + Type: game_room.InstanceTerminating, + Description: "PodSucceeded", + }, + }, + "pod unknown": { + pod: &v1.Pod{ + Status: v1.PodStatus{ + Phase: v1.PodUnknown, + }, + }, + expectedStatus: game_room.InstanceStatus{ + Type: game_room.InstanceError, + Description: "PodUnknown", + }, + }, + "pod being deleted": { + pod: &v1.Pod{ + ObjectMeta: metav1.ObjectMeta{ + DeletionTimestamp: &metav1.Time{Time: time.Now()}, + }, + Status: v1.PodStatus{ + Phase: v1.PodRunning, + }, + }, + expectedStatus: game_room.InstanceStatus{ + Type: game_room.InstanceTerminating, + }, + }, + "container terminated successfully": { + pod: &v1.Pod{ + Status: v1.PodStatus{ + Phase: v1.PodRunning, + ContainerStatuses: []v1.ContainerStatus{ + {State: v1.ContainerState{Terminated: &v1.ContainerStateTerminated{Reason: "Completed", ExitCode: 0}}}, + }, + }, + }, + expectedStatus: game_room.InstanceStatus{ + Type: game_room.InstanceTerminating, + Description: "Completed", + }, + }, + "container terminated with error": { + pod: &v1.Pod{ + Status: v1.PodStatus{ + Phase: v1.PodRunning, + ContainerStatuses: []v1.ContainerStatus{ + {State: v1.ContainerState{Terminated: &v1.ContainerStateTerminated{Reason: "OOMKilled", ExitCode: 137}}}, + }, + }, + }, + expectedStatus: game_room.InstanceStatus{ + Type: game_room.InstanceError, + Description: "OOMKilled", + }, + }, + "running without ready condition": { + pod: &v1.Pod{ + Status: v1.PodStatus{ + Phase: v1.PodRunning, + }, + }, + expectedStatus: game_room.InstanceStatus{ + Type: game_room.InstanceReady, + Description: "", + }, + }, } for name, test := range cases {