feat: service logs command to stream service logs (#196)

* chore: fix landing logo shadow * feat: implement service logs command with colored output and strict ordering * revert Makefile * fix after rebase * move logs command under services with root shortcut * simplify server options for streaming logs and CLI flags * refactor ContainerLogs grpc server * update --tail flag * minor docker.proto * refactor client ServiceLogs and ContainerLogs * move ProxyMachinesContext from api to client pkg * minor refactor proto Stream * add api/logs * implement LogMerger * fix LogMerger to correctly use semaphore * increate inflish entries to 100 per stream * send heartbeats * refactor ContainerLogs to synchronise Send of entries and heartbeats to the steram * minor logmerege * remove ContainerName form ServiceLogEntryMetadata * refactor ContainerLogs into docker.Service * detect stalled container logs streams * update logmerger tests * fix comment in test * refactor LogMerger with options * uc logs: format one or multiple services * make LogMerger emit heartbeats, emit entries <= watermark, rewrite tests * update uc logs with new LogMerger * go mod tidy * fix after merge --------- Co-authored-by: Evgenii Orlov <evgenii.orlov@semrush.com>
2026-08-26 19:13:34 +00:00 · 2025-12-02 19:50:48 +10:00
parent 234985b57d
commit 79dc05cb66
25 changed files with 3657 additions and 1925 deletions
@@ -47,6 +47,7 @@ import (
 	"google.golang.org/grpc/codes"
 	"google.golang.org/grpc/status"
 	"google.golang.org/protobuf/types/known/emptypb"
+	"google.golang.org/protobuf/types/known/timestamppb"
 )

 var fullDockerIDRegex = regexp.MustCompile(`^[a-f0-9]{64}$`)
@@ -1015,6 +1016,97 @@ func (s *Server) RemoveServiceContainer(ctx context.Context, req *pb.RemoveConta
 	return resp, nil
 }

+// logsHeartbeatInterval is the interval at which heartbeat entries are sent when there are no logs to stream.
+const logsHeartbeatInterval = 200 * time.Millisecond
+
+// ContainerLogs streams logs from a container.
+func (s *Server) ContainerLogs(
+	req *pb.ContainerLogsRequest, stream grpc.ServerStreamingServer[pb.ContainerLogEntry],
+) error {
+	// Stream context is cancelled when the client has disconnected or the stream has ended.
+	ctx := stream.Context()
+
+	opts := ContainerLogsOptions{
+		ContainerID: req.ContainerId,
+		Follow:      req.Follow,
+		Tail:        int(req.Tail),
+		Since:       req.Since,
+		Until:       req.Until,
+	}
+
+	logsCh, err := s.service.ContainerLogs(ctx, opts)
+	if err != nil {
+		if errdefs.IsNotFound(err) {
+			return status.Error(codes.NotFound, err.Error())
+		}
+		return status.Errorf(codes.Internal, "get container logs: %v", err)
+	}
+
+	log := slog.With("container_id", req.ContainerId, "stream_id", fmt.Sprintf("%p", stream)[2:])
+	log.Debug("Starting container logs streaming.",
+		"follow", req.Follow, "tail", req.Tail, "since", req.Since, "until", req.Until)
+
+	// Heartbeats are needed only when following logs to let the client know when there are no new log entries
+	// to allow it to advance the watermark of last received log timestamp.
+	var heartbeatCh <-chan time.Time
+	if req.Follow {
+		heartbeatTicker := time.NewTicker(logsHeartbeatInterval)
+		defer heartbeatTicker.Stop()
+		heartbeatCh = heartbeatTicker.C
+	}
+
+	started := time.Now()
+	lastSent := time.Time{}
+
+	for {
+		select {
+		case entry, ok := <-logsCh:
+			if !ok {
+				// Channel closed, no more log entries.
+				return nil
+			}
+
+			if entry.Err != nil {
+				return status.Error(codes.Internal, entry.Err.Error())
+			}
+
+			pbEntry := &pb.ContainerLogEntry{
+				Stream:    api.LogStreamTypeToProto(entry.Stream),
+				Timestamp: timestamppb.New(entry.Timestamp),
+				Message:   entry.Message,
+			}
+			if err = stream.Send(pbEntry); err != nil {
+				return status.Errorf(codes.Internal, "send log entry: %v", err)
+			}
+			lastSent = entry.Timestamp
+
+		case now := <-heartbeatCh:
+			// Only send heartbeat if no log entries have been sent since the last heartbeat interval or
+			// if no log entries have been sent at all for at least a heartbeat interval since starting.
+			if now.Sub(lastSent) < logsHeartbeatInterval ||
+				(lastSent.IsZero() && now.Sub(started) < logsHeartbeatInterval) {
+				continue
+			}
+
+			// Use the timestamp one heartbeat in the past to be conservative. This reduces the chance of sending
+			// a timestamp that is greater than a log entry currently being parsed but not yet sent, which would
+			// cause the client to incorrectly believe it has received all logs up to that point.
+			heartbeat := &pb.ContainerLogEntry{
+				Stream:    pb.ContainerLogEntry_HEARTBEAT,
+				Timestamp: timestamppb.New(now.Add(-logsHeartbeatInterval)),
+			}
+			if err = stream.Send(heartbeat); err != nil {
+				return status.Errorf(codes.Internal, "send log stream heartbeat: %v", err)
+			}
+			lastSent = heartbeat.Timestamp.AsTime()
+			log.Debug("Sent log stream heartbeat.", "timestamp", lastSent)
+
+		case <-ctx.Done():
+			return status.Error(codes.Canceled, ctx.Err().Error())
+		}
+	}
+}
+
 // receiveExecConfig receives and validates the initial exec configuration from the stream.
 func (s *Server) receiveExecConfig(stream pb.Docker_ExecContainerServer) (*pb.ExecConfig, api.ExecOptions, error) {
 	req, err := stream.Recv()
@@ -1,18 +1,22 @@
 package docker

 import (
+	"bytes"
 	"context"
 	"database/sql"
 	"encoding/json"
 	"errors"
 	"fmt"
 	"log/slog"
+	"strconv"
 	"strings"
+	"time"

 	"github.com/docker/docker/api/types/container"
 	"github.com/docker/docker/api/types/filters"
 	"github.com/docker/docker/api/types/image"
 	"github.com/docker/docker/client"
+	"github.com/docker/docker/pkg/stdcopy"
 	"github.com/jmoiron/sqlx"
 	"github.com/psviderski/uncloud/pkg/api"
 	"google.golang.org/grpc/codes"
@@ -150,3 +154,104 @@ func (s *Service) ListImages(ctx context.Context, opts image.ListOptions) (Image

 	return imagesResp, nil
 }
+
+// ContainerLogsOptions specifies parameters for ContainerLogs.
+type ContainerLogsOptions struct {
+	ContainerID string
+	Follow      bool
+	Tail        int
+	Since       string
+	Until       string
+}
+
+// ContainerLogs streams logs from a container and returns demultiplexed entries via a channel.
+// The channel is closed when streaming completes or context is cancelled.
+func (s *Service) ContainerLogs(ctx context.Context, opts ContainerLogsOptions) (<-chan api.ContainerLogEntry, error) {
+	dockerOpts := container.LogsOptions{
+		ShowStdout: true,
+		ShowStderr: true,
+		Follow:     opts.Follow,
+		Tail:       strconv.FormatInt(int64(opts.Tail), 10),
+		Since:      opts.Since,
+		Until:      opts.Until,
+		Timestamps: true,
+	}
+
+	reader, err := s.Client.ContainerLogs(ctx, opts.ContainerID, dockerOpts)
+	if err != nil {
+		return nil, err
+	}
+
+	outCh := make(chan api.ContainerLogEntry)
+	stdoutWriter := &logsChannelWriter{ctx: ctx, ch: outCh, isStderr: false}
+	stderrWriter := &logsChannelWriter{ctx: ctx, ch: outCh, isStderr: true}
+
+	// Wrap the context in a cancellable one to unblock the second goroutine below when StdCopy completes.
+	ctx, cancel := context.WithCancel(ctx)
+
+	// Run StdCopy in a goroutine to be able to handle context cancellation.
+	go func() {
+		defer close(outCh)
+		defer cancel()
+
+		// StdCopy is blocking and will return when the reader is closed in another goroutine below or on error.
+		if _, err := stdcopy.StdCopy(stdoutWriter, stderrWriter, reader); err != nil {
+			// Send error as the last entry.
+			select {
+			case outCh <- api.ContainerLogEntry{Err: fmt.Errorf("demultiplex container logs: %w", err)}:
+			case <-ctx.Done():
+			}
+		}
+	}()
+
+	// Close the reader when the context is done to cancel StdCopy if it's still running.
+	go func() {
+		<-ctx.Done()
+		reader.Close()
+	}()
+
+	return outCh, nil
+}
+
+// logsChannelWriter is a writer for stdcopy.StdCopy that sends demultiplexed container logs to a channel.
+type logsChannelWriter struct {
+	ctx      context.Context
+	ch       chan<- api.ContainerLogEntry
+	isStderr bool
+}
+
+func (w *logsChannelWriter) Write(data []byte) (n int, err error) {
+	// Parse timestamp and message from the demultiplexed Docker log payload if the data looks like it contains one.
+	// Format: 2025-01-01T00:00:00.000000000Z message
+	timestamp := time.Time{}
+	message := data
+	if len(data) > 30 && data[4] == '-' && data[7] == '-' && data[10] == 'T' {
+		timestampPart, messagePart, found := bytes.Cut(data, []byte(" "))
+		if found {
+			timestamp, err = time.Parse(time.RFC3339Nano, string(timestampPart))
+			if err != nil {
+				timestamp = time.Time{}
+			}
+			message = messagePart
+		}
+	}
+
+	entry := api.ContainerLogEntry{
+		Timestamp: timestamp,
+		// Clone is required because message is a slice into data, which stdcopy.StdCopy may reuse
+		// after Write returns but before the entry is consumed from the channel.
+		Message: bytes.Clone(message),
+	}
+	if w.isStderr {
+		entry.Stream = api.LogStreamStderr
+	} else {
+		entry.Stream = api.LogStreamStdout
+	}
+
+	select {
+	case w.ch <- entry:
+		return len(data), nil
+	case <-w.ctx.Done():
+		return 0, w.ctx.Err()
+	}
+}