Skip to content
This repository has been archived by the owner on Jun 23, 2020. It is now read-only.

Allow line-log circling #74

Open
wants to merge 1 commit into
base: master
Choose a base branch
from
Open

Allow line-log circling #74

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
11 changes: 5 additions & 6 deletions runtime/line.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -49,12 +49,6 @@ func newWriter(state *State) *lineWriter {
}

func (w *lineWriter) Write(p []byte) (n int, err error) {
// if the maximum log size has been exceeded, the
// log entry is silently ignored.
if w.size >= w.limit {
return len(p), nil
Copy link
Member

@bradrydzewski bradrydzewski Jun 26, 2019 •
edited
Loading

Choose a reason for hiding this comment

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

one issue is that this will not place any restrictions on the size of the logs that are streamed (in real time) to the server which stores the stream in memory. Storing the stream in memory (for dozens or even hundreds of concurrent builds) is not an issue because the size of the logs are limited (e.g. 100 concurrent builds cannot use more than 500mb ram on the server). When this limit is removed it presents an opportunity to overload the server memory.

Copy link
Author

@typeless typeless Jun 27, 2019 •
edited
Loading

Choose a reason for hiding this comment

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

@bradrydzewski As I understand it, every time append needs more space than the slice current has, it will allocate a new one and copy the content of the old slice to it. Then the memory chunk of the old slice can be recycled. The lines (pointers) not copied to the new space are dead and can be recycled too. So the cap of the slice keeps under the limit.
https://play.golang.org/p/-3SZNMLs_5h
https://github.com/golang/go/blob/master/src/runtime/slice.go#L76-L191

That said, there might be something I am missing, and only actual measurement can make sure.

Copy link
Author

Choose a reason for hiding this comment

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

I did some simplified test:

mura@bs003:~/tmp$ cat a.go
package main

import (
        "fmt"
)

func main() {
        myslice := make([]byte, 1024)
        for i := 0; i < 1000000000; i++ {
                myslice = append(myslice, 'A')
                myslice = myslice[1:]

        }
        fmt.Printf("cap(myslice):%d len(myslice):%d [0]:%c [-1]:%c\n", cap(myslice), len(myslice), myslice[0], myslice[len(myslice)-1])

}
mura@bs003:~/tmp$ go build a.go
mura@bs003:~/tmp$ /usr/bin/time -v ./a
cap(myslice):1024 len(myslice):1024 [0]:A [-1]:A
        Command being timed: "./a"
        User time (seconds): 6.72
        System time (seconds): 0.26
        Percent of CPU this job got: 132%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 0:05.28
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 6668
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 0
        Minor (reclaiming a frame) page faults: 9844
        Voluntary context switches: 21049
        Involuntary context switches: 13
        Swaps: 0
        File system inputs: 0
        File system outputs: 0
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0

As expected, the peak memory does not grow to 1GB.

Copy link
Member

@bradrydzewski bradrydzewski Jun 27, 2019 •
edited
Loading

Choose a reason for hiding this comment

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

that is testing the agent. I am speaking of the server-side package that stores the streams in-memory at https://github.com/drone/drone/tree/master/livelog.

The circular buffer does not restrict the size of logs pushed to the server (this line) and therefore allows unbounded log lines to accumulate. In 2013 (in a very early prototype of Drone) a single build generated 120mb log file and took down our server. With no limit to the stream, the server would be susceptible to this issue.

Copy link
Author

Choose a reason for hiding this comment

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

I understand what you mean now.

Copy link
Author

Choose a reason for hiding this comment

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

Just had a look at it.
It seems that the stream logger has done something similar
(https://github.com/drone/drone/blob/master/livelog/stream.go#L43-L57) to avoid unbounded log lines.
About the channel subscribers, I can find only one in the live_log test.
https://github.com/drone/drone/blob/master/livelog/livelog.go#L79
I am not 100% confident, though.

}

out := string(p)
if w.rep != nil {
out = w.rep.Replace(out)
Expand Down Expand Up @@ -83,6 +77,11 @@ func (w *lineWriter) Write(p []byte) (n int, err error) {
if w.state.hook.GotLine != nil {
w.state.hook.GotLine(w.state, line)
}

for w.size+len(part) >= w.limit {
w.size -= len(w.lines[0].Message)
w.lines = w.lines[1:]
}
w.size = w.size + len(part)
w.num++

Expand Down
28 changes: 28 additions & 0 deletions runtime/line_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -114,3 +114,31 @@ func TestLineReplacer(t *testing.T) {
t.Errorf("Expect nil replacer when no masked secrets")
}
}

func TestLineCircling(t *testing.T) {
hook := &Hook{}
state := &State{}

state.hook = hook
state.Step = &engine.Step{}
state.config = &engine.Spec{}
state.config.Secrets = []*engine.Secret{
{Metadata: engine.Metadata{Name: "foo"}, Data: "bar"},
}

w := newWriter(state)
w.limit = 25
w.Write([]byte("foobar1"))
w.Write([]byte("foobar2"))
w.Write([]byte("foobar3"))

if len(w.lines) != 2 {
t.Errorf("Got %d lines, want %d lines", len(w.lines), 2)
}
if got, want := w.lines[0].Message, "foo********2"; got != want {
t.Errorf("Got line %q, want %q", got, want)
}
if got, want := w.lines[1].Message, "foo********3"; got != want {
t.Errorf("Got line %q, want %q", got, want)
}
}