FreeAndNil commented on PR #323:
URL: https://github.com/apache/logging-log4net/pull/323#issuecomment-6121926943
Implementation plan for #323, kept here for the record. Revised after the
merge so that it describes the change as it landed, including the review rounds.
<details>
<summary>Plan</summary>
# PR #323: the event and context cluster
## Context
Four findings of the 2026-08-29 scan in the event and context subsystem, to
land as PR #323 on
top of `Feature/322-reconfiguration-file-lock` (that branch already carries
every #319 commit).
Checked against the published documents on `logging-site` `main` at
`67d4ea65`, tree clean:
- **f021 is out of scope.** `_threat-model-common.adoc` "Destination
integrity
(operator-controlled)" makes a path interpolated from a lookup the
operator's decision, and
`security/faq.adoc` "Problematic contexts" names the
context-lookup-into-a-path case and closes
with "It is the user's responsibility to ensure that the sources of any
interpolated values used
in file paths are trustworthy". The sentence `tmd-2` calls factually wrong
lives in the scan's own
`THREAT_MODEL.md`; the published model never mentions `PatternString`.
- **f006, f039, f044 need no adversary at all**, so under "Adversary
capabilities" none is a
vulnerability. The whole cluster is reliability work: no security language
anywhere, finding ids
cited as provenance only.
Two of the four get code, two get prose, and the f044 fix frees a public
delegate, which gets a
deprecation of its own. Five commits.
## f021: context values in a PatternString-typed config value
No code change. `PropertyPatternConverter.Convert` reads the ambient context
of the configuring
thread and `PatternStringConverter.ConvertTo` expands it once at config-bind
time
(`XmlHierarchyConfigurator.SetParameter:711-715`), which is exactly the
operator decision the model
puts on the deployer. The scan's patch sanitizes `/`, `\`, `:` and `..`
inside the converter behind
a process-wide static: content mangling in a converter, against the
sink-owns-escaping rule.
1. `src/log4net/Util/PatternStringConverters/PropertyPatternConverter.cs`,
above the
`CompositeProperties` build in `Convert` (:64): two lines saying context
values may hold
user-supplied data, so a path built from `%property` is the operator's
choice, linking
`https://logging.apache.org/security/faq.html#path-traversal`. That FAQ
entry is the one that
settles the finding and links to the model itself, so the model URL is
not repeated: two links
on a two line comment is more pointer than point.
2. `src/site/antora/modules/ROOT/pages/manual/faq.adoc`, the
`#dynamic-patterns` entry (:180-195):
one sentence that `%property` expands context values, which may carry
user-supplied data, so a
path built from one is only as trustworthy as that value, with the same
FAQ link.
3. No changelog entry (comment and docs only).
## f006: buffered events reach another request's trace
No code change. `AspNetTraceAppender.Append`
(`src/log4net/Appender/AspNetTraceAppender.cs:60-78`)
resolves `HttpContext.Current` on the calling thread, and
`BufferingAppenderSkeleton` delivers the
whole buffer synchronously on whichever thread triggers the flush
(`BufferingForwardingAppender.SendBuffer:77-84`). A `LoggingEvent` carries
no request handle, so
nothing at the sink can tell the events apart. The scan's timestamp guard
drops any event older than
`HttpContext.Current.Timestamp`, which trades the mix-up for event loss and
still admits a later
concurrent request.
1. Class remarks on `AspNetTraceAppender` (:44-54), one sentence as its own
`<para>`: writes to the
request current on the appending thread, so it must not be wrapped in a
buffering appender.
2.
`src/site/antora/modules/ROOT/pages/manual/configuration/appenders.adoc:48`,
the same sentence
as a second paragraph in the existing cell. A blank line inside a cell
opens a paragraph, a
cell ends only at the next `|` at the start of a line, so the table keeps
its 3 tables and 30
rows; render it with the Asciidoctor in `node_modules` if a reviewer
doubts it.
3. No Windows round is needed, because nothing behavioural changes. The file
is
`#if NET462_OR_GREATER`, so still compile-check it with
`dotnet build src/log4net.Tests/log4net.Tests.csproj -f net462
-p:TargetFrameworks=net462`.
4. No changelog entry.
## f044: AutoPopStackFrame.Dispose resurrects captured frames
Real defect, and the deterministic case needs no misuse:
`LogicalThreadContext.Stacks[x].Clear()`
registers a fresh empty stack (`LogicalThreadContextStack.cs:96`), then
disposing a frame pushed
before the `Clear` re-registers the pre-`Clear` snapshot, because `Dispose`
(:314-329) rebuilds from
`_logicalThreadContextStack._stack` captured at `Push` time and never looks
at what is registered
now.
1. **Reproduce first**, in
`src/log4net.Tests/Context/LogicalThreadContextTest.cs`:
`DisposingAFrameAfterClearKeepsTheStackEmpty`, push two frames,
`Clear()`, dispose the inner
frame, assert `Count` is 0. Watch it fail.
2. Give the stack its owner instead of a callback.
`LogicalThreadContextStack` holds a
`LogicalThreadContextStacks _owner` in place of the `TwoArgAction`
`_registerNew` field, the
internal constructor takes the owner, and `LogicalThreadContextStacks`
gets two internal
members: `RegisterNew(string, LogicalThreadContextStack)`, the former
private method, and
`GetCurrent(string)`, which returns `_properties[name] as
LogicalThreadContextStack`, so a
foreign value under the key reads as null. `Clear`, `Pop` and `Push` call
`_owner.RegisterNew`.
3. Fix `Dispose`: return when `_frameDepth` is negative; read the stack
registered now through
`owner.GetCurrent(propertyKey)` and return when it is null or its count
is already at or below
`_frameDepth`; otherwise copy it, pop down to `_frameDepth` and register
the trimmed copy. Trim
only, never grow, so a stale snapshot can no longer be injected, and a
non-stack value under the
key is left alone rather than overwritten.
4. Further tests in the same fixture, assertions outside any task body:
`DisposingAFrameAfterPoppingBelowItKeepsTheStackEmpty` (two pops, then
dispose the inner
frame), `DisposingAFrameTrimsTheStackToItsDepth` (the nested happy path,
which passes before
and after the fix and is the guard that the trim still happens), and
`DisposingAFrameInAnotherFlowDoesNotResurrectIt`, where a `Task.Run`
clears, disposes and
returns the count it saw, asserted as 0 outside, with the outer flow
still at 2 as the flow
isolation guard. The fixture's `[TearDown]` removes the property from
every context, so the
frames the tests leave pushed do not leak.
5. Residual to state in the commit message, not the source: disposing a
foreign flow's frame while
the current flow holds a deeper stack still trims the current flow. That
is context loss, never
context injection, and it is the trade the trim-only rule buys.
6. Measure before and after, 1M operations, best of five, Release on
net10.0: push and dispose at
depth 1 and depth 3 (expected the same within noise, same bytes), dispose
after `Clear`
(expected faster and smaller, since it no longer rebuilds the snapshot).
Table into the commit
message and the PR body.
7. Changelog `src/changelog/3.5.0/323-logical-stack-dispose.xml`,
`type="fixed"`, closing
`(audit da18b6fd-f044, fixed by @FreeAndNil)`.
## TwoArgAction: deprecate the delegate the owner reference replaces
After step 2 above nothing in the tree uses `log4net.Util.TwoArgAction<T1,
T2>`. It is public, so
it stays until version 4.
1. Own commit `deprecate TwoArgAction #323`: summary reduced to what it is,
"Delegate type for an
action taking two arguments", and `[Obsolete("No longer used by log4net
and removed in
version 4.")]`. The solution still builds with 0 warnings, since no call
site remains.
2. Changelog `323-deprecate-twoargaction.xml`, `type="changed"`, closing
`(implemented by @FreeAndNil)`.
## f039: the event cache unlocks on a redundant Fix
`FixVolatileData` (`src/log4net/Core/LoggingEvent.cs:1138-1225`) sets
`_cacheUpdatable = true` at
:1143 unconditionally, while the fixing work is guarded by `updateFlags > 0`
at :1147 and the
re-lock at :1224 is unconditional. `_cacheUpdatable` is a plain `bool`
(:1451) and every lazy getter
gates on `field is null && _cacheUpdatable` (Identity :902, ThreadName :655,
LocationInfo :483,
Domain :947). A redundant `Fix` therefore reopens capture for a concurrent
reader.
**The first deliverable is a measurement, not a patch**, and it fires.
1. Scratch harness, not a committed test: one thread setting `Fix =
FixFlags.Partial` on an
already-fixed event in a loop, another reading `Identity`, which
`Partial` does not cover.
Expect a non-null `Identity` after 56000 to 63000 calls, five runs of
five, and none in
2000000 once the patch is in. Both numbers go into the commit message and
the PR body.
2. Patch: move `_cacheUpdatable = true` inside the `if (updateFlags > 0)`
block with a one line
comment, and make the field `volatile`. The late `UserName` capture at
:1215-1221 writes
`_data.UserName` directly and does not pass a gated getter, so it is
unaffected; the
unconditional re-lock at the end stays, so a `Fix` with nothing to do
still ends locked.
`UserNameFixingTest` and `FixingTest` stay green.
3. Hammer test `ARedundantFixDoesNotLetAnotherThreadCacheItsIdentity` in
`src/log4net.Tests/Core/FixingTest.cs`: fix the event `Partial`, start a
background reader that
sets its own `GenericPrincipal`, signals a `TaskCompletionSource<bool>`
once running and spins
on `Identity is null` counting its passes; wait on the gate, assign `Fix
= FixFlags.Partial`
500000 times, stop the reader, join with a timeout, then assert the pass
count is greater than
zero and `Identity` is null. The gate is a `TaskCompletionSource<bool>`
and not a
`ManualResetEventSlim`: a timed out `Wait` would dispose the event and a
late reader would then
`Set` a disposed object, which takes the test host down on a background
thread. The spin stays
without a yield, since the reader has to read as often as possible to see
a hit once per 60000
calls; the whole test takes about 34 ms. Mutation-verify in both
directions: the reverted fix
fails the identity assertion, a reader that exits at once fails the pass
count assertion.
4. Changelog `323-logging-event-fix-cache.xml`, `type="fixed"`, closing
`(audit da18b6fd-f039, fixed by @FreeAndNil)`.
## House rules that bite here
- No test method underscores, no `BugFNNN` fixture names: the new tests go
into the existing
`LogicalThreadContextTest` and `FixingTest` fixtures, each with a doc
comment.
- NUnit 4 constraint model, expression bodies for single-statement tests,
generous timeouts on any
gate. The test assembly declares no parallelism, so `[NonParallelizable]`
adds nothing here.
- Every `<issue>` needs `id` and `link`; the description is prose only and
does not repeat the pull
request link.
- Stage only. Commit messages go to `.git/plans/323/`, one file per commit,
the maintainer commits
and signs.
## Verification
```
dotnet build src/log4net.sln # 0 warnings, both TFMs
dotnet build src/log4net.Tests/log4net.Tests.csproj -f net462
-p:TargetFrameworks=net462
dotnet test src/log4net.Tests/log4net.Tests.csproj -f net10.0
dotnet test src/log4net.Ext.Mail.Tests/log4net.Ext.Mail.Tests.csproj
```
Redirect build output to a file and read the whole file. With both
production changes reverted,
four of the five new tests fail and `DisposingAFrameTrimsTheStackToItsDepth`
passes, as the happy
path guard it is. Restore before reporting anything green.
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
