Keep run logs opaque and streamline transfers
This commit is contained in:
@@ -22,6 +22,7 @@ const (
|
||||
managedProcessOutputPollInterval = 50 * time.Millisecond
|
||||
managedProcessOutputDrainDelay = 750 * time.Millisecond
|
||||
managedProcessOutputRetryDelay = 500 * time.Millisecond
|
||||
managedProcessOutputReaderSize = 64 * 1024
|
||||
)
|
||||
|
||||
type ProcessIdentity struct {
|
||||
@@ -143,7 +144,7 @@ func (supervisor *OSManagedProcessSupervisor) Start(ctx context.Context, command
|
||||
supervisor.mu.Lock()
|
||||
defer supervisor.mu.Unlock()
|
||||
key := identity.Scope
|
||||
log.Printf("RUN phase=process.managed status=start_requested job=%s server=%s scope=%s command=%s workdir=%s", safeOptional(identity.JobID), identity.ServerInstanceID, safeOptional(identity.Scope), redactedCommandLine(command.Args), safeOptional(command.WorkDir))
|
||||
log.Printf("RUN phase=process.managed status=start_requested job=%s server=%s scope=%s command=%s workdir=%s", safeOptional(identity.JobID), identity.ServerInstanceID, safeOptional(identity.Scope), quotedCommandLine(command.Args), safeOptional(command.WorkDir))
|
||||
if existing, ok := supervisor.items[key]; ok && existing.State == "running" && supervisor.isAlive(existing) {
|
||||
if existing.LogSessionID == "" {
|
||||
logSessionID, err := newManagedProcessLogSessionID()
|
||||
@@ -167,7 +168,7 @@ func (supervisor *OSManagedProcessSupervisor) Start(ctx context.Context, command
|
||||
return existing, nil
|
||||
}
|
||||
if err := ctx.Err(); err != nil {
|
||||
log.Printf("RUN phase=process.managed status=context_done job=%s error=%s", safeOptional(identity.JobID), RedactText(err.Error()))
|
||||
log.Printf("RUN phase=process.managed status=context_done job=%s error=%s", safeOptional(identity.JobID), err.Error())
|
||||
return ProcessIdentity{}, err
|
||||
}
|
||||
if len(command.Args) == 0 {
|
||||
@@ -187,14 +188,14 @@ func (supervisor *OSManagedProcessSupervisor) Start(ctx context.Context, command
|
||||
}
|
||||
files, identity, err := supervisor.prepareOutputFilesLocked(identity, startedAt)
|
||||
if err != nil {
|
||||
log.Printf("RUN phase=process.managed status=prepare_output_failed job=%s error=%s", safeOptional(identity.JobID), RedactText(err.Error()))
|
||||
log.Printf("RUN phase=process.managed status=prepare_output_failed job=%s error=%s", safeOptional(identity.JobID), err.Error())
|
||||
return ProcessIdentity{}, err
|
||||
}
|
||||
log.Printf("RUN phase=process.managed status=output_ready job=%s stdoutRef=%s stderrRef=%s", safeOptional(identity.JobID), safeOptional(identity.StdoutLogRef), safeOptional(identity.StderrLogRef))
|
||||
process, err := startManagedProcess(command, files, identity.StopEventName)
|
||||
if err != nil {
|
||||
files.close()
|
||||
log.Printf("RUN phase=process.managed status=start_failed job=%s error=%s", safeOptional(identity.JobID), RedactText(err.Error()))
|
||||
log.Printf("RUN phase=process.managed status=start_failed job=%s error=%s", safeOptional(identity.JobID), err.Error())
|
||||
return ProcessIdentity{}, err
|
||||
}
|
||||
identity.SupervisorPID = process.PID()
|
||||
@@ -214,7 +215,7 @@ func (supervisor *OSManagedProcessSupervisor) Start(ctx context.Context, command
|
||||
} else {
|
||||
delete(supervisor.items, key)
|
||||
}
|
||||
log.Printf("RUN phase=process.managed status=persist_failed job=%s pid=%d error=%s", safeOptional(identity.JobID), identity.PID, RedactText(err.Error()))
|
||||
log.Printf("RUN phase=process.managed status=persist_failed job=%s pid=%d error=%s", safeOptional(identity.JobID), identity.PID, err.Error())
|
||||
return ProcessIdentity{}, err
|
||||
}
|
||||
supervisor.startTailersLocked(identity, output)
|
||||
@@ -241,7 +242,7 @@ func (supervisor *OSManagedProcessSupervisor) Stop(ctx context.Context, identity
|
||||
}
|
||||
log.Printf("RUN phase=process.managed status=stop_requested job=%s pid=%d scope=%s", safeOptional(identity.JobID), current.PID, safeOptional(identity.Scope))
|
||||
if err := requestManagedProcessStop(current); err != nil {
|
||||
log.Printf("RUN phase=process.managed status=stop_signal_failed job=%s pid=%d error=%s", safeOptional(identity.JobID), current.PID, RedactText(err.Error()))
|
||||
log.Printf("RUN phase=process.managed status=stop_signal_failed job=%s pid=%d error=%s", safeOptional(identity.JobID), current.PID, err.Error())
|
||||
}
|
||||
supervisor.mu.Unlock()
|
||||
deadline := time.NewTimer(2 * time.Second)
|
||||
@@ -264,11 +265,11 @@ func (supervisor *OSManagedProcessSupervisor) Stop(ctx context.Context, identity
|
||||
}
|
||||
select {
|
||||
case <-ctx.Done():
|
||||
log.Printf("RUN phase=process.managed status=stop_context_done job=%s pid=%d error=%s", safeOptional(identity.JobID), current.PID, RedactText(ctx.Err().Error()))
|
||||
log.Printf("RUN phase=process.managed status=stop_context_done job=%s pid=%d error=%s", safeOptional(identity.JobID), current.PID, ctx.Err().Error())
|
||||
return ProcessIdentity{}, ctx.Err()
|
||||
case <-deadline.C:
|
||||
if err := forceManagedProcessStop(current); err != nil {
|
||||
log.Printf("RUN phase=process.managed status=forced_stop_signal_failed job=%s pid=%d error=%s", safeOptional(identity.JobID), current.PID, RedactText(err.Error()))
|
||||
log.Printf("RUN phase=process.managed status=forced_stop_signal_failed job=%s pid=%d error=%s", safeOptional(identity.JobID), current.PID, err.Error())
|
||||
}
|
||||
current.State = "stopped"
|
||||
current.ExitClassification = "forced-stop"
|
||||
@@ -404,7 +405,7 @@ func (supervisor *OSManagedProcessSupervisor) wait(key string, process managedPr
|
||||
supervisor.drainTailersAfter(item, managedProcessOutputDrainDelay)
|
||||
}
|
||||
if err != nil {
|
||||
log.Printf("RUN phase=process.managed status=%s job=%s pid=%d state=%s exitCode=%d classification=%s error=%s", processTerminalStatus(item.State), safeOptional(item.JobID), pid, item.State, item.ExitCode, item.ExitClassification, RedactText(err.Error()))
|
||||
log.Printf("RUN phase=process.managed status=%s job=%s pid=%d state=%s exitCode=%d classification=%s error=%s", processTerminalStatus(item.State), safeOptional(item.JobID), pid, item.State, item.ExitCode, item.ExitClassification, err.Error())
|
||||
return
|
||||
}
|
||||
log.Printf("RUN phase=process.managed status=%s job=%s pid=%d state=%s exitCode=%d classification=%s", processTerminalStatus(item.State), safeOptional(item.JobID), pid, item.State, item.ExitCode, item.ExitClassification)
|
||||
@@ -516,31 +517,31 @@ func (supervisor *OSManagedProcessSupervisor) tailOutput(ctx context.Context, ta
|
||||
defer supervisor.removeTailer(tailerID, tailer, identity)
|
||||
file, err := os.Open(path)
|
||||
if err != nil {
|
||||
log.Printf("RUN phase=process.managed.output status=tail_open_failed job=%s pid=%d stream=%s path=%s error=%s", safeOptional(identity.JobID), identity.PID, stream, safeOptional(path), RedactText(err.Error()))
|
||||
log.Printf("RUN phase=process.managed.output status=tail_open_failed job=%s pid=%d stream=%s path=%s error=%s", safeOptional(identity.JobID), identity.PID, stream, safeOptional(path), err.Error())
|
||||
return
|
||||
}
|
||||
defer file.Close()
|
||||
if offset > 0 {
|
||||
if _, err := file.Seek(offset, io.SeekStart); err != nil {
|
||||
log.Printf("RUN phase=process.managed.output status=tail_seek_failed job=%s pid=%d stream=%s path=%s offset=%d error=%s", safeOptional(identity.JobID), identity.PID, stream, safeOptional(path), offset, RedactText(err.Error()))
|
||||
log.Printf("RUN phase=process.managed.output status=tail_seek_failed job=%s pid=%d stream=%s path=%s offset=%d error=%s", safeOptional(identity.JobID), identity.PID, stream, safeOptional(path), offset, err.Error())
|
||||
return
|
||||
}
|
||||
}
|
||||
reader := bufio.NewReader(file)
|
||||
reader := bufio.NewReaderSize(file, managedProcessOutputReaderSize)
|
||||
defer func() {
|
||||
log.Printf("RUN phase=process.managed.output status=tail_stop job=%s pid=%d stream=%s offset=%d", safeOptional(identity.JobID), identity.PID, stream, offset)
|
||||
}()
|
||||
for {
|
||||
line, err := reader.ReadString('\n')
|
||||
line, err := reader.ReadSlice('\n')
|
||||
if len(line) > 0 {
|
||||
startOffset := offset
|
||||
endOffset := offset + int64(len(line))
|
||||
text := strings.TrimSuffix(line, "\n")
|
||||
text := strings.TrimSuffix(string(line), "\n")
|
||||
for {
|
||||
if sinkErr := sink(identity, ManagedProcessLine{Text: text, StartOffset: startOffset, EndOffset: endOffset}); sinkErr == nil {
|
||||
break
|
||||
} else {
|
||||
log.Printf("RUN phase=process.managed.output status=sink_retry job=%s pid=%d stream=%s error=%s", safeOptional(identity.JobID), identity.PID, stream, RedactText(sinkErr.Error()))
|
||||
log.Printf("RUN phase=process.managed.output status=sink_retry job=%s pid=%d stream=%s error=%s", safeOptional(identity.JobID), identity.PID, stream, sinkErr.Error())
|
||||
}
|
||||
select {
|
||||
case <-ctx.Done():
|
||||
@@ -552,7 +553,7 @@ func (supervisor *OSManagedProcessSupervisor) tailOutput(ctx context.Context, ta
|
||||
if offsetErr := supervisor.updateOutputOffset(identity, stream, endOffset); offsetErr == nil {
|
||||
break
|
||||
} else {
|
||||
log.Printf("RUN phase=process.managed.output status=offset_retry job=%s pid=%d stream=%s error=%s", safeOptional(identity.JobID), identity.PID, stream, RedactText(offsetErr.Error()))
|
||||
log.Printf("RUN phase=process.managed.output status=offset_retry job=%s pid=%d stream=%s error=%s", safeOptional(identity.JobID), identity.PID, stream, offsetErr.Error())
|
||||
}
|
||||
select {
|
||||
case <-ctx.Done():
|
||||
@@ -565,6 +566,9 @@ func (supervisor *OSManagedProcessSupervisor) tailOutput(ctx context.Context, ta
|
||||
if err == nil {
|
||||
continue
|
||||
}
|
||||
if err == bufio.ErrBufferFull {
|
||||
continue
|
||||
}
|
||||
if err != io.EOF {
|
||||
return
|
||||
}
|
||||
@@ -589,7 +593,7 @@ func (supervisor *OSManagedProcessSupervisor) removeTailer(tailerID string, tail
|
||||
delete(supervisor.retired, key)
|
||||
if err := supervisor.persistLocked(); err != nil {
|
||||
supervisor.retired[key] = retired
|
||||
log.Printf("RUN phase=process.managed.output status=retired_prune_failed job=%s pid=%d error=%s", safeOptional(identity.JobID), identity.PID, RedactText(err.Error()))
|
||||
log.Printf("RUN phase=process.managed.output status=retired_prune_failed job=%s pid=%d error=%s", safeOptional(identity.JobID), identity.PID, err.Error())
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user