[ws-manager-mk2] redact log #18906

iQQBot · 2023-10-10T18:16:00Z

Description

This PR introduces a new function DeepCopyStruct in scrubber, it can copy a struct and do scrub.

Summary generated by Copilot

`🤖 Generated by Copilot at dbc828e`

This pull request enhances the logging and scrubbing features of the ws-manager-mk2 component. It adds a new feature to the scrubber package to deep copy and scrub struct values, and uses it to log values securely with the logrusr package. It also refactors the logging logic in the workspace controller and removes some unused code.

Related Issue(s)

Fixes ENG-872

How to test

Documentation

Preview status

Gitpod was successfully deployed to your preview environment.

🏷️ Name - pd-ws-man-5c0d6febc1
🔗 URL - pd-ws-man-5c0d6febc1.preview.gitpod-dev.com/workspaces.
📚 Documentation - See our internal documentation for information on how to interact with your preview environment.
📦 Version - pd-ws-man-2-redact-log-gha.18376
🗒️ Logs - GCP Logs Explorer

Build Options

Build

/werft with-werft
Run the build with werft instead of GHA
leeway-no-cache
/werft no-test
Run Leeway with --dont-test

Publish

/werft publish-to-npm
/werft publish-to-jb-marketplace

Installer

analytics=segment
with-dedicated-emulation
workspace-feature-flags
Add desired feature flags to the end of the line above, space separated

Preview Environment / Integration Tests

/werft with-local-preview
If enabled this will build install/preview
/werft with-preview
/werft with-large-vm
/werft with-gce-vm
If enabled this will create the environment on GCE infra
with-integration-tests=all
Valid options are all, workspace, webapp, ide, jetbrains, vscode, ssh. If enabled, with-preview and with-large-vm will be enabled.
with-monitoring

/hold

WVerlaek · 2023-10-12T15:50:04Z

Thanks - do you have examples of how e.g. the workspace status/pod status fields show now in the logs? Which fields are included and which are redacted?

iQQBot · 2023-10-12T15:50:54Z

Thanks - do you have examples of how e.g. the workspace status/pod status fields show now in the logs? Which fields are included and which are redacted?

the pod status behavior same as before, if you need an example, I need to wait for the preview environment.

iQQBot · 2023-10-12T16:25:05Z

@WVerlaek see example below

Logs example

{
  "Workspace": {
    "name": "3a6affd2-e7bd-4a78-861c-5d85d90a9b06",
    "namespace": "default"
  },
  "controller": "workspace",
  "controllerGroup": "workspace.gitpod.io",
  "controllerKind": "Workspace",
  "level": "info",
  "message": "updating workspace status",
  "name": "3a6affd2-e7bd-4a78-861c-5d85d90a9b06",
  "namespace": "default",
  "podStatus": {
    "phase": "Pending",
    "conditions": [
      {
        "type": "Initialized",
        "status": "True",
        "lastProbeTime": null,
        "lastTransitionTime": "2023-10-12T16:21:37Z"
      },
      {
        "type": "Ready",
        "status": "False",
        "lastProbeTime": null,
        "lastTransitionTime": "2023-10-12T16:21:37Z",
        "reason": "ContainersNotReady",
        "message": "containers with unready status: [workspace]"
      },
      {
        "type": "ContainersReady",
        "status": "False",
        "lastProbeTime": null,
        "lastTransitionTime": "2023-10-12T16:21:37Z",
        "reason": "ContainersNotReady",
        "message": "containers with unready status: [workspace]"
      },
      {
        "type": "PodScheduled",
        "status": "True",
        "lastProbeTime": null,
        "lastTransitionTime": "2023-10-12T16:21:37Z"
      }
    ],
    "hostIP": "10.128.0.80",
    "startTime": "2023-10-12T16:21:37Z",
    "containerStatuses": [
      {
        "name": "workspace",
        "state": {
          "waiting": {
            "reason": "ContainerCreating"
          }
        },
        "lastState": {},
        "ready": false,
        "restartCount": 0,
        "image": "reg.pd-ws-man-5c0d6febc1.preview.gitpod-dev.com:31750/remote/3a6affd2-e7bd-4a78-861c-5d85d90a9b06",
        "imageID": "",
        "started": false
      }
    ],
    "qosClass": "Burstable"
  },
  "reconcileID": "db55667b-b3bb-4c44-a9d6-bea57007ce26",
  "serviceContext": {
    "service": "ws-manager-mk2",
    "version": "commit-32450c07bf23c12a5a999aab6f2aa40527ce8552"
  },
  "severity": "INFO",
  "status": {
    "podStarts": 1,
    "url": "https://iqqbot-gofuse-05xczdztvll.ws-dev.pd-ws-man-5c0d6febc1.preview.gitpod-dev.com",
    "ownerToken": "[redacted]",
    "phase": "Creating",
    "conditions": [
      {
        "type": "Deployed",
        "status": "True",
        "lastTransitionTime": "2023-10-12T16:21:37Z",
        "reason": "Unknown",
        "message": ""
      },
      {
        "type": "Refresh",
        "status": "True",
        "lastTransitionTime": "2023-10-12T16:21:37Z",
        "reason": "Unknown",
        "message": ""
      },
      {
        "type": "ContentReady",
        "status": "True",
        "lastTransitionTime": "2023-10-12T16:21:49Z",
        "reason": "InitializationSuccess",
        "message": ""
      }
    ],
    "runtime": {
      "nodeName": "preview-pd-ws-man-5c0d6febc1",
      "podName": "ws-3a6affd2-e7bd-4a78-861c-5d85d90a9b06",
      "hostIP": "10.128.0.80"
    }
  },
  "time": "2023-10-12T16:21:49.19141569Z"
}

{
  "Workspace": {
    "name": "3a6affd2-e7bd-4a78-861c-5d85d90a9b06",
    "namespace": "default"
  },
  "controller": "workspace",
  "controllerGroup": "workspace.gitpod.io",
  "controllerKind": "Workspace",
  "level": "info",
  "message": "updating workspace status",
  "name": "3a6affd2-e7bd-4a78-861c-5d85d90a9b06",
  "namespace": "default",
  "podStatus": {
    "phase": "Running",
    "conditions": [
      {
        "type": "Initialized",
        "status": "True",
        "lastProbeTime": null,
        "lastTransitionTime": "2023-10-12T16:21:37Z"
      },
      {
        "type": "Ready",
        "status": "True",
        "lastProbeTime": null,
        "lastTransitionTime": "2023-10-12T16:23:07Z"
      },
      {
        "type": "ContainersReady",
        "status": "True",
        "lastProbeTime": null,
        "lastTransitionTime": "2023-10-12T16:23:07Z"
      },
      {
        "type": "PodScheduled",
        "status": "True",
        "lastProbeTime": null,
        "lastTransitionTime": "2023-10-12T16:21:37Z"
      }
    ],
    "hostIP": "10.128.0.80",
    "podIP": "192.168.2.44",
    "podIPs": [
      {
        "ip": "192.168.2.44"
      }
    ],
    "startTime": "2023-10-12T16:21:37Z",
    "containerStatuses": [
      {
        "name": "workspace",
        "state": {
          "running": {
            "startedAt": "2023-10-12T16:23:02Z"
          }
        },
        "lastState": {},
        "ready": true,
        "restartCount": 0,
        "image": "reg.pd-ws-man-5c0d6febc1.preview.gitpod-dev.com:31750/remote/3a6affd2-e7bd-4a78-861c-5d85d90a9b06:latest",
        "imageID": "reg.pd-ws-man-5c0d6febc1.preview.gitpod-dev.com:[redacted:email]:82966070187b644e4a214db1c0c6cdf4a7d23091d57995215775b1c7118dfdfe",
        "containerID": "containerd://c1826ee417cf681629a679e4b3304112fb724c4eddeee1e9cfd7b07a2bb87a6d",
        "started": true
      }
    ],
    "qosClass": "Burstable"
  },
  "reconcileID": "491e10c0-c1c2-4122-af72-ae974bbbce87",
  "serviceContext": {
    "service": "ws-manager-mk2",
    "version": "commit-32450c07bf23c12a5a999aab6f2aa40527ce8552"
  },
  "severity": "INFO",
  "status": {
    "podStarts": 1,
    "url": "https://iqqbot-gofuse-05xczdztvll.ws-dev.pd-ws-man-5c0d6febc1.preview.gitpod-dev.com",
    "ownerToken": "[redacted]",
    "phase": "Running",
    "conditions": [
      {
        "type": "Deployed",
        "status": "True",
        "lastTransitionTime": "2023-10-12T16:21:37Z",
        "reason": "Unknown",
        "message": ""
      },
      {
        "type": "Refresh",
        "status": "True",
        "lastTransitionTime": "2023-10-12T16:21:37Z",
        "reason": "Unknown",
        "message": ""
      },
      {
        "type": "ContentReady",
        "status": "True",
        "lastTransitionTime": "2023-10-12T16:21:49Z",
        "reason": "InitializationSuccess",
        "message": ""
      },
      {
        "type": "EverReady",
        "status": "True",
        "lastTransitionTime": "2023-10-12T16:23:07Z",
        "reason": "Unknown",
        "message": ""
      },
      {
        "type": "FirstUserActivity",
        "status": "True",
        "lastTransitionTime": "2023-10-12T16:23:07Z",
        "reason": "MarkActiveRequest",
        "message": ""
      }
    ],
    "runtime": {
      "nodeName": "preview-pd-ws-man-5c0d6febc1",
      "podName": "ws-3a6affd2-e7bd-4a78-861c-5d85d90a9b06",
      "podIP": "192.168.2.44",
      "hostIP": "10.128.0.80"
    },
    "lastActivity": "2023-10-12T16:23:07Z"
  },
  "time": "2023-10-12T16:23:07.922931558Z"
}

iQQBot · 2023-10-12T16:27:52Z

"url": "https://iqqbot-gofuse-05xczdztvll.ws-dev.pd-ws-man-5c0d6febc1.preview.gitpod-dev.com",

actually, this url contains workspace id, but the scriber don't have rule to redact it

easyCZ · 2023-10-13T07:24:57Z

components/ws-manager-mk2/main.go

+	l := log.WithFields(logrus.Fields{})
+	l.Logger.SetReportCaller(false)
+	baseLogger := logrusr.New(l, logrusr.WithFormatter(func(i interface{}) interface{} {
+		return &scrubber.TrustedValueWrap{Value: scrubber.Default.DeepCopyStruct(i)}


What is the perf implication of doing a deep copy? If I remember correctly, @akosyakov was running into perf issues when we performed deep scrubbing and the call we made is we'd only scrub a fixed depth and redact anything below.

On complex and deep structures it was considerably slow, but in golang is still was negligible.
Our concern though was that we introduce it generically and don't want to make some hot path even slower by mistake, so decided to go with enforcing rather flat primitive properties. If this code is not on such path I would think it should be alright.

For log, it's fine

I mean the point is that delivery of updates now will be slowed down by deep scrubbing of workspace status, you need to decide how acceptable it is.

https://github.com/gitpod-io/gitpod/pull/18906/files#diff-f99e73fcd35fa75f1bb44136fccd8d70d328d02372d9b4e7d7884f3f7c9abd61R128-R134

The workspace status used to be deep copied and then logged, so it has a relatively small impact on it.

Printing logs is not a hot path, and printing logs itself is also slow. Whether it's printing to stdout or to a file, it consumes I/O.

components/scrubber/scrubber.go

akosyakov · 2023-10-13T07:46:58Z

actually, this url contains workspace id, but the scriber don't have rule to redact it

@iQQBot I'm not sure it is good idea to scrub each URL string, since regex is very expensive. If you know the structure maybe just scrub this property specifically on the top?

akosyakov

approve to unblock, fine with scrubber changes

WVerlaek · 2023-10-16T09:15:56Z

@iQQBot changes lgtm but still see the URL unscrubbed, do you want to do that in a follow-up pr?

iQQBot · 2023-10-16T09:24:42Z

changes lgtm but still see the URL unscrubbed, do you want to do that in a follow-up pr?

It seems that we can only enable regex for each field called url to clear the workspace id (maybe it's make sense), other than that we may need to make big changes to scrubber

akosyakov · 2023-10-16T09:28:05Z

Could you clarify which URLs? Also do you really want to log the entire workspace status? e.g. are you interested in ports?

if you are interested only let's say in phase and conditions log only them? You don't need even deep scrubbing then?

It could be good idea rather start small and add more info as you find it useful. In the past we over logged because of using deep structures.

iQQBot · 2023-10-16T09:32:14Z

Could you clarify which URLs?

Also do you really want to log the entire workspace status? e.g. are you interested in ports? if you are interested only let's say in phase and conditions log only them? You don't need even deep scrubbing then?

Personally, the pod status update would be debug level, but the cc @WVerlaek

akosyakov · 2023-10-16T09:35:17Z

for status.url my understanding was

do deep scrubbing get a new structure
now get a value from status.url and replace with [redacted] or use string ?

Alternatively we add workspaceId in

gitpod/components/scrubber/config.go

Line 33 in 20a6d13

RedactedValues = map[string]*regexp.Regexp{

? But it can make logging with strings slower. Redacting url actually sounds better. It should not have perf impact.

WVerlaek · 2023-10-16T10:00:48Z

Also do you really want to log the entire workspace status? e.g. are you interested in ports?

if possible yes - it's been useful to debug workspace issues by having the full status. Lets you reconstruct a timeline of the workspace and its status changes

WVerlaek · 2023-10-16T10:02:26Z

Is it possible to add a scrubbed tag on the status.URL field?

iQQBot · 2023-10-16T10:04:05Z

Is it possible to add a scrubbed tag on the status.URL field?

only if it's our control struct

iQQBot · 2023-10-16T10:07:19Z

Is it possible to add a scrubbed tag on the status.URL field?

I checked, we can do this

iQQBot · 2023-10-16T10:18:58Z

updated

WVerlaek

lgtm

roboquat added do-not-merge/hold do-not-merge/work-in-progress size/M labels Oct 10, 2023

iQQBot force-pushed the pd/ws-man-2-redact-log branch from 74894c7 to 6666333 Compare October 10, 2023 20:15

roboquat added size/L and removed size/M labels Oct 10, 2023

iQQBot force-pushed the pd/ws-man-2-redact-log branch 3 times, most recently from 9812d55 to a64322f Compare October 11, 2023 09:36

iQQBot changed the title ~~[test] ws-manager-mk2 redact log~~ [ws-manager-mk2] redact log Oct 12, 2023

roboquat added size/XL and removed size/L labels Oct 12, 2023

iQQBot force-pushed the pd/ws-man-2-redact-log branch from f4b3b79 to 32450c0 Compare October 12, 2023 15:36

iQQBot marked this pull request as ready for review October 12, 2023 15:37

iQQBot requested a review from a team as a code owner October 12, 2023 15:37

roboquat removed the do-not-merge/work-in-progress label Oct 12, 2023

github-actions bot added the team: team-engine label Oct 12, 2023

easyCZ reviewed Oct 13, 2023

View reviewed changes

akosyakov reviewed Oct 13, 2023

View reviewed changes

components/scrubber/scrubber.go Show resolved Hide resolved

akosyakov reviewed Oct 13, 2023

View reviewed changes

components/scrubber/scrubber.go Outdated Show resolved Hide resolved

iQQBot force-pushed the pd/ws-man-2-redact-log branch from 32450c0 to 68e87af Compare October 13, 2023 08:33

iQQBot requested a review from a team as a code owner October 13, 2023 08:33

github-actions bot added the team: staff-engineers label Oct 13, 2023

akosyakov approved these changes Oct 13, 2023

View reviewed changes

iQQBot removed the do-not-merge/hold label Oct 13, 2023

iQQBot and others added 4 commits October 16, 2023 10:18

update to logrusr v4

e81c498

Add DeepCopyStruct to scrubber

1bbe3dc

use DeepCopyStruct to scrub log

f01a33c

mark wrokspace.stauts.url redact

c5c7c5c

iQQBot force-pushed the pd/ws-man-2-redact-log branch from 68e87af to c5c7c5c Compare October 16, 2023 10:18

WVerlaek approved these changes Oct 16, 2023

View reviewed changes

roboquat merged commit 81ff3d1 into main Oct 16, 2023

roboquat deleted the pd/ws-man-2-redact-log branch October 16, 2023 10:48

[ws-manager-mk2] redact log #18906

[ws-manager-mk2] redact log #18906

Uh oh!

Conversation

iQQBot commented Oct 10, 2023 • edited by ghost Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Description

🤖 Generated by Copilot at dbc828e

Related Issue(s)

How to test

Documentation

Preview status

Build Options

Uh oh!

WVerlaek commented Oct 12, 2023

Uh oh!

iQQBot commented Oct 12, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

iQQBot commented Oct 12, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

iQQBot commented Oct 12, 2023

Uh oh!

easyCZ Oct 13, 2023

Choose a reason for hiding this comment

Uh oh!

akosyakov Oct 13, 2023

Choose a reason for hiding this comment

Uh oh!

iQQBot Oct 13, 2023

Choose a reason for hiding this comment

Uh oh!

akosyakov Oct 13, 2023

Choose a reason for hiding this comment

Uh oh!

iQQBot Oct 13, 2023

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

akosyakov commented Oct 13, 2023

Uh oh!

akosyakov left a comment

Choose a reason for hiding this comment

Uh oh!

WVerlaek commented Oct 16, 2023

Uh oh!

iQQBot commented Oct 16, 2023

Uh oh!

akosyakov commented Oct 16, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

iQQBot commented Oct 16, 2023

Uh oh!

akosyakov commented Oct 16, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

WVerlaek commented Oct 16, 2023

Uh oh!

WVerlaek commented Oct 16, 2023

Uh oh!

iQQBot commented Oct 16, 2023

Uh oh!

iQQBot commented Oct 16, 2023

Uh oh!

iQQBot commented Oct 16, 2023

Uh oh!

WVerlaek left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

iQQBot commented Oct 10, 2023 •

edited by ghost

Loading

`🤖 Generated by Copilot at dbc828e`

iQQBot commented Oct 12, 2023 •

edited

Loading

iQQBot commented Oct 12, 2023 •

edited

Loading

akosyakov commented Oct 16, 2023 •

edited

Loading

akosyakov commented Oct 16, 2023 •

edited

Loading