From ac2d6fa5d054ca725a7268eb1a8e050525372c34 Mon Sep 17 00:00:00 2001 From: Paul Buetow Date: Sun, 24 Oct 2021 12:59:08 +0300 Subject: Fix deadlock around aggregating data + server max concurrent file read limiter --- integrationtests/commandutils.go | 36 +++++++++--- integrationtests/dmap_test.go | 42 ++++++++++---- integrationtests/dtail_test.go | 1 - internal/clients/connectors/serverless.go | 1 - internal/io/fs/catfile.go | 5 +- internal/io/fs/readfile.go | 26 ++------- internal/io/fs/tailfile.go | 5 +- internal/mapr/server/aggregate.go | 93 ++++++++++++++++++++----------- internal/server/handlers/basehandler.go | 1 - internal/server/handlers/readcommand.go | 39 ++++++++++++- 10 files changed, 163 insertions(+), 86 deletions(-) diff --git a/integrationtests/commandutils.go b/integrationtests/commandutils.go index 23b9c37..d5b5987 100644 --- a/integrationtests/commandutils.go +++ b/integrationtests/commandutils.go @@ -12,9 +12,6 @@ import ( "time" ) -// The exit code and the Go error of the command terminated. -type exitPromise func() (int, error) - func runCommand(ctx context.Context, t *testing.T, stdoutFile, cmdStr string, args ...string) (int, error) { @@ -51,7 +48,7 @@ func runCommandRetry(ctx context.Context, t *testing.T, retries int, stdoutFile, } func startCommand(ctx context.Context, t *testing.T, cmdStr string, - args ...string) (<-chan string, <-chan string, exitPromise, error) { + args ...string) (<-chan string, <-chan string, <-chan error, error) { stdoutCh := make(chan string) stderrCh := make(chan string) @@ -90,10 +87,33 @@ func startCommand(ctx context.Context, t *testing.T, cmdStr string, close(stderrCh) }() - return stdoutCh, stderrCh, func() (int, error) { - err := cmd.Wait() - return exitCodeFromError(err), err - }, nil + cmdErrCh := make(chan error) + go func() { + cmdErrCh <- cmd.Wait() + }() + + return stdoutCh, stderrCh, cmdErrCh, nil +} + +func waitForCommand(ctx context.Context, t *testing.T, + stdoutCh, stderrCh <-chan string, cmdErrCh <-chan error) { + + for { + select { + case line, ok := <-stdoutCh: + if ok { + t.Log(line) + } + case line, ok := <-stderrCh: + if ok { + t.Log(line) + } + case cmdErr := <-cmdErrCh: + t.Log(fmt.Sprintf("Command finished with with exit code %d: %v", + exitCodeFromError(cmdErr), cmdErr)) + return + } + } } func exitCodeFromError(err error) int { diff --git a/integrationtests/dmap_test.go b/integrationtests/dmap_test.go index 7d8b8b5..2de679b 100644 --- a/integrationtests/dmap_test.go +++ b/integrationtests/dmap_test.go @@ -15,7 +15,6 @@ func TestDMap(t *testing.T) { return } inFile := "mapr_testdata.log" - stdoutFile := "dmap.stdout.tmp" csvFile := "dmap.csv.tmp" expectedCsvFile := "dmap.csv.expected" queryFile := fmt.Sprintf("%s.query", csvFile) @@ -25,14 +24,23 @@ func TestDMap(t *testing.T) { "avg($goroutines),min(concurrentConnections),max(lifetimeConnections) "+ "group by $hostname outfile %s", csvFile) - _, err := runCommand(context.TODO(), t, stdoutFile, - "../dmap", "--query", query, inFile) + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + stdoutCh, stderrCh, cmdErrCh, err := startCommand(ctx, t, "../dmap", + "--query", query, + "--logger", "stdout", + "--logLevel", "error", + "--noColor", + inFile) if err != nil { t.Error(err) return } + waitForCommand(ctx, t, stdoutCh, stderrCh, cmdErrCh) + if err := compareFiles(t, csvFile, expectedCsvFile); err != nil { t.Error(err) return @@ -42,7 +50,6 @@ func TestDMap(t *testing.T) { return } - os.Remove(stdoutFile) os.Remove(csvFile) os.Remove(queryFile) } @@ -100,16 +107,31 @@ func TestDMap3(t *testing.T) { "avg($goroutines),min($goroutines) group by $time order by count($time) "+ "outfile %s", csvFile) - // Read many input files at once. - args := []string{"--logLevel", "trace", "--pprof", "localhost:8080", "--query", query} - for i := 0; i < 100; i++ { - args = append(args, inFile) - } + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + stdoutCh, stderrCh, cmdErrCh, err := startCommand(ctx, t, "../dmap", + "--query", query, + "--logger", "stdout", + "--logLevel", "info", + "--noColor", + inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, + inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, + inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, + inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, + inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, + inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, + inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, + inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, + inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, + inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile, inFile) - if _, err := runCommand(context.TODO(), t, stdoutFile, "../dmap", args...); err != nil { + if err != nil { t.Error(err) return } + waitForCommand(ctx, t, stdoutCh, stderrCh, cmdErrCh) + if err := compareFilesContents(t, csvFile, expectedCsvFile); err != nil { t.Error(err) return diff --git a/integrationtests/dtail_test.go b/integrationtests/dtail_test.go index c6d0107..2b4d6de 100644 --- a/integrationtests/dtail_test.go +++ b/integrationtests/dtail_test.go @@ -45,7 +45,6 @@ func TestDTailWithServer(t *testing.T) { return } - // TODO: In testmode, the client should not try to manipulate any known_hosts files. // TODO: In testmode, never read a config file (use none for all commands) clientCh, _, _, err := startCommand(ctx, t, "../dtail", diff --git a/internal/clients/connectors/serverless.go b/internal/clients/connectors/serverless.go index 2ff490a..431247a 100644 --- a/internal/clients/connectors/serverless.go +++ b/internal/clients/connectors/serverless.go @@ -47,7 +47,6 @@ func (s *Serverless) Start(ctx context.Context, cancel context.CancelFunc, dlog.Client.Debug("Starting serverless connector") go func() { defer cancel() - if err := s.handle(ctx, cancel); err != nil { dlog.Client.Warn(err) } diff --git a/internal/io/fs/catfile.go b/internal/io/fs/catfile.go index 01c15ba..e4676f3 100644 --- a/internal/io/fs/catfile.go +++ b/internal/io/fs/catfile.go @@ -6,9 +6,7 @@ type CatFile struct { } // NewCatFile returns a new file catter. -func NewCatFile(filePath string, globID string, serverMessages chan<- string, - limiter chan struct{}) CatFile { - +func NewCatFile(filePath string, globID string, serverMessages chan<- string) CatFile { return CatFile{ readFile: readFile{ filePath: filePath, @@ -17,7 +15,6 @@ func NewCatFile(filePath string, globID string, serverMessages chan<- string, retry: false, canSkipLines: false, seekEOF: false, - limiter: limiter, }, } } diff --git a/internal/io/fs/readfile.go b/internal/io/fs/readfile.go index 28cbe58..5815aa3 100644 --- a/internal/io/fs/readfile.go +++ b/internal/io/fs/readfile.go @@ -38,7 +38,6 @@ type readFile struct { canSkipLines bool // Seek to the EOF before processing file? seekEOF bool - limiter chan struct{} } // String returns the string representation of the readFile @@ -66,25 +65,7 @@ func (f readFile) Retry() bool { func (f readFile) Start(ctx context.Context, ltx lcontext.LContext, lines chan<- line.Line, re regex.Regex) error { - dlog.Common.Debug("readFile", f) - defer func() { - select { - case <-f.limiter: - default: - } - }() - - select { - case f.limiter <- struct{}{}: - default: - select { - case f.serverMessages <- dlog.Common.Warn(f.filePath, f.globID, - "Server limit reached. Queuing file..."): - case <-ctx.Done(): - return nil - } - f.limiter <- struct{}{} - } + dlog.Common.Trace("readFile", f) fd, err := os.Open(f.filePath) if err != nil { @@ -156,7 +137,9 @@ func (f readFile) makeReader(fd *os.File) (reader *bufio.Reader, err error) { return } -func (f readFile) read(ctx context.Context, fd *os.File, rawLines chan *bytes.Buffer, truncate <-chan struct{}) error { +func (f readFile) read(ctx context.Context, fd *os.File, rawLines chan *bytes.Buffer, + truncate <-chan struct{}) error { + var offset uint64 reader, err := f.makeReader(fd) if err != nil { @@ -250,6 +233,7 @@ func (f readFile) filterWithoutLContext(ctx context.Context, rawLines <-chan *by return } if filteredLine, ok := f.transmittable(line, len(lines), cap(lines), re); ok { + //dlog.Common.Trace("TODO", "lines", lines, len(lines), cap(lines)) select { case lines <- filteredLine: case <-ctx.Done(): diff --git a/internal/io/fs/tailfile.go b/internal/io/fs/tailfile.go index b03b45d..7a40ac4 100644 --- a/internal/io/fs/tailfile.go +++ b/internal/io/fs/tailfile.go @@ -6,9 +6,7 @@ type TailFile struct { } // NewTailFile returns a new file tailer. -func NewTailFile(filePath string, globID string, serverMessages chan<- string, - limiter chan struct{}) TailFile { - +func NewTailFile(filePath string, globID string, serverMessages chan<- string) TailFile { return TailFile{ readFile: readFile{ filePath: filePath, @@ -17,7 +15,6 @@ func NewTailFile(filePath string, globID string, serverMessages chan<- string, retry: true, canSkipLines: true, seekEOF: true, - limiter: limiter, }, } } diff --git a/internal/mapr/server/aggregate.go b/internal/mapr/server/aggregate.go index 97fee11..11c9ee5 100644 --- a/internal/mapr/server/aggregate.go +++ b/internal/mapr/server/aggregate.go @@ -20,6 +20,7 @@ type Aggregate struct { done *internal.Done // NextLinesCh can be used to use a new line ch. NextLinesCh chan chan line.Line + linesCh chan line.Line // Hostname of the current server (used to populate $hostname field). hostname string // Signals to serialize data. @@ -113,58 +114,84 @@ func (a *Aggregate) aggregateTimer(ctx context.Context) { } } +func (a *Aggregate) nextLine() (line line.Line, ok bool, noMoreChannels bool) { + + dlog.Common.Trace("nextLine", "entry", line, ok, noMoreChannels) + select { + case line, ok = <-a.linesCh: + if !ok { + // Channel is closed, go to next channel. + select { + case a.linesCh = <-a.NextLinesCh: + default: + noMoreChannels = true + } + } + default: + // No new line from current lines channel. Try next one. + select { + case newLinesCh := <-a.NextLinesCh: + oldLinesCh := a.linesCh + go func() { a.NextLinesCh <- oldLinesCh }() + a.linesCh = newLinesCh + default: + // No new lines channel found. + } + } + dlog.Common.Trace("nextLine", "exit", line, ok, noMoreChannels) + + return +} + func (a *Aggregate) fieldsFromLines(ctx context.Context) <-chan map[string]string { fieldsCh := make(chan map[string]string) go func() { defer close(fieldsCh) - var lines chan line.Line // Gather first lines channel (first input file) select { - case lines = <-a.NextLinesCh: + case a.linesCh = <-a.NextLinesCh: case <-ctx.Done(): return } for { select { - case line, ok := <-lines: - if !ok { - select { - case lines = <-a.NextLinesCh: - // Have a new lines channel (e.g. new input file) - case <-ctx.Done(): - default: - // No new lines channel found. - return - } - } + case <-ctx.Done(): + return + default: + } - maprLine := strings.TrimSpace(line.Content.String()) - fields, err := a.parser.MakeFields(maprLine) - // Can't recycle it here yet, as field slices are still - // TODO: Add unit test reading from multiple mapreduce files lines. - // TODO: Add capability to recycle this bytes buffer. - //pool.RecycleBytesBuffer(line.Content) - - if err != nil { - // Should fields be ignored anyway? - if err != logformat.ErrIgnoreFields { - dlog.Common.Error(fields, err) - } - continue - } - if !a.query.WhereClause(fields) { - continue + // Gather first lines channel (first input file) + line, ok, noMoreChannels := a.nextLine() + if !ok { + if noMoreChannels { + break } + time.Sleep(time.Millisecond * 100) + } + + maprLine := strings.TrimSpace(line.Content.String()) + fields, err := a.parser.MakeFields(maprLine) + // Can't recycle it here yet, as field slices are still + // MAYBETODO: Add capability to recycle this bytes buffer. + //pool.RecycleBytesBuffer(line.Content) - select { - case fieldsCh <- fields: - case <-ctx.Done(): + if err != nil { + // Should fields be ignored anyway? + if err != logformat.ErrIgnoreFields { + dlog.Common.Error(fields, err) } + continue + } + if !a.query.WhereClause(fields) { + continue + } + + select { + case fieldsCh <- fields: case <-ctx.Done(): - return } } }() diff --git a/internal/server/handlers/basehandler.go b/internal/server/handlers/basehandler.go index 6d10d17..53bf375 100644 --- a/internal/server/handlers/basehandler.go +++ b/internal/server/handlers/basehandler.go @@ -114,7 +114,6 @@ func (h *baseHandler) Read(p []byte) (n int, err error) { pool.RecycleBytesBuffer(line.Content) case <-time.After(time.Second): - // Once in a while check whether we are done. select { case <-h.done.Done(): err = io.EOF diff --git a/internal/server/handlers/readcommand.go b/internal/server/handlers/readcommand.go index 4728a55..51077fc 100644 --- a/internal/server/handlers/readcommand.go +++ b/internal/server/handlers/readcommand.go @@ -109,18 +109,51 @@ func (r *readCommand) readFileIfPermissions(ctx context.Context, ltx lcontext.LC r.readFile(ctx, ltx, path, globID, re) } +func (*readCommand) limit(ctx context.Context, limiter chan struct{}, message string) { + select { + case <-ctx.Done(): + return + } +} + func (r *readCommand) readFile(ctx context.Context, ltx lcontext.LContext, path, globID string, re regex.Regex) { dlog.Server.Info(r.server.user, "Start reading file", path, globID) var reader fs.FileReader + var limiter chan struct{} + switch r.mode { case omode.TailClient: - reader = fs.NewTailFile(path, globID, r.server.serverMessages, r.server.tailLimiter) + reader = fs.NewTailFile(path, globID, r.server.serverMessages) + limiter = r.server.tailLimiter case omode.GrepClient, omode.CatClient: - reader = fs.NewCatFile(path, globID, r.server.serverMessages, r.server.catLimiter) + reader = fs.NewCatFile(path, globID, r.server.serverMessages) + limiter = r.server.catLimiter default: - reader = fs.NewTailFile(path, globID, r.server.serverMessages, r.server.tailLimiter) + reader = fs.NewTailFile(path, globID, r.server.serverMessages) + limiter = r.server.tailLimiter + } + + defer func() { + select { + case <-limiter: + default: + } + }() + + select { + case limiter <- struct{}{}: + case <-ctx.Done(): + return + default: + dlog.Server.Info("Server limit hit, queueing file", len(limiter), path) + select { + case limiter <- struct{}{}: + dlog.Server.Info("Server limit OK now, processing file", len(limiter), path) + case <-ctx.Done(): + return + } } lines := r.server.lines -- cgit v1.2.3 From 14959ffba46282dd7b8ada53db0dfc0e1b26ab2e Mon Sep 17 00:00:00 2001 From: Paul Buetow Date: Sun, 24 Oct 2021 13:34:06 +0300 Subject: Fix DCat color test. --- Makefile | 2 - integrationtests/dcat_test.go | 5 +- integrationtests/dcatcolors.expected | 5508 ++++++++++++++--------------- integrationtests/dtail_test.go | 2 +- internal/config/client.go | 3 - internal/config/env.go | 20 + internal/config/initializer.go | 6 +- internal/io/dlog/dlog.go | 2 +- internal/mapr/logformat/parser.go | 4 +- internal/mapr/server/aggregate.go | 3 +- internal/server/handlers/healthhandler.go | 4 +- internal/server/handlers/serverhandler.go | 4 +- internal/ssh/client/authmethods.go | 21 +- internal/ssh/client/knownhostscallback.go | 6 - 14 files changed, 2793 insertions(+), 2797 deletions(-) diff --git a/Makefile b/Makefile index 0e66ac4..a3b299c 100644 --- a/Makefile +++ b/Makefile @@ -1,6 +1,4 @@ GO ?= go -# This is so that all the tests don't manipulate ~/.ssh/known_hosts -DTAIL_SSH_DONT_ADD_HOSTS_TO_KNOWNHOSTS_FILE = yes all: build build: dserver dcat dgrep dmap dtail dtailhealth dserver: diff --git a/integrationtests/dcat_test.go b/integrationtests/dcat_test.go index 2516867..dc2234f 100644 --- a/integrationtests/dcat_test.go +++ b/integrationtests/dcat_test.go @@ -60,13 +60,11 @@ func TestDCat2(t *testing.T) { os.Remove(stdoutFile) } -/* -// TODO: The test currently fails as there is a hostname in the output. What needs -// to be done is to ignore the hostnames in the output (which is field 2 of the output) func TestDCatColors(t *testing.T) { if !config.Env("DTAIL_RUN_INTEGRATION_TESTS") { return } + testdataFile := "dcatcolors.txt" stdoutFile := "dcatcolors.out" expectedFile := "dcatcolors.expected" @@ -86,4 +84,3 @@ func TestDCatColors(t *testing.T) { os.Remove(stdoutFile) } -*/ diff --git a/integrationtests/dcatcolors.expected b/integrationtests/dcatcolors.expected index 3ccdeff..fcd8dbf 100644 --- a/integrationtests/dcatcolors.expected +++ b/integrationtests/dcatcolors.expected @@ -1,2754 +1,2754 @@ -REMOTE|earth|100|1|dcatcolors.txt|FATAL|20211015-053919|SSH relaxed-auth mode enabled -REMOTE|earth|100|2|dcatcolors.txt|INFO|20211015-053919|Creating server|DTail 4.0.0-RC1 Protocol 4 Have a lot of fun! -REMOTE|earth|100|3|dcatcolors.txt|INFO|20211015-053919|Generating private server RSA host key -REMOTE|earth|100|4|dcatcolors.txt|ERROR|20211015-053919|Unable to write private server RSA host key to file|cache/ssh_host_key|open cache/ssh_host_key: no such file or directory -REMOTE|earth|100|5|dcatcolors.txt|INFO|20211015-053919|Starting server -REMOTE|earth|100|6|dcatcolors.txt|INFO|20211015-053919|Binding server|0.0.0.0:2222 -REMOTE|earth|100|7|dcatcolors.txt|DEBUG|20211015-053919|Starting listener loop -REMOTE|earth|100|8|dcatcolors.txt|INFO|20211015-053919|Starting continuous job runner after 10s -REMOTE|earth|100|9|dcatcolors.txt|INFO|20211015-053919|Starting scheduled job runner after 10s -REMOTE|earth|100|10|dcatcolors.txt|INFO|20211015-053926|Handling connection -REMOTE|earth|100|11|dcatcolors.txt|INFO|20211015-053928|paul@172.17.0.1:33710|Incoming authorization -REMOTE|earth|100|12|dcatcolors.txt|FATAL|20211015-053928|paul@172.17.0.1:33710|Granting permissions via relaxed-auth -REMOTE|earth|100|13|dcatcolors.txt|INFO|20211015-053928|1|stats.go:53|8|16|7|1.34|781h28m6s|MAPREDUCE:STATS|currentConnections=1|lifetimeConnections=1 -REMOTE|earth|100|14|dcatcolors.txt|INFO|20211015-053928|paul@172.17.0.1:33710|Invoking channel handler -REMOTE|earth|100|15|dcatcolors.txt|INFO|20211015-053928|paul@172.17.0.1:33710|Invoking request handler -REMOTE|earth|100|16|dcatcolors.txt|DEBUG|20211015-053928|paul@172.17.0.1:33710|Creating new server handler -REMOTE|earth|100|17|dcatcolors.txt|DEBUG|20211015-053928|paul@172.17.0.1:33710|protocol 4 base64 dGFpbDogL3Zhci9sb2cvZHNlcnZlci8qIHJlZ2V4Om5vb3Ag -REMOTE|earth|100|18|dcatcolors.txt|TRACE|20211015-053928|paul@172.17.0.1:33710|Base64 decoded received command|tail: /var/log/dserver/* regex:noop |36|[tail: /var/log/dserver/* regex:noop ]|at /home/paul/git/dtail/internal/server/handlers/basehandler.go:225 -REMOTE|earth|100|19|dcatcolors.txt|DEBUG|20211015-053928|paul@172.17.0.1:33710|Handling user command|36|[tail: /var/log/dserver/* regex:noop ] -REMOTE|earth|100|20|dcatcolors.txt|DEBUG|20211015-053928|paul@172.17.0.1:33710|/var/log/dserver/dserver.log|readfiles|Checking config permissions -REMOTE|earth|100|21|dcatcolors.txt|FATAL|20211015-053928|paul@172.17.0.1:33710|/var/log/dserver/dserver.log|readfiles|Server releaxed auth enabled -REMOTE|earth|100|22|dcatcolors.txt|INFO|20211015-053928|paul@172.17.0.1:33710|Start reading file|/var/log/dserver/dserver.log|dserver.log -REMOTE|earth|100|23|dcatcolors.txt|DEBUG|20211015-053928|readFile|readFile(filePath:/var/log/dserver/dserver.log,globID:dserver.log,retry:true,canSkipLines:true,seekEOF:true) -REMOTE|earth|100|24|dcatcolors.txt|INFO|20211015-053929|1|stats.go:53|8|26|7|1.34|781h28m7s|MAPREDUCE:STATS|currentConnections=1|lifetimeConnections=1 -REMOTE|earth|100|25|dcatcolors.txt|DEBUG|20211015-053931|/var/log/dserver/dserver.log|File truncation check -REMOTE|earth|100|26|dcatcolors.txt|DEBUG|20211015-053934|/var/log/dserver/dserver.log|File truncation check -REMOTE|earth|100|27|dcatcolors.txt|DEBUG|20211015-053937|/var/log/dserver/dserver.log|File truncation check -REMOTE|earth|100|28|dcatcolors.txt|INFO|20211015-053939|1|stats.go:53|8|16|7|1.21|781h28m16s|MAPREDUCE:STATS|lifetimeConnections=1|currentConnections=0 -REMOTE|earth|100|29|dcatcolors.txt|INFO|20211015-053939|paul@172.17.0.1:33710|Good bye Mister! -REMOTE|earth|100|30|dcatcolors.txt|DEBUG|20211015-053939|paul@172.17.0.1:33710|shutdown() -REMOTE|earth|100|31|dcatcolors.txt|TRACE|20211015-053939|paul@172.17.0.1:33710|flush()|at /home/paul/git/dtail/internal/server/handlers/basehandler.go:278 -REMOTE|earth|100|32|dcatcolors.txt|DEBUG|20211015-053939|paul@172.17.0.1:33710|ALL lines sent|0xc0002aa000 -REMOTE|earth|100|33|dcatcolors.txt|INFO|20211015-053939|1|stats.go:53|8|11|7|1.21|781h28m17s|MAPREDUCE:STATS|currentConnections=0|lifetimeConnections=1 -REMOTE|earth|100|34|dcatcolors.txt|INFO|20211015-053942|Handling connection -REMOTE|earth|100|35|dcatcolors.txt|INFO|20211015-053942|paul@172.17.0.1:33712|Incoming authorization -REMOTE|earth|100|36|dcatcolors.txt|FATAL|20211015-053942|paul@172.17.0.1:33712|Granting permissions via relaxed-auth -REMOTE|earth|100|37|dcatcolors.txt|INFO|20211015-053942|1|stats.go:53|8|15|7|1.11|781h28m19s|MAPREDUCE:STATS|lifetimeConnections=2|currentConnections=1 -REMOTE|earth|100|38|dcatcolors.txt|INFO|20211015-053942|paul@172.17.0.1:33712|Invoking channel handler -REMOTE|earth|100|39|dcatcolors.txt|INFO|20211015-053942|paul@172.17.0.1:33712|Invoking request handler -REMOTE|earth|100|40|dcatcolors.txt|DEBUG|20211015-053942|paul@172.17.0.1:33712|Creating new server handler -REMOTE|earth|100|41|dcatcolors.txt|DEBUG|20211015-053942|paul@172.17.0.1:33712|protocol 4 base64 Y2F0OiAvZXRjL3Bhc3N3ZCByZWdleDpub29wIA== -REMOTE|earth|100|42|dcatcolors.txt|TRACE|20211015-053942|paul@172.17.0.1:33712|Base64 decoded received command|cat: /etc/passwd regex:noop |28|[cat: /etc/passwd regex:noop ]|at /home/paul/git/dtail/internal/server/handlers/basehandler.go:225 -REMOTE|earth|100|43|dcatcolors.txt|DEBUG|20211015-053942|paul@172.17.0.1:33712|Handling user command|28|[cat: /etc/passwd regex:noop ] -REMOTE|earth|100|44|dcatcolors.txt|DEBUG|20211015-053942|paul@172.17.0.1:33712|/etc/passwd|readfiles|Checking config permissions -REMOTE|earth|100|45|dcatcolors.txt|FATAL|20211015-053942|paul@172.17.0.1:33712|/etc/passwd|readfiles|Server releaxed auth enabled -REMOTE|earth|100|46|dcatcolors.txt|INFO|20211015-053942|paul@172.17.0.1:33712|Start reading file|/etc/passwd|passwd -REMOTE|earth|100|47|dcatcolors.txt|DEBUG|20211015-053942|readFile|readFile(filePath:/etc/passwd,globID:passwd,retry:false,canSkipLines:false,seekEOF:false) -REMOTE|earth|100|48|dcatcolors.txt|INFO|20211015-053942|/etc/passwd|End of file reached -REMOTE|earth|100|49|dcatcolors.txt|DEBUG|20211015-053942|paul@172.17.0.1:33712|shutdown() -REMOTE|earth|100|50|dcatcolors.txt|TRACE|20211015-053942|paul@172.17.0.1:33712|flush()|at /home/paul/git/dtail/internal/server/handlers/basehandler.go:278 -REMOTE|earth|100|51|dcatcolors.txt|DEBUG|20211015-053942|paul@172.17.0.1:33712|Still lines to be sent -REMOTE|earth|100|52|dcatcolors.txt|DEBUG|20211015-053942|paul@172.17.0.1:33712|ALL lines sent|0xc0002aa0e0 -REMOTE|earth|100|53|dcatcolors.txt|INFO|20211015-053942|1|stats.go:53|8|21|7|1.11|781h28m19s|MAPREDUCE:STATS|lifetimeConnections=2|currentConnections=0 -REMOTE|earth|100|54|dcatcolors.txt|INFO|20211015-053942|paul@172.17.0.1:33712|Good bye Mister! -REMOTE|earth|100|55|dcatcolors.txt|INFO|20211015-053949|Handling connection -REMOTE|earth|100|56|dcatcolors.txt|INFO|20211015-053949|paul@172.17.0.1:33714|Incoming authorization -REMOTE|earth|100|57|dcatcolors.txt|FATAL|20211015-053949|paul@172.17.0.1:33714|Granting permissions via relaxed-auth -REMOTE|earth|100|58|dcatcolors.txt|INFO|20211015-053949|1|stats.go:53|8|15|7|1.10|781h28m26s|MAPREDUCE:STATS|currentConnections=1|lifetimeConnections=3 -REMOTE|earth|100|59|dcatcolors.txt|INFO|20211015-053949|paul@172.17.0.1:33714|Invoking channel handler -REMOTE|earth|100|60|dcatcolors.txt|INFO|20211015-053949|paul@172.17.0.1:33714|Invoking request handler -REMOTE|earth|100|61|dcatcolors.txt|DEBUG|20211015-053949|paul@172.17.0.1:33714|Creating new server handler -REMOTE|earth|100|62|dcatcolors.txt|DEBUG|20211015-053949|paul@172.17.0.1:33714|protocol 4 base64 bWFwIGZyb20gc3RhdHMgc2VsZWN0IGF2ZygkZ29yb3V0aW5lcyksbWF4KCRnb3JvdXRpbmVzKSxtaW4oJGdvcm91dGluZXMpLGxhc3QoJGdvcm91dGluZXMpLGNvdW50KCRob3N0bmFtZSksJGhvc3RuYW1lIGdyb3VwIGJ5ICRob3N0bmFtZSBvcmRlciBieSBhdmcoJGdvcm91dGluZXMp -REMOTE|earth|100|63|dcatcolors.txt|TRACE|20211015-053949|paul@172.17.0.1:33714|Base64 decoded received command|map from stats select avg($goroutines),max($goroutines),min($goroutines),last($goroutines),count($hostname),$hostname group by $hostname order by avg($goroutines)|162|[map from stats select avg($goroutines),max($goroutines),min($goroutines),last($goroutines),count($hostname),$hostname group by $hostname order by avg($goroutines)]|at /home/paul/git/dtail/internal/server/handlers/basehandler.go:225 -REMOTE|earth|100|64|dcatcolors.txt|DEBUG|20211015-053949|paul@172.17.0.1:33714|Handling user command|162|[map from stats select avg($goroutines),max($goroutines),min($goroutines),last($goroutines),count($hostname),$hostname group by $hostname order by avg($goroutines)] -REMOTE|earth|100|65|dcatcolors.txt|INFO|20211015-053949|Creating log format parser|default -REMOTE|earth|100|66|dcatcolors.txt|DEBUG|20211015-053949|paul@172.17.0.1:33714|protocol 4 base64 Y2F0OiAvdmFyL2xvZy9kc2VydmVyLyogcmVnZXg6ZGVmYXVsdCBcfE1BUFJFRFVDRTpTVEFUU1x8 -REMOTE|earth|100|67|dcatcolors.txt|TRACE|20211015-053949|paul@172.17.0.1:33714|Base64 decoded received command|cat: /var/log/dserver/* regex:default \|MAPREDUCE:STATS\||57|[cat: /var/log/dserver/* regex:default \|MAPREDUCE:STATS\|]|at /home/paul/git/dtail/internal/server/handlers/basehandler.go:225 -REMOTE|earth|100|68|dcatcolors.txt|DEBUG|20211015-053949|paul@172.17.0.1:33714|Handling user command|57|[cat: /var/log/dserver/* regex:default \|MAPREDUCE:STATS\|] -REMOTE|earth|100|69|dcatcolors.txt|DEBUG|20211015-053949|paul@172.17.0.1:33714|/var/log/dserver/dserver.log|readfiles|Checking config permissions -REMOTE|earth|100|70|dcatcolors.txt|FATAL|20211015-053949|paul@172.17.0.1:33714|/var/log/dserver/dserver.log|readfiles|Server releaxed auth enabled -REMOTE|earth|100|71|dcatcolors.txt|INFO|20211015-053949|paul@172.17.0.1:33714|Start reading file|/var/log/dserver/dserver.log|dserver.log -REMOTE|earth|100|72|dcatcolors.txt|DEBUG|20211015-053949|readFile|readFile(filePath:/var/log/dserver/dserver.log,globID:dserver.log,retry:false,canSkipLines:false,seekEOF:false) -REMOTE|earth|100|73|dcatcolors.txt|INFO|20211015-053949|/var/log/dserver/dserver.log|End of file reached -REMOTE|earth|100|74|dcatcolors.txt|INFO|20211015-053949|Serializing mapreduce result -REMOTE|earth|100|75|dcatcolors.txt|TRACE|20211015-053949|Serialising mapr.AggregateSet|AggregateSet(Samples:7,FValues:map[avg($goroutines):120 count($hostname):7 max($goroutines):26 min($goroutines):11],SValues:map[$hostname:serv6 last($goroutines):15])|at /home/paul/git/dtail/internal/mapr/aggregateset.go:72 -REMOTE|earth|100|76|dcatcolors.txt|DEBUG|20211015-053949|paul@172.17.0.1:33714|shutdown() -REMOTE|earth|100|77|dcatcolors.txt|TRACE|20211015-053949|paul@172.17.0.1:33714|flush()|at /home/paul/git/dtail/internal/server/handlers/basehandler.go:278 -REMOTE|earth|100|78|dcatcolors.txt|DEBUG|20211015-053949|paul@172.17.0.1:33714|ALL lines sent|0xc0004f0000 -REMOTE|earth|100|79|dcatcolors.txt|INFO|20211015-053949|1|stats.go:53|8|13|7|1.10|781h28m26s|MAPREDUCE:STATS|currentConnections=0|lifetimeConnections=3 -REMOTE|earth|100|80|dcatcolors.txt|INFO|20211015-053949|paul@172.17.0.1:33714|Good bye Mister! -REMOTE|earth|100|81|dcatcolors.txt|INFO|20211015-053949|1|stats.go:53|8|12|7|1.10|781h28m27s|MAPREDUCE:STATS|currentConnections=0|lifetimeConnections=3 -REMOTE|earth|100|82|dcatcolors.txt|INFO|20211015-053959|1|stats.go:53|8|11|7|1.01|781h28m37s|MAPREDUCE:STATS|currentConnections=0|lifetimeConnections=3 -REMOTE|earth|100|83|dcatcolors.txt|INFO|20211015-054002|Handling connection -REMOTE|earth|100|84|dcatcolors.txt|INFO|20211015-054002|paul@172.17.0.1:33716|Incoming authorization -REMOTE|earth|100|85|dcatcolors.txt|FATAL|20211015-054002|paul@172.17.0.1:33716|Granting permissions via relaxed-auth -REMOTE|earth|100|86|dcatcolors.txt|INFO|20211015-054002|1|stats.go:53|8|15|7|1.09|781h28m39s|MAPREDUCE:STATS|currentConnections=1|lifetimeConnections=4 -REMOTE|earth|100|87|dcatcolors.txt|INFO|20211015-054002|paul@172.17.0.1:33716|Invoking channel handler -REMOTE|earth|100|88|dcatcolors.txt|INFO|20211015-054002|paul@172.17.0.1:33716|Invoking request handler -REMOTE|earth|100|89|dcatcolors.txt|DEBUG|20211015-054002|paul@172.17.0.1:33716|Creating new server handler -REMOTE|earth|100|90|dcatcolors.txt|DEBUG|20211015-054002|paul@172.17.0.1:33716|protocol 4 base64 Z3JlcDogL3Zhci9sb2cvZHNlcnZlci8qIHJlZ2V4OmRlZmF1bHQgTUFQUkVEVUNF -REMOTE|earth|100|91|dcatcolors.txt|TRACE|20211015-054002|paul@172.17.0.1:33716|Base64 decoded received command|grep: /var/log/dserver/* regex:default MAPREDUCE|48|[grep: /var/log/dserver/* regex:default MAPREDUCE]|at /home/paul/git/dtail/internal/server/handlers/basehandler.go:225 -REMOTE|earth|100|92|dcatcolors.txt|DEBUG|20211015-054002|paul@172.17.0.1:33716|Handling user command|48|[grep: /var/log/dserver/* regex:default MAPREDUCE] -REMOTE|earth|100|93|dcatcolors.txt|DEBUG|20211015-054002|paul@172.17.0.1:33716|/var/log/dserver/dserver.log|readfiles|Checking config permissions -REMOTE|earth|100|94|dcatcolors.txt|FATAL|20211015-054002|paul@172.17.0.1:33716|/var/log/dserver/dserver.log|readfiles|Server releaxed auth enabled -REMOTE|earth|100|95|dcatcolors.txt|INFO|20211015-054002|paul@172.17.0.1:33716|Start reading file|/var/log/dserver/dserver.log|dserver.log -REMOTE|earth|100|96|dcatcolors.txt|DEBUG|20211015-054002|readFile|readFile(filePath:/var/log/dserver/dserver.log,globID:dserver.log,retry:false,canSkipLines:false,seekEOF:false) -REMOTE|earth|100|97|dcatcolors.txt|INFO|20211015-054002|/var/log/dserver/dserver.log|End of file reached -REMOTE|earth|100|98|dcatcolors.txt|DEBUG|20211015-054002|paul@172.17.0.1:33716|shutdown() -REMOTE|earth|100|99|dcatcolors.txt|TRACE|20211015-054002|paul@172.17.0.1:33716|flush()|at /home/paul/git/dtail/internal/server/handlers/basehandler.go:278 -REMOTE|earth|100|100|dcatcolors.txt|DEBUG|20211015-054002|paul@172.17.0.1:33716|Still lines to be sent -REMOTE|earth|100|101|dcatcolors.txt|DEBUG|20211015-054002|paul@172.17.0.1:33716|ALL lines sent|0xc0004f00e0 -REMOTE|earth|100|102|dcatcolors.txt|ERROR|20211015-054002|paul@172.17.0.1:33716|read tcp 172.17.0.8:2222->172.17.0.1:33716: use of closed network connection -REMOTE|earth|100|103|dcatcolors.txt|INFO|20211015-054002|1|stats.go:53|8|15|7|1.09|781h28m39s|MAPREDUCE:STATS|currentConnections=0|lifetimeConnections=4 -REMOTE|earth|100|104|dcatcolors.txt|INFO|20211015-054002|paul@172.17.0.1:33716|Good bye Mister! -REMOTE|earth|100|105|dcatcolors.txt|INFO|20211015-054009|1|stats.go:53|8|11|7|1.00|781h28m47s|MAPREDUCE:STATS|currentConnections=0|lifetimeConnections=4 -REMOTE|earth|100|106|dcatcolors.txt|INFO|20211015-054019|1|stats.go:53|8|11|7|1.01|781h28m57s|MAPREDUCE:STATS|currentConnections=0|lifetimeConnections=4 -REMOTE|earth|100|107|dcatcolors.txt|INFO|20211015-054029|1|stats.go:53|8|11|7|0.85|781h29m7s|MAPREDUCE:STATS|currentConnections=0|lifetimeConnections=4 -REMOTE|earth|100|108|dcatcolors.txt|INFO|20211015-054039|1|stats.go:53|8|11|7|0.87|781h29m17s|MAPREDUCE:STATS|lifetimeConnections=4|currentConnections=0 -REMOTE|earth|100|109|dcatcolors.txt|INFO|20211015-054049|1|stats.go:53|8|11|7|0.73|781h29m27s|MAPREDUCE:STATS|currentConnections=0|lifetimeConnections=4 -REMOTE|earth|100|110|dcatcolors.txt|INFO|20211015-054059|1|stats.go:53|8|11|7|0.70|781h29m37s|MAPREDUCE:STATS|currentConnections=0|lifetimeConnections=4 -R