Skip to content

Make a corrupt script log diagnosable - #1278

Draft
akirayamamoto wants to merge 7 commits into
OctopusDeploy:mainfrom
akirayamamoto:akirayamamoto/report-script-log-corruption
Draft

Make a corrupt script log diagnosable#1278
akirayamamoto wants to merge 7 commits into
OctopusDeploy:mainfrom
akirayamamoto:akirayamamoto/report-script-log-corruption

Conversation

@akirayamamoto

@akirayamamoto akirayamamoto commented Aug 4, 2026 •
edited
Loading

Copy link
Copy Markdown

Background

The Tentacle nightly failed with an unhandled JsonReaderException out of ScriptLog.GetOutput. The real failure was one test in Integration Test: net8.0 on Windows 2012 R2 #9.2.4244-main-nightly; the chain build just relayed it. That test has passed 39 of its last 40 runs, so this is a flake, not a regression.

I could not work out why the log was corrupt. The test deletes its workspace at the end of the method and nothing prints that file anywhere, so there was nothing left by the time I looked.

So this PR adds the diagnostics we were missing. Next time it happens there should be enough to go on.

Results

  • When the log cannot be parsed, the error now says how big it was and whether a write arrived after it closed. Before it just quoted the JSON token that tripped the parser, which told you nothing about how the log got that way. This is the only change a user sees.
  • A failing integration test prints the script log into the build output. Nothing printed it before, and the workspace was gone by teardown.
  • Closing the log takes the same lock as every write. It could previously close midway through a write and leave half an entry on disk.
  • Writes arriving after the log closed are refused rather than attempted, so they cannot leave a partial entry either.
  • Failed writes get logged. The try/catch was around the wrong code, so this had been failing silently.
  • Abandoning a script logs whether its task finished and what state it was in, which tells us if a live writer was left on the log.

A corrupt log still fails the step, exactly as it does today. The behaviour is unchanged.

Before

The parse error, with nothing to explain it:

Newtonsoft.Json.JsonReaderException : JsonToken EndArray is not valid for closing JsonType None. Path '', line 1, position 1450.
   at Newtonsoft.Json.JsonReader.ValidateEnd(JsonToken endToken)
   at Octopus.Tentacle.Core.Services.Scripts.Logging.ScriptLog.GetOutput(Int64 afterSequenceNumber, Int64& nextSequenceNumber)

After

Same failure, now saying what state the log was in:

Could not parse the script log. It is 56 bytes, and a write was refused after it closed. Parser reported: JsonToken EndArray is not valid for closing JsonType None. Path '', line 1, position 53.

And from a real build, forced to fail on a Linux agent to check this reaches the build output:

Abandoning the script for task 1312161c...; its task had not finished, status WaitingForActivation
Could not write script output to log, for task 1312161c.... This script's log is closed, so any
further output it produces will be discarded.
System.ObjectDisposedException: The script log writer has been disposed...
### SCRIPT LOG .../script-logs/0-1419/l8MFdaAcskqTMUz3sjNxaw.log (832 bytes) ###
["stdout","##octopus[stdout-verbose]","2026-08-04T08:28:09.2980966+00:00"]["stdout","Acquiring isolation mutex RunningScript with FullIsolation in 1312161c...","2026-08-04T08:28:09.2987699+00:00"]...
### END SCRIPT LOG ###

That middle warning is the interesting one. It fired on a real agent, so the abandoned script really does try to write after its log has closed. That was silent before this.

How to review this PR

The claim worth checking is that behaviour does not change. ShouldHandleIncompleteLine is the guard for it. I did not touch the existing corrupt-log handling, so that test still asserts the same message it always did.

Two production changes to think about: Writer.Dispose now takes the lock, and writes after the log closes are refused. The rest is log lines and test code.

ScriptLog is shared by net48 and net8.0. I could only run net8.0 locally, so the net48 side rests on the build.

Follow ups

Right now the log is only text in the build output. Copying it into artifacts/trace-logs would publish it as a proper artifact, since these configs already have a rule for that path. Needs a build to prove it works, so not in this PR.

@akirayamamoto
Close the script log under the lock
0dd26c0 
Every other member of the writer takes the lock before touching the file, but
Dispose did not, so closing could interleave with a write in progress and flush a
partial entry. Writes after disposal are now refused outright rather than
attempted against a closed stream, which is what keeps a half-written entry out
of the log.

The writer takes its owning ScriptLog rather than four separate dependencies,
which is what lets disposal share the same lock.
@akirayamamoto
Warn when script output can no longer be recorded
2e3d959 
The handler meant to report a failed write wrapped the construction of the output
delegate rather than its body, so it could never run. A write that failed was
therefore lost in silence: the process runner catches it, tries to report it
through the same dead writer, and swallows that too.

Only a disposed log is handled, so any other write failure keeps propagating as
before, and the warning fires once per script rather than once per line.

Abandoning a script now also records whether its task was still running, since
that decides whether the log had a live writer left on it. It is logged at the
same level as the timeout it follows, so it cannot be filtered out separately.
@akirayamamoto
Report the state of the script log when it cannot be parsed
2915590 
A parse failure previously surfaced as a bare complaint about a JSON token, which
says nothing about how the log reached that state. It now carries the log's size,
how many writers were open, the highest number open at once, and whether a write
was refused after the log closed.

The peak matters more than the current count: corruption is only noticed during a
read, by which point the writer responsible has usually been disposed. The same
exception type is rethrown, so nothing keying on it changes, and the original is
kept as the inner exception.
@akirayamamoto
Preserve script logs when an integration test fails
fd2b2fd 
A corrupt script log is unrecoverable after the fact: the workspace lives in a
temporary directory disposed at the end of the test method, so nothing survives
for teardown to collect. Copying happens there instead, unconditionally, and
teardown decides whether to keep it.

The split is necessary rather than tidy. An unhandled exception has not been
recorded while the test body is still unwinding, so the outcome reads as
inconclusive at that point. Assertion failures are recorded eagerly and would look
fine, which is how a single-phase version passes while missing the case this
exists for.
@akirayamamoto
Address review: drop an unreachable signal and two unusable paths
5fdb1b1 
The peak concurrent-writer count could never exceed one. Both writers are created
sequentially, and the log is opened with a share mode that stops a second writer
opening it at all, so the number was noise and the test proving it could only pass
on platforms that do not enforce sharing.

Reporting the log's size is now best-effort. The workspace is deleted once a script
completes, so a read racing that deletion would have thrown while reporting the
parse failure it was called for, losing the diagnostic entirely.

The artifact service message could not reach TeamCity: test output is captured and
re-emitted escaped, and the path sat outside the checkout. The inline dump already
carries the log.

Abandoning a script reports the task's status rather than whether it finished, so a
task that faulted is not reported as simply done.
This was referenced Aug 4, 2026
Closed
Closed
@akirayamamoto
Report both whether the abandoned task finished and its status
f4d44df 
Status alone reads as never-started when the task is really in flight, which is
the opposite of what the line is there to tell us. IsCompleted alone reports a
faulted task as simply finished.
@akirayamamoto akirayamamoto changed the title Capture the script log when it fails to parse Make a corrupt script log diagnosable Aug 5, 2026
@akirayamamoto
Check the log size before inlining it rather than truncating after
44b0813 
The previous read allocated a fixed 256K character buffer on every call to hold a
log measured in hundreds of bytes, then truncated. Checking the size first never
reads a large file at all, and says why it skipped instead of cutting mid-log.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

No reviews

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

1 participant

@akirayamamoto