Merge pull request #51 from stealthrocket/timecraft-log

timecraft: add logs command

config.go

@@ -22,7 +22,7 @@ const configUsage = `
 Usage: timecraft config [options]
 
 Options:
- -c, --config   Path to the timecraft configuration file (overrides TIMECRAFTCONFIG)
+ -c, --config path Path to the timecraft configuration file (overrides TIMECRAFTCONFIG)
  --edit Open $EDITOR to edit the configuration
  -h, --help Show usage information
  -o, --output format Output format, one of: text, json, yaml

describe.go

@@ -41,7 +41,7 @@ Examples:
  Version: devel
 
 Options:
- -c, --config   Path to the timecraft configuration file (overrides TIMECRAFTCONFIG)
+ -c, --config path Path to the timecraft configuration file (overrides TIMECRAFTCONFIG)
  -h, --help Show this usage information
  -o, --output format Output format, one of: text, json, yaml
  -v, --verbose For text output, display more details about the resource

export.go

@@ -22,8 +22,8 @@ Usage: timecraft export <resource type> <resource id> <output file> [options]
  resource to stdout.
 
 Options:
- -c, --config Path to the timecraft configuration file (overrides TIMECRAFTCONFIG)
- -h, --help Show this usage information
+ -c, --config path  Path to the timecraft configuration file (overrides TIMECRAFTCONFIG)
+ -h, --help  Show this usage information
 `
 
 func export(ctx context.Context, args []string) error {

get.go

@@ -44,7 +44,7 @@ Examples:
  }
 
 Options:
- -c, --config   Path to the timecraft configuration file (overrides TIMECRAFTCONFIG)
+ -c, --config path Path to the timecraft configuration file (overrides TIMECRAFTCONFIG)
  -h, --help Show this usage information
  -o, --output format Output format, one of: text, json, yaml
  -q, --quiet Only display the resource ids

help.go

@@ -19,6 +19,7 @@ Runtime Commands:
  replay Replay a recorded trace of execution
 
 Debugging Commands:
+ logs Print the logs for a module execution
  profile Generate performance profile from execution records
 
 Other Commands:
@@ -27,8 +28,8 @@ Other Commands:
  version Show the timecraft version information
 
 Global Options:
- -c, --config Path to the timecraft configuration file (overrides TIMECRAFTCONFIG)
- -h, --help Show usage information
+ -c, --config path  Path to the timecraft configuration file (overrides TIMECRAFTCONFIG)
+ -h, --help  Show usage information
 
 For a description of each command, run 'timecraft help <command>'.`
 
@@ -61,6 +62,8 @@ func help(ctx context.Context, args []string) error {
  msg = getUsage
  case "help":
  msg = helpUsage
+ case "logs":
+ msg = logsUsage
  case "profile":
  msg = profileUsage
  case "run":

internal/debug/stdio/limit.go

@@ -0,0 +1,39 @@
+package stdio
+
+import (
+ "bytes"
+ "io"
+)
+
+type Limit struct {
+ R io.Reader
+ N int
+}
+
+func (r *Limit) Read(b []byte) (int, error) {
+ if r.N <= 0 {
+ return 0, io.EOF
+ }
+
+ n, err := r.R.Read(b)
+
+ nl := bytes.Count(b[:n], []byte{'\n'})
+ if nl <= r.N {
+ r.N -= nl
+ if r.N == 0 {
+ n = bytes.LastIndexByte(b[:n], '\n') + 1
+ }
+ return n, err
+ }
+
+ for i, c := range b[:n] {
+ if c != '\n' {
+ continue
+ }
+ if r.N--; r.N == 0 {
+ return i + 1, io.EOF
+ }
+ }
+
+ return n, io.EOF
+}

internal/debug/stdio/limit_test.go

@@ -0,0 +1,39 @@
+package stdio_test
+
+import (
+ "bytes"
+ "strings"
+ "testing"
+
+ "github.com/stealthrocket/timecraft/internal/assert"
+ "github.com/stealthrocket/timecraft/internal/debug/stdio"
+)
+
+func TestLimit(t *testing.T) {
+ const text = `hello world!
+second line
+third line
+a
+b
+the last line has no return`
+
+ for limit := 0; limit < 10; limit++ {
+ t.Run("", func(t *testing.T) {
+ lines := strings.Split(text, "\n")
+ if len(lines) > limit {
+ lines = lines[:limit]
+ if limit > 0 {
+ lines[limit-1] += "\n"
+ }
+ }
+ output := strings.Join(lines, "\n")
+ buffer := new(bytes.Buffer)
+ _, err := buffer.ReadFrom(&stdio.Limit{
+ R: strings.NewReader(text),
+ N: limit,
+ })
+ assert.OK(t, err)
+ assert.Equal(t, buffer.String(), output)
+ })
+ }
+}

internal/debug/stdio/reader.go

@@ -0,0 +1,111 @@
+package stdio
+
+import (
+ "bytes"
+ "io"
+ "math"
+ "time"
+
+ "github.com/stealthrocket/timecraft/internal/stream"
+ "github.com/stealthrocket/timecraft/internal/timemachine"
+ "github.com/stealthrocket/timecraft/internal/timemachine/wasicall"
+ "github.com/stealthrocket/wasi-go"
+)
+
+type Reader struct {
+ Records stream.Reader[timemachine.Record]
+ StartTime time.Time
+ Stdout int
+ Stderr int
+
+ buffer bytes.Buffer
+ stdout wasi.FD
+ stderr wasi.FD
+ iovecs []wasi.IOVec
+ codec wasicall.Codec
+ records [100]timemachine.Record
+}
+
+const noneFD = ^wasi.FD(0)
+
+func makeFD(fd int) wasi.FD {
+ if fd < 0 || fd > math.MaxInt32 {
+ return noneFD
+ }
+ return wasi.FD(fd)
+}
+
+func (r *Reader) Read(b []byte) (n int, err error) {
+ if r.stdout != noneFD {
+ r.stdout = makeFD(r.Stdout)
+ }
+ if r.stderr != noneFD {
+ r.stderr = makeFD(r.Stderr)
+ }
+
+ for {
+ if r.buffer.Len() > 0 {
+ rn, _ := r.buffer.Read(b[n:])
+ n += rn
+ }
+ if n == len(b) || err != nil {
+ return n, err
+ }
+ if r.stdout == noneFD && r.stderr == noneFD {
+ return n, io.EOF
+ }
+ var rn int
+ rn, err = r.Records.Read(r.records[:])
+
+ for _, record := range r.records[:rn] {
+ switch wasicall.SyscallID(record.FunctionID) {
+ case wasicall.FDClose:
+ fd, _, err := r.codec.DecodeFDClose(record.FunctionCall)
+ if err != nil {
+ return n, err
+ }
+ switch fd {
+ case r.stdout:
+ r.stdout = noneFD
+ case r.stderr:
+ r.stderr = noneFD
+ }
+
+ case wasicall.FDRenumber:
+ from, to, errno, err := r.codec.DecodeFDRenumber(record.FunctionCall)
+ if err != nil {
+ return n, err
+ }
+ if errno != wasi.ESUCCESS {
+ continue
+ }
+ switch from {
+ case r.stdout:
+ r.stdout = to
+ case r.stderr:
+ r.stderr = to
+ }
+
+ case wasicall.FDWrite:
+ if record.Time.Before(r.StartTime) {
+ continue
+ }
+ fd, iovecs, size, _, err := r.codec.DecodeFDWrite(record.FunctionCall, r.iovecs[:0])
+ if err != nil {
+ return n, err
+ }
+ switch fd {
+ case r.stdout, r.stderr:
+ for _, iov := range iovecs {
+ iovLen := wasi.Size(len(iov))
+ if iovLen > size {
+ iovLen = size
+ }
+ size -= iovLen
+ r.buffer.Write(iov[:iovLen])
+ }
+ }
+ }
+ }
+ }
+}

logs.go

@@ -0,0 +1,97 @@
+package main
+
+import (
+ "context"
+ "errors"
+ "io"
+ "math"
+ "os"
+ "time"
+
+ "github.com/google/uuid"
+ "github.com/stealthrocket/timecraft/internal/debug/stdio"
+ "github.com/stealthrocket/timecraft/internal/print/human"
+ "github.com/stealthrocket/timecraft/internal/timemachine"
+)
+
+const logsUsage = `
+Usage: timecraft logs [options] <process id>
+
+Example:
+
+ $ timecraft run app.wasm
+ 661fddee-347b-429e-81f5-f45ca153fbb7
+ Hello World!
+
+ $ timecraft logs 661fddee-347b-429e-81f5-f45ca153fbb7
+ Hello World!
+
+Options:
+ -c, --config path Path to the timecraft configuration file (overrides TIMECRAFTCONFIG)
+ -h, --help Show this usage information
+ -n, --limit count Limit the number of log lines to print (default to no limit)
+ -t, --start-time time Time at which the logr gets started (default to 1 minute)
+`
+
+func logs(ctx context.Context, args []string) error {
+ var (
+ limit human.Count
+ startTime = human.Time{}
+ )
+
+ flagSet := newFlagSet("timecraft logs", logsUsage)
+ customVar(flagSet, &limit, "n", "limit")
+ customVar(flagSet, &startTime, "t", "start-time")
+ if limit == 0 {
+ limit = math.MaxInt32
+ }
+
+ args, err := parseFlags(flagSet, args)
+ if err != nil {
+ return err
+ }
+ if len(args) != 1 {
+ return errors.New(`expected exactly one process id as argument`)
+ }
+
+ processID, err := uuid.Parse(args[0])
+ if err != nil {
+ return errors.New(`malformed process id passed as argument (not a UUID)`)
+ }
+ config, err := loadConfig()
+ if err != nil {
+ return err
+ }
+ registry, err := config.openRegistry()
+ if err != nil {
+ return err
+ }
+
+ manifest, err := registry.LookupLogManifest(ctx, processID)
+ if err != nil {
+ return err
+ }
+ if startTime.IsZero() {
+ startTime = human.Time(manifest.StartTime)
+ }
+
+ logSegment, err := registry.ReadLogSegment(ctx, processID, 0)
+ if err != nil {
+ return err
+ }
+ defer logSegment.Close()
+
+ logReader := timemachine.NewLogReader(logSegment, manifest.StartTime)
+ defer logReader.Close()
+
+ _, err = io.Copy(os.Stdout, &stdio.Limit{
+ R: &stdio.Reader{
+ Records: timemachine.NewLogRecordReader(logReader),
+ StartTime: time.Time(startTime),
+ Stdout: 1,
+ Stderr: 2,
+ },
+ N: int(limit),
+ })
+ return err
+}

logs_test.go

@@ -0,0 +1,42 @@
+package main_test
+
+import (
+ "strings"
+ "testing"
+
+ "github.com/stealthrocket/timecraft/internal/assert"
+)
+
+const text = `
+Lorem ipsum dolor sit amet, consectetur adipiscing elit, sed do eiusmod tempor incididunt ut labore et dolore magna aliqua.
+Ut enim ad minim veniam, quis nostrud exercitation ullamco laboris nisi ut aliquip ex ea commodo consequat.
+Duis aute irure dolor in reprehenderit in voluptate velit esse cillum dolore eu fugiat nulla pariatur.
+Excepteur sint occaecat cupidatat non proident, sunt in culpa qui officia deserunt mollit anim id est laborum.`
+
+var logs = tests{
+ "show the logs command help with the short option": func(t *testing.T) {
+ stdout, stderr, exitCode := timecraft(t, "logs", "-h")
+ assert.Equal(t, exitCode, 0)
+ assert.HasPrefix(t, stdout, "Usage:\ttimecraft logs ")
+ assert.Equal(t, stderr, "")
+ },
+
+ "show the logs command help with the long option": func(t *testing.T) {
+ stdout, stderr, exitCode := timecraft(t, "logs", "--help")
+ assert.Equal(t, exitCode, 0)
+ assert.HasPrefix(t, stdout, "Usage:\ttimecraft logs ")
+ assert.Equal(t, stderr, "")
+ },
+
+ "the output of a run is available when printing its logs": func(t *testing.T) {
+ stdout, stderr, exitCode := timecraft(t, "run", "./testdata/go/echo.wasm", "-n", text)
+ assert.Equal(t, exitCode, 0)
+ assert.Equal(t, stdout, text[1:])
+ processID := strings.TrimSpace(stderr)
+
+ stdout, stderr, exitCode = timecraft(t, "logs", processID)
+ assert.Equal(t, exitCode, 0)
+ assert.Equal(t, stdout, text[1:])
+ assert.Equal(t, stderr, "")
+ },
+}