Skip to content

logging: client side - #283

Merged
psviderski merged 11 commits into
psviderski:mainfrom
miekg:miek/26/mrt23ma/client-logging
Apr 21, 2026
Merged

logging: client side#283
psviderski merged 11 commits into
psviderski:mainfrom
miekg:miek/26/mrt23ma/client-logging

Conversation

@miekg

@miekg miekg commented Mar 23, 2026

Copy link
Copy Markdown
Contributor

Create internal/logs and put abstracted way service and machine logging in there This adds the bits to do machine logging of the services.

See #273 and discussion in #158

@miekg

miekg commented Mar 23, 2026 •
edited
Loading

Copy link
Copy Markdown
Contributor Author

this depends on #282, because it's calling the wrong endpoint (and that hasn't hooked yet). Can should be easy rebase.

One question though: how can I get the machine ID as I'm not getting any services back, i.e. the s.MachineLogs will only return a channel and error...?

	for _, unit := range units {
		// This is wrong because we're calling the wrong endpoints. Must be c.MachineLogs.
		svc, ch, err := c.ServiceLogs(ctx, unit, logsOpts)
		if err != nil {
			return fmt.Errorf("stream logs for systemd service '%s': %w", unit, err)
		}
		unitStreams = append(unitStreams, ch)

		machineIDs := svc.MachineIDs()
		machineIDsSet.Append(machineIDs...)
	}

not relevant anymore

@miekg miekg mentioned this pull request Apr 8, 2026
Merged
miekg added 2 commits April 8, 2026 14:45
@miekg
logging: client side
8421045 
Create internal/logs and put abstracted way service and machine logging in there
This adds the bits to do machine logging of the services.

See psviderski#273 and discussion in psviderski#158

Signed-off-by: Miek Gieben <[email protected]>
@miekg
go mod tidy
87b81d9 
Signed-off-by: Miek Gieben <[email protected]>
@miekg
miekg force-pushed the miek/26/mrt23ma/client-logging branch from 72c6f63 to 87b81d9 Compare April 8, 2026 12:45
miekg added 4 commits April 8, 2026 14:53
@miekg
fix typo
c1bc76f 
Signed-off-by: Miek Gieben <[email protected]>
@miekg
Hook it up further
7657bbb 
Signed-off-by: Miek Gieben <[email protected]>
@miekg
Check unit validity server side
1bc7118 
Signed-off-by: Miek Gieben <[email protected]>
@miekg
Make cli-docs
c52e0f3 
Signed-off-by: Miek Gieben <[email protected]>
@miekg

miekg commented Apr 9, 2026

Copy link
Copy Markdown
Contributor Author

ok, this is starting work, but casting stuff to ServiceLogEntry makes it slightly weird. Now cleaning up and cutting down the amount of change

@miekg

miekg commented Apr 9, 2026

Copy link
Copy Markdown
Contributor Author 
% ./uc machine logs uncloud-corrosion
...
pr  9 10:50:26.948 machine-ieny                  [unclo] uncloud-corrosion[25470]: 2026-04-09T08:50:26.948545Z  INFO corro_agent::api::public::pubsub: forwarding subscription events to a sender sub_id=4418038e-6056-4dbf-a800-4942e7d93cef
Apr  9 10:50:26.948 machine-ieny                  [unclo] uncloud-corrosion[25470]: 2026-04-09T08:50:26.948718Z  INFO corro_agent::api::public::pubsub: minimum expected change id: ChangeId(11) sub_id=46d82639-3d7e-4576-9f8e-eaa625014a0a
Apr  9 10:50:26.948 machine-ieny                  [unclo] uncloud-corrosion[25470]: 2026-04-09T08:50:26.948725Z  INFO corro_agent::api::public::pubsub: last change id sent by subscription: ChangeId(10) sub_id=46d82639-3d7e-4576-9f8e-eaa625014a0a
Apr  9 10:50:26.948 machine-ieny                  [unclo] uncloud-corrosion[25470]: 2026-04-09T08:50:26.948728Z  INFO corro_agent::api::public::pubsub: subscription is caught up, no gaps in change id. last change id: ChangeId(10), last_sub_change_id: None sub_id=46d82639-3d7e-4576-9f8e-eaa625014a0a
Apr  9 10:50:26.948 machine-ieny                  [unclo] uncloud-corrosion[25470]: 2026-04-09T08:50:26.948733Z  INFO corro_agent::api::public::pubsub: forwarding subscription events to a sender sub_id=46d82639-3d7e-4576-9f8e-eaa625014a0a

server side:

DEBUG Starting systemd service logs streaming. unit=uncloud-corrosion stream_id=ad3e95300d0 follow=false tail=100 since="" until=""

miekg added 2 commits April 9, 2026 10:51
@miekg
Add newline to logs
79a611c 
Signed-off-by: Miek Gieben <[email protected]>
@miekg
docs
9c2e5dd 
Signed-off-by: Miek Gieben <[email protected]>
@miekg

miekg commented Apr 9, 2026

Copy link
Copy Markdown
Contributor Author

geh, seems to work fine. Only PrintEntry is a bit weird, because we don't file service, maybe that should be the unit and containerid should be empty (or some such)

miekg added 2 commits April 9, 2026 11:02
@miekg
Polish a bit
79280e0 
Signed-off-by: Miek Gieben <[email protected]>
@miekg
comment fix
33857df 
Signed-off-by: Miek Gieben <[email protected]>
miekg
miekg commented Apr 9, 2026
View reviewed changes
Comment thread pkg/client/logs.go
}

// Enrich log entries from the machine with metadata.
metadata := api.ServiceLogEntryMetadata{

@miekg miekg Apr 9, 2026

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm in favor of keeping this, and putting unit as ServiceName or some such.

@miekg

miekg commented Apr 9, 2026

Copy link
Copy Markdown
Contributor Author

@psviderski this works, and code looks reasonable to me. PTAL

@miekg
There is no groupid
dac5fc3 
Signed-off-by: Miek Gieben <[email protected]>
@miekg miekg mentioned this pull request Apr 20, 2026
Closed
psviderski
psviderski approved these changes Apr 21, 2026
View reviewed changes

@psviderski psviderski left a comment

Copy link
Copy Markdown
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks good, thank you! 👍

@psviderski
psviderski merged commit f44ada0 into psviderski:main Apr 21, 2026
4 checks passed
@psviderski

psviderski commented Apr 21, 2026 •
edited
Loading

Copy link
Copy Markdown
Owner

@miekg FYI uc machine logs uncloud -f hangs in my tests and prints a warning about stalled streams. Also zombie journalctl processes start to appear on the remote machine(s):

ps ax | grep journal
    242 ?        Ss    21:59 /lib/systemd/systemd-journald
 286152 ?        Z      0:00 [journalctl] <defunct>
 286153 ?        Z      0:00 [journalctl] <defunct>
 286180 ?        Z      0:00 [journalctl] <defunct>
 286181 ?        Z      0:00 [journalctl] <defunct>
 286197 ?        Z      0:00 [journalctl] <defunct>
 286218 ?        Z      0:00 [journalctl] <defunct>
 286219 ?        Z      0:00 [journalctl] <defunct>
 286230 ?        Z      0:00 [journalctl] <defunct>
 286238 ?        Z      0:00 [journalctl] <defunct>
 286248 ?        Z      0:00 [journalctl] <defunct>
 286479 ?        Z      0:00 [journalctl] <defunct>
 286487 ?        Z      0:00 [journalctl] <defunct>
 286488 ?        Z      0:00 [journalctl] <defunct>
 286496 ?        Z      0:00 [journalctl] <defunct>
 286497 ?        Z      0:00 [journalctl] <defunct>
 286499 ?        Z      0:00 [journalctl] <defunct>

Note that -f -n N where N is any number < 100 works but hangs >=100. This could be related to this constant:

uncloud/pkg/client/logmerger.go

Line 15 in cef0472

logMergerMaxInFlightPerStream = 100

But I haven't seen this behaviour for service logs. So I suspect we're not correctly handling timestamps and heartbeats when streaming journal logs.
Zombie processes might be an unrelated issue.

@miekg

miekg commented Apr 21, 2026 via email

Copy link
Copy Markdown
Contributor Author

@miekg
miekg deleted the miek/26/mrt23ma/client-logging branch April 21, 2026 14:41
@miekg

miekg commented Apr 21, 2026

Copy link
Copy Markdown
Contributor Author

lol, ucind clusters use Alpine as the base image, that lacks journalctl as there is no systemd on those

@psviderski

psviderski commented Apr 21, 2026

Copy link
Copy Markdown
Owner

Yeah, ucind is not suitable for this. I'm testing on my hybrid dev cluster (2 local VMs + 1 free Oracle Cloud VM).
Building the local code and upgrading daemons on the remote machines with:

mise run dev:install user@host1 user@host2/arm64

https://github.com/psviderski/uncloud/blob/main/HACKING.md#manual-testing-on-dev-machines

@miekg miekg mentioned this pull request Apr 22, 2026
Closed
@miekg

miekg commented Apr 22, 2026

Copy link
Copy Markdown
Contributor Author

I can't replicate a hang, it just works and with #325 is also cleans up the journalctl process :)

@psviderski

psviderski commented Apr 22, 2026

Copy link
Copy Markdown
Owner

I can't replicate a hang

Does the systemd service logs you're testing contain more than 100 lines already? Can you try uncloud-corrosion which writes a lot of logs.

@miekg

miekg commented Apr 22, 2026

Copy link
Copy Markdown
Contributor Author

copied uncloudd (compiles from my branch) to the machines started. My corrosion doesn't log very actively - not this is also a newer corrosion..

But: uc machine logs uncloud -f -n 140 stream like crazy:


Apr 22 10:59:52.310 machine-781l uncloud uncloudd[21638]: DEBUG Sent log stream heartbeat. unit=uncloud stream_id=7d100038f10 timestamp=2026-04-22T08:59:52.110Z
Apr 22 10:59:52.510 machine-781l uncloud uncloudd[21638]: DEBUG Sent log stream heartbeat. unit=uncloud stream_id=7d100038f10 timestamp=2026-04-22T08:59:52.310Z
Apr 22 10:59:52.315 machine-9q7y uncloud uncloudd[17441]: DEBUG Sent log stream heartbeat. unit=uncloud stream_id=334852a28820 timestamp=2026-04-22T08:59:52.115Z
Apr 22 10:59:52.516 machine-9q7y uncloud uncloudd[17441]: DEBUG Sent log stream heartbeat. unit=uncloud stream_id=334852a28820 timestamp=2026-04-22T08:59:52.315Z
Apr 22 10:59:52.712 machine-781l uncloud uncloudd[21638]: DEBUG Sent log stream heartbeat. unit=uncloud stream_id=7d100038f10 timestamp=2026-04-22T08:59:52.510Z

@psviderski

psviderski commented Apr 23, 2026

Copy link
Copy Markdown
Owner

Ah, found the root cause of my issue with hanging. systemd <v255 prints an ISO datetime (short-iso-precise) that is an invalid RFC3339:

misses : in the timezone offset: systemd/systemd#29134

My Debian 12 machine (systemd v252) returns the datetime without the colon which fails to parse so the server returns time.Time{}. Then the log merger is confused when subsequent log entries don't have the datetime that is > lastSeen so it never advances.

Will implement a few fixes:

  • change the time format to short-unix which should be stable across all systemd versions
  • try to relax the logs merger a bit to still emit logs even when the time is malformed

@psviderski

psviderski commented Apr 23, 2026 •
edited
Loading

Copy link
Copy Markdown
Owner

Fixes:

  • change the journalctl time format to short-unix: 50057c4
  • print logs with zero timestamps immediately to prevent indefinite stalling: 9ce624f

@miekg

miekg commented Apr 23, 2026

Copy link
Copy Markdown
Contributor Author

wow, nice find! And glad it's fixed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@psviderski psviderski psviderski approved these changes

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

2 participants

@miekg @psviderski