fix: machine logs timestamp parsing and streaming for systemd <v255

This commit is contained in:
Pasha Sviderski
2026-04-23 17:31:31 +10:00
parent f379bf4c14
commit 50057c42e0
4 changed files with 132 additions and 16 deletions
+1 -1
View File
@@ -47,7 +47,7 @@ func logs(ctx context.Context, unit string, opts api.ServiceLogsOptions) (io.Rea
}
args = append(args, "-o")
args = append(args, "short-iso-precise")
args = append(args, "short-unix")
if opts.Since != "" {
args = append(args, "-S")
+22 -9
View File
@@ -5,6 +5,7 @@ import (
"context"
"fmt"
"slices"
"strconv"
"time"
"github.com/psviderski/uncloud/pkg/api"
@@ -33,17 +34,12 @@ func Logs(ctx context.Context, unit string, opts api.ServiceLogsOptions) (<-chan
}
func entry(data []byte) api.LogEntry {
// 2025-10-12T11:03:27+02:00 systemd[1]:
// 1758193407.686964 systemd[1]: ...
timestamp := time.Time{}
message := data
if len(data) > 30 && data[4] == '-' && data[7] == '-' && data[10] == 'T' {
timestampPart, messagePart, found := bytes.Cut(data, []byte(" "))
var err error
if found {
timestamp, err = time.Parse(time.RFC3339Nano, string(timestampPart))
if err != nil {
timestamp = time.Time{}
}
if timestampPart, messagePart, found := bytes.Cut(data, []byte(" ")); found {
if t, ok := parseUnixTimestamp(timestampPart); ok {
timestamp = t
message = messagePart
}
}
@@ -54,3 +50,20 @@ func entry(data []byte) api.LogEntry {
Stream: api.LogStreamStdout,
}
}
// parseUnixTimestamp parses a journalctl short-unix timestamp "SSSSSSSSSS.UUUUUU" with microsecond precision.
func parseUnixTimestamp(b []byte) (time.Time, bool) {
secPart, usecPart, found := bytes.Cut(b, []byte("."))
if !found {
return time.Time{}, false
}
sec, err := strconv.ParseInt(string(secPart), 10, 64)
if err != nil {
return time.Time{}, false
}
usec, err := strconv.ParseInt(string(usecPart), 10, 64)
if err != nil {
return time.Time{}, false
}
return time.Unix(sec, usec*1000), true
}
+103
View File
@@ -11,6 +11,109 @@ import (
"github.com/stretchr/testify/require"
)
func TestParseUnixTimestamp(t *testing.T) {
tests := []struct {
name string
input string
want time.Time
ok bool
}{
{
name: "valid with microseconds",
input: "1769188773.687500",
want: time.Unix(1769188773, 687500000),
ok: true,
},
{
name: "zero microseconds",
input: "1769188773.000000",
want: time.Unix(1769188773, 0),
ok: true,
},
{
name: "epoch",
input: "0.000000",
want: time.Unix(0, 0),
ok: true,
},
{
name: "no fractional part",
input: "1769188773",
want: time.Time{},
ok: false,
},
{
name: "non-numeric seconds",
input: "abc.000000",
want: time.Time{},
ok: false,
},
{
name: "non-numeric microseconds",
input: "1769188773.abc",
want: time.Time{},
ok: false,
},
{
name: "empty",
input: "",
want: time.Time{},
ok: false,
},
}
for _, tt := range tests {
t.Run(tt.name, func(t *testing.T) {
got, ok := parseUnixTimestamp([]byte(tt.input))
assert.Equal(t, tt.ok, ok)
assert.True(t, tt.want.Equal(got), "want %v, got %v", tt.want, got)
})
}
}
func TestEntry(t *testing.T) {
tests := []struct {
name string
input string
timestamp time.Time
message string
}{
{
name: "valid entry",
input: "1769188773.687500 uncloudd[332455]: INFO Starting daemon.",
timestamp: time.Unix(1769188773, 687500000),
message: "uncloudd[332455]: INFO Starting daemon.\n",
},
{
name: "unparseable timestamp keeps full line as message",
input: "-- Boot 1234567890 --",
timestamp: time.Time{},
message: "-- Boot 1234567890 --\n",
},
{
name: "line without space keeps full line as message",
input: "nospacehere",
timestamp: time.Time{},
message: "nospacehere\n",
},
{
name: "empty line",
input: "",
timestamp: time.Time{},
message: "\n",
},
}
for _, tt := range tests {
t.Run(tt.name, func(t *testing.T) {
got := entry([]byte(tt.input))
assert.True(t, tt.timestamp.Equal(got.Timestamp), "timestamp: want %v, got %v", tt.timestamp, got.Timestamp)
assert.Equal(t, tt.message, string(got.Message))
assert.Equal(t, api.LogStreamStdout, got.Stream)
})
}
}
func TestLogs(t *testing.T) {
commandContext = func(ctx context.Context, _ string, _ ...string) *exec.Cmd {
return exec.CommandContext(ctx, "/usr/bin/tail", "testdata/logs")
+6 -6
View File
@@ -1,6 +1,6 @@
2026-01-23T17:19:33.686964+01:00 fedora kernel: apple-dcp 271c00000.dcp: DCP index:1 dptx target phy: 5 dptx die: 0
2026-01-23T17:19:33.687155+01:00 fedora kernel: platform 271c00000.dcp:piodma: Adding to iommu group 9
2026-01-23T17:19:33.687343+01:00 fedora kernel: apple-dcp 271c00000.dcp: RTKit: Initializing (protocol version 12)
2026-01-23T17:19:33.687500+01:00 fedora kernel: apple-dcp 271c00000.dcp: shmem_setup: iova: 880255000 -> pa: be4f29000 -> iomem: ffff800082>
2026-01-23T17:19:33.687657+01:00 fedora kernel: apple-dcp 271c00000.dcp: shmem_setup: iova: ffffec000, buffer: ffff8000817cc000
2026-01-23T17:19:33.687826+01:00 fedora kernel: apple-dcp 271c00000.dcp: shmem_setup: iova: ffffe8000, buffer: ffff8000817d4000
1769188773.686964 fedora kernel: apple-dcp 271c00000.dcp: DCP index:1 dptx target phy: 5 dptx die: 0
1769188773.687155 fedora kernel: platform 271c00000.dcp:piodma: Adding to iommu group 9
1769188773.687343 fedora kernel: apple-dcp 271c00000.dcp: RTKit: Initializing (protocol version 12)
1769188773.687500 fedora kernel: apple-dcp 271c00000.dcp: shmem_setup: iova: 880255000 -> pa: be4f29000 -> iomem: ffff800082>
1769188773.687657 fedora kernel: apple-dcp 271c00000.dcp: shmem_setup: iova: ffffec000, buffer: ffff8000817cc000
1769188773.687826 fedora kernel: apple-dcp 271c00000.dcp: shmem_setup: iova: ffffe8000, buffer: ffff8000817d4000