Skip to content
Snippets Groups Projects

Mask log trace

Merged Kamil Trzciński requested to merge mask-trace into master
All threads resolved!

What does this MR do?

This adds support for masking variables. Rails API needs to annotate each variable to be masked with masked: true flag.

From now one, the trace will be delayed until we are certain that it does not contain masked output.

It uses a Trie type of search for efficient masked output search.

Why was this MR needed?

Are there points in the code the reviewer needs to double check?

Does this MR meet the acceptance criteria?

  • Documentation created/updated
  • Added tests for this feature/bug
  • In case of conflicts with master - branch was rebased

What are the relevant issue numbers?

Edited by Kamil Trzciński

Merge request reports

Loading
Loading

Activity

Filter activity
  • Approvals
  • Assignees & reviewers
  • Comments (from bots)
  • Comments (from users)
  • Commits & branches
  • Edits
  • Labels
  • Lock status
  • Mentions
  • Merge request status
  • Tracking
  • Author Maintainer

    @tmaczukin @matteeyah I have this working. Tested locally, it seems to mask correctly.

    It adds a new feature send by Runner features: { masked: true }.

    It requires each masked variable to be annotated with masked: true, similar how they are annotated today with public: true or file: true.

    Edited by Kamil Trzciński
  • Kamil Trzciński added 5 commits

    added 5 commits

    Compare with previous version

  • added 1 commit

    Compare with previous version

  • Kamil Trzciński resolved all discussions

    resolved all discussions

  • Kamil Trzciński changed milestone to %11.9

    changed milestone to %11.9

  • added Deliverable devopsverify + 1 deleted label

  • Author Maintainer

    @tmaczukin @steveazz I need your help on early review of this MR. I plan to slightly improve the implementation, and add a bunch of tests. Do you have any structural comments of what I should change?

  • Steve Xuereb
  • Steve Xuereb resolved all discussions

    resolved all discussions

  • I need your help on early review of this MR. I plan to slightly improve the implementation, and add a bunch of tests. Do you have any structural comments of what I should change?

    @ayufan The direction that it's going for is good, and I really like it. I don't have any feedback on the code as of yet.

    • Resolved by Kamil Trzciński

      There are few missing changes in the test files (related to changing tracePatch.trace from bytes.Buffer to []byte):

      # gitlab.com/gitlab-org/gitlab-runner/network
      ./gitlab_test.go:706: cannot use trace (type bytes.Buffer) as type []byte in argument to newTracePatch
      ./trace_patch_test.go:14: cannot use *trace (type bytes.Buffer) as type []byte in argument to newTracePatch
      ./trace_patch_test.go:24: cannot use *trace (type bytes.Buffer) as type []byte in argument to newTracePatch
      ./trace_patch_test.go:30: cannot use *trace (type bytes.Buffer) as type []byte in argument to newTracePatch
      ./trace_patch_test.go:39: cannot use *trace (type bytes.Buffer) as type []byte in argument to newTracePatch
      diff
      diff --git a/network/gitlab_test.go b/network/gitlab_test.go
      index ae6089c0..6d09c54c 100644
      --- a/network/gitlab_test.go
      +++ b/network/gitlab_test.go
      @@ -701,9 +701,7 @@ func getPatchServer(t *testing.T, handler func(w http.ResponseWriter, r *http.Re
       }
       
       func getTracePatch(traceString string, offset int) *tracePatch {
      -       trace := bytes.Buffer{}
      -       trace.WriteString(traceString)
      -       tracePatch, _ := newTracePatch(trace, offset)
      +       tracePatch, _ := newTracePatch([]byte(traceString), offset)
       
              return tracePatch
       }
      diff --git a/network/trace_patch_test.go b/network/trace_patch_test.go
      index ce936643..54061f8a 100644
      --- a/network/trace_patch_test.go
      +++ b/network/trace_patch_test.go
      @@ -10,8 +10,7 @@ import (
       var traceContent = "test content"
       
       func TestNewTracePatch(t *testing.T) {
      -       trace := bytes.NewBufferString(traceContent)
      -       tp, err := newTracePatch(*trace, 0)
      +       tp, err := newTracePatch([]byte(traceContent), 0)
              assert.NoError(t, err)
       
              assert.Equal(t, 0, tp.Offset())
      @@ -21,13 +20,12 @@ func TestNewTracePatch(t *testing.T) {
       
       func TestInvalidTracePatchInitialOffsetValue(t *testing.T) {
              trace := bytes.NewBufferString("test")
      -       _, err := newTracePatch(*trace, trace.Len()+10)
      +       _, err := newTracePatch([]byte("test"), trace.Len()+10)
              assert.EqualError(t, err, "Range is invalid, limit can't be less than offset")
       }
       
       func TestTracePatch_PatchAfterSetNewOffset(t *testing.T) {
      -       trace := bytes.NewBufferString(traceContent)
      -       tp, err := newTracePatch(*trace, 0)
      +       tp, err := newTracePatch([]byte(traceContent), 0)
              assert.NoError(t, err)
       
              tp.SetNewOffset(5)
      @@ -35,8 +33,7 @@ func TestTracePatch_PatchAfterSetNewOffset(t *testing.T) {
       }
       
       func TestTracePatchEmptyPatch(t *testing.T) {
      -       trace := bytes.NewBufferString(traceContent)
      -       tp, err := newTracePatch(*trace, len(traceContent))
      +       tp, err := newTracePatch([]byte(traceContent), len(traceContent))
              assert.NoError(t, err)
       
              assert.Empty(t, tp.Patch())
      diff --git a/network/trace_test.go b/network/trace_test.go
      index 86a25a6c..852c3093 100644
      --- a/network/trace_test.go
      +++ b/network/trace_test.go
      @@ -344,3 +344,17 @@ func TestFinalUpdateWithTrace(t *testing.T) {
       
              wg.Wait()
       }
      +
      +func TestVariablesMasking(t *testing.T) {
      +       traceMessage := "This is the secret message containing secret values"
      +       net := new(common.MockNetwork)
      +
      +       trace := newJobTrace(net, jobConfig, jobCredentials)
      +       trace.SetMasked([]string{"secret"})
      +
      +       trace.updateInterval = 500 * time.Microsecond
      +       trace.start()
      +       fmt.Fprint(trace, traceMessage)
      +
      +       trace.finish()
      +}
      \ No newline at end of file
      Edited by Tomasz Maczukin
    • Resolved by Tomasz Maczukin

      The thing that is obviously missing are the test. While testing the change manually I've found a strange failure, so maybe it would be good to add them now, even if the code is not finished yet?

      For a reference:

      The test
      # ./network/trace_test.go
      
      func TestVariablesMasking(t *testing.T) {
      	traceMessage := "This is the secret message containing secret values"
      	maskedValues := []string{
      		"is",
      		"secret",
      		"containing",
      	}
      
      	wg := new(sync.WaitGroup)
      	wg.Add(1)
      
      	net := new(common.MockNetwork)
      	defer net.AssertExpectations(t)
      	net.On("PatchTrace", jobConfig, jobCredentials, mock.Anything).
      		Return(common.UpdateSucceeded).
      		Once().
      		Run(func(args mock.Arguments) {
      			tracePatch, ok := args[2].(common.JobTracePatch)
      			require.True(t, ok)
      
      			t.Log(traceMessage)
      			t.Log(string(tracePatch.Patch()))
      			assert.Equal(t, "Th[MASKED] [MASKED] the [MASKED] message [MASKED] [MASKED] values", string(tracePatch.Patch()))
      		})
      	net.On("UpdateJob", jobConfig, jobCredentials, mock.Anything).
      		Return(common.UpdateSucceeded).
      		Once().
      		Run(func(_ mock.Arguments) {
      			wg.Done()
      		})
      
      	trace := newJobTrace(net, jobConfig, jobCredentials)
      	trace.SetMasked(maskedValues)
      
      	trace.updateInterval = 25 * time.Second
      	trace.start()
      
      	fmt.Fprint(trace, traceMessage)
      
      	trace.finish()
      
      	wg.Wait()
      }
      The test output (failing)
      === RUN   TestVariablesMasking
      --- FAIL: TestVariablesMasking (0.00s)
              trace_test.go:368: This is the secret message containing secret values
              trace_test.go:369: Th[MASKED] [MASKED] the [MASKED] message [MASKED] [MASKED] value
              assertions.go:260: 
                              Error Trace:    trace_test.go:370
                                                                      mock_Network.go:31
                                                                      trace.go:252
                                                                      trace.go:319
                                                                      trace.go:119
                                                                      trace_test.go:387
                              Error:          Not equal: 
                                              expected: "Th[MASKED] [MASKED] the [MASKED] message [MASKED] [MASKED] values"
                                              actual  : "Th[MASKED] [MASKED] the [MASKED] message [MASKED] [MASKED] value"
                                          
                                              Diff:
                                              --- Expected
                                              +++ Actual
                                              @@ -1 +1 @@
                                              -Th[MASKED] [MASKED] the [MASKED] message [MASKED] [MASKED] values
                                              +Th[MASKED] [MASKED] the [MASKED] message [MASKED] [MASKED] value
                              Test:           TestVariablesMasking
              mock.go:456: PASS:      PatchTrace(common.RunnerConfig,*common.JobCredentials,string)
              mock.go:456: PASS:      UpdateJob(common.RunnerConfig,*common.JobCredentials,string)
      FAIL
      exit status 1
      FAIL    gitlab.com/gitlab-org/gitlab-runner/network     0.009s

      The trace that is being sent is missing the last character. Just like c.log.Bytes()[0:c.logMaskedSize] from safeLog() would lost one byte. It seems that increment of c.logMaskedSize is done wrong somewhere. But the code looks properly. So maybe there is something wrong in my test?

    • Resolved by Kamil Trzciński

      I have a feeling that clientJobTrace starts to be bloated with the number of methods and it's responsibilities. It rewrites the job output, it schedules patches/updates sending, it orchestrates the status changes... and now it's starting adjusting the content of the trace. Maybe we could move the trace masking code to an external object that would be just called by the clientJobTrace internals? This could also make tests implementation easier and more unit-like :wink:

    • Resolved by Tomasz Maczukin

      Just thinking loud: should we disallow to set single characters as the masked variabes? Just imagine that someone adds variables containing a, b or 3 and make them masked. This would bloat the size of the trace significantly, waste a lot of CPU power since most of the output would probably contain such simple values.

      Maybe this is something that should be handled on Rails side, but I think it's something that we should think about.

  • @ayufan I've left few comments. Just like @steveazz wrote, I also like the general idea. Using Trie made the implementation so much simpler than I thought it will be :smiley:

  • Kamil Trzciński added 8 commits

    added 8 commits

    Compare with previous version

  • Kamil Trzciński changed the description

    changed the description

  • Kamil Trzciński added 117 commits

    added 117 commits

    Compare with previous version

  • Author Maintainer

    @tmaczukin @steveazz

    This is almost done. I likely miss one or two extra tests.

    Also my dep ensure seems to be quite mangled. Can you check that?

    Can you comment WDYT?

  • Kamil Trzciński assigned to @steveazz

    assigned to @steveazz

  • Also my dep ensure seems to be quite mangled

    @ayufan I think this is because an old version of dep was used, when you ran dep ensure. When updating to v0.5.0 should generate the correct input.

    Edited by Steve Xuereb
  • Author Maintainer

    Checking. Yep. You are right! Thanks :)

    Edited by Kamil Trzciński
  • Kamil Trzciński added 2 commits

    added 2 commits

    Compare with previous version

  • Kamil Trzciński resolved all discussions

    resolved all discussions

  • Kamil Trzciński added 2 commits

    added 2 commits

    • 49e60e29 - Add ability to mask variables.
    • 20022a2b - Add `github.com/markelog/trie`

    Compare with previous version

  • Kamil Trzciński added 2 commits

    added 2 commits

    • b7fd7181 - Add ability to mask variables.
    • a475bcf9 - Add `github.com/markelog/trie`

    Compare with previous version

  • Tomasz Maczukin
  • Tomasz Maczukin
  • Tomasz Maczukin
  • Steve Xuereb
  • Steve Xuereb
  • Steve Xuereb
  • Steve Xuereb
  • @ayufan this is awesome I learned about tire whilst reviewing this so thank you :bow: I left a few questions.

  • assigned to @ayufan

  • Kamil Trzciński added 13 commits

    added 13 commits

    Compare with previous version

  • Author Maintainer

    @steveazz Another round? I miss one final test :)

  • Kamil Trzciński assigned to @steveazz

    assigned to @steveazz

  • Kamil Trzciński unmarked as a Work In Progress

    unmarked as a Work In Progress

  • added 1 commit

    • afd7e998 - Add `github.com/markelog/trie`

    Compare with previous version

  • Kamil Trzciński added 2 commits

    added 2 commits

    • e252143e - Add ability to mask variables.
    • 37e445ba - Add `github.com/markelog/trie`

    Compare with previous version

  • Kamil Trzciński resolved all discussions

    resolved all discussions

  • Author Maintainer

    @tmaczukin Can you review? I added last test.

  • Two last questions @ayufan looking good!

  • Kamil Trzciński added 2 commits

    added 2 commits

    • 4bf5c2fd - Add ability to mask variables.
    • cdca637e - Add `github.com/markelog/trie`

    Compare with previous version

  • Kamil Trzciński resolved all discussions

    resolved all discussions

  • Steve Xuereb approved this merge request

    approved this merge request

  • LGTM, I'll leave it up to @tmaczukin to give the final :thumbsup: and merge.

  • Tomasz Maczukin approved this merge request

    approved this merge request

  • LGTM, so :thumbsup:

  • Tomasz Maczukin mentioned in commit 9ef63b5f

    mentioned in commit 9ef63b5f

  • Steve Xuereb mentioned in merge request !1241 (merged)

    mentioned in merge request !1241 (merged)

  • mentioned in issue #3989 (closed)

  • Please register or sign in to reply
    Loading