tstor/src/vfs/log.go

package vfs

import (
	"context"
	"errors"
	"fmt"
	"io"
	"io/fs"
	"log/slog"
	"reflect"
	"time"

	"git.kmsign.ru/royalcat/tstor/pkg/rlog"
	"go.opentelemetry.io/otel"
	"go.opentelemetry.io/otel/attribute"
	"go.opentelemetry.io/otel/metric"
	"go.opentelemetry.io/otel/trace"
)

var (
	meter  = otel.Meter("git.kmsign.ru/royalcat/tstor/src/vfs")
	tracer = otel.Tracer("git.kmsign.ru/royalcat/tstor/src/vfs")
)

type fsTelemetry struct {
	openedFiles metric.Int64UpDownCounter
}

type LogFS struct {
	fs  Filesystem
	log *rlog.Logger
	tel *fsTelemetry

	timeout     time.Duration
	readTimeout time.Duration
}

func isLoggableError(err error) bool {
	return err != nil && !errors.Is(err, fs.ErrNotExist) && !errors.Is(err, io.EOF)
}

var _ Filesystem = (*LogFS)(nil)

func WrapLogFS(vfs Filesystem) (*LogFS, error) {
	openedFiles, err := meter.Int64UpDownCounter("vfs.opened_files")
	if err != nil {
		return nil, fmt.Errorf("failed to create opened_files metric: %w", err)
	}

	return &LogFS{
		fs:          vfs,
		log:         rlog.Component("logfs"),
		tel:         &fsTelemetry{openedFiles: openedFiles},
		timeout:     time.Minute * 3,
		readTimeout: time.Minute,
	}, nil
}

// ModTime implements Filesystem.
func (lfs *LogFS) ModTime() time.Time {
	return lfs.ModTime()
}

// Mode implements Filesystem.
func (lfs *LogFS) Mode() fs.FileMode {
	return lfs.Mode()
}

// Size implements Filesystem.
func (lfs *LogFS) Size() int64 {
	return lfs.Size()
}

// Sys implements Filesystem.
func (lfs *LogFS) Sys() any {
	return lfs.Sys()
}

func (fs *LogFS) FsName() string {
	return "logfs"
}

func (fs *LogFS) traceAttrs(add ...attribute.KeyValue) trace.SpanStartOption {
	return trace.WithAttributes(append([]attribute.KeyValue{
		attribute.String("fs", fs.FsName()),
	}, add...)...)
}

// Info implements Filesystem.
func (fs *LogFS) Info() (fs.FileInfo, error) {
	return fs.fs.Info()
}

// IsDir implements Filesystem.
func (fs *LogFS) IsDir() bool {
	return fs.fs.IsDir()
}

// Name implements Filesystem.
func (fs *LogFS) Name() string {
	return fs.fs.Name()
}

// Type implements Filesystem.
func (fs *LogFS) Type() fs.FileMode {
	return fs.fs.Type()
}

// Open implements Filesystem.
func (fs *LogFS) Open(ctx context.Context, filename string) (file File, err error) {
	ctx, cancel := context.WithTimeout(ctx, fs.timeout)
	defer cancel()
	ctx, span := tracer.Start(ctx, "Open",
		fs.traceAttrs(attribute.String("filename", filename)),
	)
	defer func() {
		if err != nil {
			span.RecordError(err)
		}
		span.End()
	}()

	file, err = fs.fs.Open(ctx, filename)
	if isLoggableError(err) {
		fs.log.Error(ctx, "Failed to open file")
	}
	file = wrapLogFile(file, filename, fs.log, fs.readTimeout, fs.tel)

	if file != nil {
		fs.tel.openedFiles.Add(ctx, 1)
	}

	return file, err
}

// ReadDir implements Filesystem.
func (fs *LogFS) ReadDir(ctx context.Context, path string) (entries []fs.DirEntry, err error) {
	ctx, cancel := context.WithTimeout(ctx, fs.timeout)
	defer cancel()
	ctx, span := tracer.Start(ctx, "ReadDir",
		fs.traceAttrs(
			attribute.String("path", path),
			attribute.String("fs-type", reflect.TypeOf(fs.fs).Name()),
		),
	)
	defer func() {
		if err != nil {
			span.RecordError(err)
		}
		span.End()
	}()

	entries, err = fs.fs.ReadDir(ctx, path)
	if isLoggableError(err) {
		fs.log.Error(ctx, "Failed to read dir", rlog.Error(err))
	}
	return entries, err
}

// Stat implements Filesystem.
func (lfs *LogFS) Stat(ctx context.Context, filename string) (info fs.FileInfo, err error) {
	ctx, cancel := context.WithTimeout(ctx, lfs.timeout)
	defer cancel()
	ctx, span := tracer.Start(ctx, "Stat",
		lfs.traceAttrs(attribute.String("filename", filename)),
	)
	defer func() {
		if err != nil {
			span.RecordError(err)
		}
		span.End()
	}()

	info, err = lfs.fs.Stat(ctx, filename)
	if isLoggableError(err) {
		lfs.log.Error(ctx, "Failed to stat", rlog.Error(err))
	}
	return info, err
}

// Unlink implements Filesystem.
func (fs *LogFS) Unlink(ctx context.Context, filename string) (err error) {
	ctx, cancel := context.WithTimeout(ctx, fs.timeout)
	defer cancel()
	ctx, span := tracer.Start(ctx, "Unlink",
		fs.traceAttrs(attribute.String("filename", filename)),
	)
	defer func() {
		if err != nil {
			span.RecordError(err)
		}
		span.End()
	}()

	err = fs.fs.Unlink(ctx, filename)
	if isLoggableError(err) {
		fs.log.Error(ctx, "Failed to stat", rlog.Error(err))
	}
	return err
}

type LogFile struct {
	filename string
	f        File

	log *rlog.Logger
	tel *fsTelemetry

	timeout time.Duration
}

// Name implements File.
func (f *LogFile) Name() string {
	return f.f.Name()
}

// Type implements File.
func (f *LogFile) Type() fs.FileMode {
	return f.f.Type()
}

var _ File = (*LogFile)(nil)

func wrapLogFile(f File, filename string, log *rlog.Logger, timeout time.Duration, tel *fsTelemetry) *LogFile {
	return &LogFile{
		filename: filename,
		f:        f,
		log:      log.With(slog.String("filename", filename)),
		tel:      tel,
		timeout:  timeout,
	}
}

// Close implements File.
func (f *LogFile) Close(ctx context.Context) (err error) {
	ctx, cancel := context.WithTimeout(ctx, f.timeout)
	defer cancel()
	ctx, span := tracer.Start(ctx, "Close",
		trace.WithAttributes(attribute.String("filename", f.filename)),
	)
	defer func() {
		if err != nil {
			span.RecordError(err)
		}
		span.End()
	}()

	err = f.f.Close(ctx)
	if isLoggableError(err) {
		f.log.Error(ctx, "Failed to close", rlog.Error(err))
	}

	if err != nil {
		f.tel.openedFiles.Add(ctx, -1)
	}

	return err
}

// IsDir implements File.
func (f *LogFile) IsDir() bool {
	return f.f.IsDir()
}

// Read implements File.
func (f *LogFile) Read(ctx context.Context, p []byte) (n int, err error) {
	ctx, cancel := context.WithTimeout(ctx, f.timeout)
	defer cancel()
	ctx, span := tracer.Start(ctx, "Read",
		trace.WithAttributes(
			attribute.String("filename", f.filename),
			attribute.Int("length", len(p)),
		),
	)
	defer func() {
		span.SetAttributes(attribute.Int("read", n))
		if err != nil {
			span.RecordError(err)
		}
		span.End()
	}()

	n, err = f.f.Read(ctx, p)
	if isLoggableError(err) {
		f.log.Error(ctx, "Failed to read", rlog.Error(err))
	}
	return n, err
}

// ReadAt implements File.
func (f *LogFile) ReadAt(ctx context.Context, p []byte, off int64) (n int, err error) {
	ctx, cancel := context.WithTimeout(ctx, f.timeout)
	defer cancel()
	ctx, span := tracer.Start(ctx, "ReadAt",
		trace.WithAttributes(
			attribute.String("filename", f.filename),
			attribute.Int("length", len(p)),
			attribute.Int64("offset", off),
		),
	)
	defer func() {
		span.SetAttributes(attribute.Int("read", n))
		if err != nil {
			span.RecordError(err)
		}
		span.End()
	}()

	n, err = f.f.ReadAt(ctx, p, off)
	if isLoggableError(err) {
		f.log.Error(ctx, "Failed to read", rlog.Error(err))
	}
	return n, err
}

// Size implements File.
func (f *LogFile) Size() int64 {
	return f.f.Size()
}

// Stat implements File.
func (f *LogFile) Info() (fs.FileInfo, error) {
	info, err := f.f.Info()
	if isLoggableError(err) {
		f.log.Error(context.Background(), "Failed to info", rlog.Error(err))
	}
	return info, err
}