diff --git a/runner/internal/shim/backends/aws.go b/runner/internal/shim/backends/aws.go index 355c4ff29..da91b2cd5 100644 --- a/runner/internal/shim/backends/aws.go +++ b/runner/internal/shim/backends/aws.go @@ -55,7 +55,7 @@ func (e *AWSBackend) GetRealDeviceName(ctx context.Context, volumeID, deviceName if time.Now().After(deadline) { return "", fmt.Errorf("volume %s not found among block devices after %s", volumeID, deviceResolveTimeout) } - log.Debug(ctx, "volume not yet visible among block devices, retrying", "volume", volumeID) + log.Trace(ctx, "volume not yet visible among block devices, retrying", "volume", volumeID) time.Sleep(deviceResolveInterval) } diff --git a/runner/internal/shim/docker.go b/runner/internal/shim/docker.go index aa5d27dd4..af6d4b07d 100644 --- a/runner/internal/shim/docker.go +++ b/runner/internal/shim/docker.go @@ -463,7 +463,7 @@ func (d *DockerRunner) Start(ctx context.Context, taskID string) (err error) { if err != nil { return fmt.Errorf("make runner dir: %w", err) } - log.Debug(ctx, "runner dir", "task", task.ID, "path", runnerDir) + log.Trace(ctx, "runner dir", "task", task.ID, "path", runnerDir) // Resources are committed as soon as they are acquired, so that they are not // lost if the task is updated by another goroutine, e.g., terminated by the server if err := d.commit(&task, func(t *Task) { t.runnerDir = runnerDir }); err != nil { @@ -496,7 +496,6 @@ func (d *DockerRunner) Start(ctx context.Context, taskID string) (err error) { } } - log.Debug(ctx, "Preparing volumes") // Volumes mounted by a failed prepareVolumes() call are unmounted by cleanupLocked() err = prepareVolumes(ctx, cfg) if err != nil { @@ -540,7 +539,7 @@ func (d *DockerRunner) Start(ctx context.Context, taskID string) (err error) { return fmt.Errorf("create container: %w", err) } - log.Debug(ctx, "Running container", "task", task.ID, "name", task.containerName) + log.Debug(ctx, "Starting container", "task", task.ID, "name", task.containerName) err = d.startContainer(ctx, &task) if len(task.config.GPUDevices) == 0 && shouldRetryWithoutNvidiaDisplayCapability(d.gpuVendor, err) { @@ -582,7 +581,7 @@ func (d *DockerRunner) Start(ctx context.Context, taskID string) (err error) { } started = true - log.Debug(ctx, "Container is running", "task", task.ID, "name", task.containerName) + log.Debug(ctx, "Task started", "task", task.ID, "name", task.containerName) return nil } @@ -677,7 +676,9 @@ func (d *DockerRunner) terminate(ctx context.Context, task *Task, timeout uint, d.cleanupLocked(ctx, task) } task.SetStatusTerminated(reason, message) - log.Debug(ctx, "terminated", "task", task.ID) + // Logged a level below the spontaneous termination reported by ProcessTasks(): + // this one is requested by the caller, which reports it on its own + log.Debug(ctx, "terminated", "task", task.ID, "reason", reason) return nil } diff --git a/runner/internal/shim/process.go b/runner/internal/shim/process.go index 0f658c22b..920caf658 100644 --- a/runner/internal/shim/process.go +++ b/runner/internal/shim/process.go @@ -88,7 +88,7 @@ func (d *DockerRunner) processTask(ctx context.Context, taskID string, container // the same lock if !task.TryLock(ctx) { // The task is busy, e.g., being terminated or removed. Try again on the next call - log.Debug(ctx, "skip processing: task is busy", "task", taskID) + log.Trace(ctx, "skip processing: task is busy", "task", taskID) return } defer func() { task.Release(ctx) }() diff --git a/runner/internal/shim/resources.go b/runner/internal/shim/resources.go index e0d888873..6d64d8a07 100644 --- a/runner/internal/shim/resources.go +++ b/runner/internal/shim/resources.go @@ -94,7 +94,8 @@ func (gl *GpuLock) Acquire(ctx context.Context, count int) ([]string, error) { } // Lock marks passed Resource IDs as locked (busy) -// This method never fails, it's safe to lock already locked resource or try to lock unknown resource +// This method never fails: an already locked or unknown resource is skipped and +// reported as a warning, as neither is expected during normal operation // The returned slice contains only actually locked resource IDs func (gl *GpuLock) Lock(ctx context.Context, ids []string) []string { gl.mu.Lock() @@ -104,7 +105,7 @@ func (gl *GpuLock) Lock(ctx context.Context, ids []string) []string { if locked, ok := gl.lock[id]; !ok { log.Warning(ctx, "skip locking: unknown GPU resource", "id", id) } else if locked { - log.Info(ctx, "skip locking: GPU already locked", "id", id) + log.Warning(ctx, "skip locking: GPU already locked", "id", id) } else { gl.lock[id] = true lockedIDs = append(lockedIDs, id) @@ -114,7 +115,8 @@ func (gl *GpuLock) Lock(ctx context.Context, ids []string) []string { } // Release marks passed Resource IDs as idle -// This method never fails, it's safe to release already idle resource or try to release unknown resource +// This method never fails: an already idle or unknown resource is skipped and +// reported as a warning, as neither is expected during normal operation // The returned slice contains only actually released resource IDs func (gl *GpuLock) Release(ctx context.Context, ids []string) []string { gl.mu.Lock() @@ -124,7 +126,7 @@ func (gl *GpuLock) Release(ctx context.Context, ids []string) []string { if locked, ok := gl.lock[id]; !ok { log.Warning(ctx, "skip releasing: unknown GPU resource", "id", id) } else if !locked { - log.Info(ctx, "skip releasing: GPU not locked", "id", id) + log.Warning(ctx, "skip releasing: GPU not locked", "id", id) } else { gl.lock[id] = false releasedIDs = append(releasedIDs, id) diff --git a/runner/internal/shim/task.go b/runner/internal/shim/task.go index e6b5790fe..67ee0edc3 100644 --- a/runner/internal/shim/task.go +++ b/runner/internal/shim/task.go @@ -61,17 +61,17 @@ type Task struct { // being processed in the background. func (t *Task) Lock(ctx context.Context) { t.mu.Lock() - log.Debug(ctx, "locked", "task", t.ID) + log.Trace(ctx, "locked", "task", t.ID) } // TryLock is a non-blocking version of Lock. It reports whether the lock has // been acquired, so that the caller can retry later instead of waiting. func (t *Task) TryLock(ctx context.Context) bool { if !t.mu.TryLock() { - log.Debug(ctx, "already locked", "task", t.ID) + log.Trace(ctx, "already locked", "task", t.ID) return false } - log.Debug(ctx, "locked", "task", t.ID) + log.Trace(ctx, "locked", "task", t.ID) return true } @@ -80,7 +80,7 @@ func (t *Task) TryLock(ctx context.Context) bool { // looks like lock: https://github.com/golang/go/issues/18451 func (t *Task) Release(ctx context.Context) { t.mu.Unlock() - log.Debug(ctx, "unlocked", "task", t.ID) + log.Trace(ctx, "unlocked", "task", t.ID) } func (t *Task) IsTransitionAllowed(toStatus TaskStatus) bool { diff --git a/runner/internal/shim/volumes.go b/runner/internal/shim/volumes.go index 99469c84d..ed88acad1 100644 --- a/runner/internal/shim/volumes.go +++ b/runner/internal/shim/volumes.go @@ -17,6 +17,10 @@ import ( ) func prepareVolumes(ctx context.Context, taskConfig TaskConfig) error { + if len(taskConfig.Volumes) == 0 { + return nil + } + log.Debug(ctx, "Preparing volumes...") for _, volume := range taskConfig.Volumes { err := formatAndMountVolume(ctx, volume) if err != nil {