Better debug logging for host user creation #46789

eriktate · 2024-09-19T21:35:01Z

Host user creation doesn't produce many useful logs, even in debug mode. This PR adds some new logs and updates some existing ones to help make more sense of what's happening at runtime.

rosstimothy

I don't mean to pile more work on you here, but we've been undergoing a slow migration from logrus to log/slog. Could I trouble you to use slog instead of logrus for any new loggers being constructed or added as members to a struct?

eriktate · 2024-09-19T21:52:36Z

I don't mean to pile more work on you here, but we've been undergoing a slow migration from logrus to log/slog. Could I trouble you to use slog instead of logrus for any new loggers being constructed or added as members to a struct?

Yeah definitely! I should've asked, I noticed there were a few loggers in play and wondered if there was a reason for that haha. I'll get all of these updated 👍

lib/srv/sess.go

lib/srv/usermgmt.go

lib/srv/sess.go

lib/srv/usermgmt.go

marcoandredinis · 2024-09-30T09:26:25Z

lib/srv/sess.go

@@ -289,15 +294,19 @@ func (s *SessionRegistry) WriteSudoersFile(identityContext IdentityContext) (io.
 // If the returned closer is not nil, it must be called at the end of the session to
 // clean up the local user.
 func (s *SessionRegistry) UpsertHostUser(identityContext IdentityContext) (bool, io.Closer, error) {
+	ctx := context.TODO()


We have s.Srv.Context(), can we use it instead?

marcoandredinis · 2024-09-30T09:30:09Z

lib/srv/sess_test.go

@@ -259,6 +260,7 @@ func TestSession_newRecorder(t *testing.T) {
 				id:  "test",
 				log: logger,
 				registry: &SessionRegistry{
+					logger: slog.Default(),


We have github.com/gravitational/teleport/lib/utils.NewSlogLoggerForTests() which is usually used for this type of initializations.
It does a little more that just calling slog.Default()

marcoandredinis · 2024-09-30T09:30:57Z

lib/srv/usermgmt.go

@@ -68,10 +70,10 @@ func NewHostSudoers(uuid string) HostSudoers {
 	backend, err := newHostSudoersBackend(uuid)
 	switch {
 	case trace.IsNotImplemented(err):
-		log.Debugf("Skipping host sudoers management: %v", err)
+		slog.DebugContext(context.Background(), "Skipping host sudoers management", "err", err)


Suggested change

slog.DebugContext(context.Background(), "Skipping host sudoers management", "err", err)

slog.DebugContext(context.Background(), "Skipping host sudoers management", "error", err)

marcoandredinis · 2024-09-30T09:31:06Z

lib/srv/usermgmt.go

 		return nil
 	case err != nil: //nolint:staticcheck // linter fails on non-linux system as only linux implementation returns useful values.
-		log.Warnf("Error making new HostSudoersBackend: %s", err)
+		slog.DebugContext(context.Background(), "Error making new HostSudoersBackend", "err", err)


Suggested change

slog.DebugContext(context.Background(), "Error making new HostSudoersBackend", "err", err)

slog.DebugContext(context.Background(), "Error making new HostSudoersBackend", "error", err)

marcoandredinis · 2024-09-30T09:31:41Z

lib/srv/usermgmt.go

@@ -232,6 +236,15 @@ func (u *HostSudoersManagement) RemoveSudoers(name string) error {
 var unmanagedUserErr = errors.New("user not managed by teleport")

 func (u *HostUserManagement) updateUser(name string, ui services.HostUsersInfo) (io.Closer, error) {
+	ctx := context.TODO()


Can we use u.ctx ?

marcoandredinis · 2024-09-30T09:48:53Z

lib/srv/usermgmt.go

+				final = append(final, group)
+			}
+
+			log.DebugContext(ctx, "Setting user groups", "before", current, "after", final)


💅 If we sort them, it would make human comparison easier

Great call 👍

marcoandredinis · 2024-09-30T09:53:12Z

lib/srv/usermgmt.go

+		"uid", ui.UID,
+	)
+
+	log.DebugContext(context.Background(), "Attempting to create host user", "gid", ui.GID)


Can we use s.ctx instead of context.Backgroun()?

marcoandredinis · 2024-09-30T09:55:54Z

lib/srv/usermgmt.go

+			if _, err := os.Stat(userOpts.Home); os.IsNotExist(err) {
+				log.InfoContext(context.Background(), "Creating home directory", "home", userOpts.Home, "gid", userOpts.GID)
+				if err := u.backend.CreateHomeDirectory(userOpts.Home, user.Uid, user.Gid); err != nil {


We have a race here. The Home might be created between the os.Stat and the CreateHomeDirectory.
Should we just try to create it anyway and then handle the error gracefully?

That's essentially what CreateHomeDirectory does, but it swallows the error context instead of returning it to the caller. I suppose we could surface the error when the directory already exists and handle it here instead 🤔

I dropped the os.Stat in favor of making CreateHomeDirectory return the os.ErrExists so that callers can handle the cases as they see fit 👍

lib/srv/usermgmt.go

marcoandredinis · 2024-09-30T09:59:57Z

lib/srv/usermgmt.go

@@ -533,14 +590,15 @@ func isUnknownGroupError(err error, groupName string) bool {

 // DeleteAllUsers deletes all host users in the teleport service group.
 func (u *HostUserManagement) DeleteAllUsers() error {
+	u.log.DebugContext(context.Background(), "Attempting to delete all temporary host users")


Maybe move this to info?

rosstimothy

Thanks Erik!

lib/srv/usermgmt_test.go

…d updating existing logs to structured logging

public-teleport-github-review-bot · 2024-10-01T20:52:48Z

@eriktate See the table below for backport results.

Branch	Result
branch/v14	Failed
branch/v15	Failed
branch/v16	Failed

github-actions bot requested review from marcoandredinis and timothyb89 September 19, 2024 21:35

github-actions bot added the size/sm label Sep 19, 2024

rosstimothy added the no-changelog Indicates that a PR does not require a changelog entry label Sep 19, 2024

gravitational deleted a comment from github-actions bot Sep 19, 2024

rosstimothy reviewed Sep 19, 2024

View reviewed changes

eriktate force-pushed the eriktate/improved-host-user-logging branch 4 times, most recently from ea53d75 to 23b356c Compare September 20, 2024 18:37

rosstimothy reviewed Sep 20, 2024

View reviewed changes

eriktate force-pushed the eriktate/improved-host-user-logging branch from 23b356c to 5f085da Compare September 20, 2024 18:55

eriktate added backport/branch/v14 backport/branch/v15 backport/branch/v16 labels Sep 20, 2024

rosstimothy reviewed Sep 20, 2024

View reviewed changes

lib/srv/sess.go Outdated Show resolved Hide resolved

eriktate force-pushed the eriktate/improved-host-user-logging branch 3 times, most recently from 1ebe439 to 5204fca Compare September 20, 2024 20:25

rosstimothy reviewed Sep 21, 2024

View reviewed changes

lib/srv/usermgmt.go Outdated Show resolved Hide resolved

eriktate force-pushed the eriktate/improved-host-user-logging branch 2 times, most recently from c29cc2a to 950f236 Compare September 26, 2024 23:13

marcoandredinis reviewed Sep 30, 2024

View reviewed changes

eriktate force-pushed the eriktate/improved-host-user-logging branch 2 times, most recently from 9d7cac3 to cb8b316 Compare October 1, 2024 19:20

rosstimothy approved these changes Oct 1, 2024

View reviewed changes

eriktate force-pushed the eriktate/improved-host-user-logging branch from cb8b316 to 0259e86 Compare October 1, 2024 19:39

marcoandredinis approved these changes Oct 1, 2024

View reviewed changes

lib/srv/usermgmt_test.go Outdated Show resolved Hide resolved

public-teleport-github-review-bot bot removed the request for review from timothyb89 October 1, 2024 19:56

switching host user creation logging to slog, adding more logging, an…

ac1c622

…d updating existing logs to structured logging

eriktate force-pushed the eriktate/improved-host-user-logging branch from 0259e86 to ac1c622 Compare October 1, 2024 20:02

eriktate added this pull request to the merge queue Oct 1, 2024

Merged via the queue into master with commit 685dd44 Oct 1, 2024
39 checks passed

eriktate deleted the eriktate/improved-host-user-logging branch October 1, 2024 20:50

This was referenced Oct 3, 2024

[v16] Better debug logging for host user creation #47137

Merged

[v15] Better debug logging for host user creation #47138

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Better debug logging for host user creation #46789

Better debug logging for host user creation #46789

eriktate commented Sep 19, 2024

rosstimothy left a comment

eriktate commented Sep 19, 2024

marcoandredinis Sep 30, 2024

marcoandredinis Sep 30, 2024

marcoandredinis Sep 30, 2024

marcoandredinis Sep 30, 2024

marcoandredinis Sep 30, 2024

marcoandredinis Sep 30, 2024

eriktate Oct 1, 2024

marcoandredinis Sep 30, 2024

marcoandredinis Sep 30, 2024

eriktate Oct 1, 2024

eriktate Oct 1, 2024

marcoandredinis Sep 30, 2024

rosstimothy left a comment

public-teleport-github-review-bot bot commented Oct 1, 2024

	slog.DebugContext(context.Background(), "Skipping host sudoers management", "err", err)
	slog.DebugContext(context.Background(), "Skipping host sudoers management", "error", err)

Better debug logging for host user creation #46789

Better debug logging for host user creation #46789

Conversation

eriktate commented Sep 19, 2024

rosstimothy left a comment

Choose a reason for hiding this comment

eriktate commented Sep 19, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rosstimothy left a comment

Choose a reason for hiding this comment

public-teleport-github-review-bot bot commented Oct 1, 2024