diff --git a/.github/workflows/git-broadcast.yml b/.github/workflows/git-broadcast.yml deleted file mode 100644 index 513b8c11d..000000000 --- a/.github/workflows/git-broadcast.yml +++ /dev/null @@ -1,44 +0,0 @@ -# -# Licensed to the Apache Software Foundation (ASF) under one or more -# contributor license agreements. See the NOTICE file distributed with -# this work for additional information regarding copyright ownership. -# The ASF licenses this file to you under the Apache License, Version 2.0 -# (the "License"); you may not use this file except in compliance with -# the License. You may obtain a copy of the License at -# -# http://www.apache.org/licenses/LICENSE-2.0 -# -# Unless required by applicable law or agreed to in writing, software -# distributed under the License is distributed on an "AS IS" BASIS, -# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -# See the License for the specific language governing permissions and -# limitations under the License. -# -name: Broadcast master updates to satellites - -on: - workflow_dispatch: -# Temporarily disabled, uncomment if needed. -# push: -# branches: [ master ] -# pull_request: -# branches: [ master ] - -concurrency: - group: git-broadcast - -jobs: - main: - runs-on: ubuntu-latest - steps: - - uses: actions/checkout@v2 - - uses: actions/setup-node@v2-beta - with: - node-version: '16' - - name: broadcast master changes to satellite branches - env: - RUN_NUMBER: ${{ github.run_number }} - run: | - git config --global user.name "Git Broadcast" - git config --global user.email "git-broadcast@no-reply.com" - npx git-broadcast@beta --ignore abandoned-develop --from master --push --pretty --suppress-log-prefixes --prefix-logs-with $GITHUB_REPOSITORY diff --git a/.mvn/wrapper/maven-wrapper.properties b/.mvn/wrapper/maven-wrapper.properties index 08ea486aa..09c1213c4 100644 --- a/.mvn/wrapper/maven-wrapper.properties +++ b/.mvn/wrapper/maven-wrapper.properties @@ -16,3 +16,10 @@ # under the License. distributionUrl=https://repo.maven.apache.org/maven2/org/apache/maven/apache-maven/3.9.0/apache-maven-3.9.0-bin.zip wrapperUrl=https://repo.maven.apache.org/maven2/org/apache/maven/wrapper/maven-wrapper/3.2.0/maven-wrapper-3.2.0.jar +# mvnw and MavenWrapperDownloader refuse to run when a download does not match these. +# distributionSha256Sum is of apache-maven-3.9.0-bin.zip as published on archive.apache.org, whose +# PGP signature verifies against https://downloads.apache.org/maven/KEYS and whose bytes are +# identical to the Maven Central copy above. wrapperSha256Sum is of the maven-wrapper.jar committed +# next to this file, which is identical to the published maven-wrapper-3.2.0.jar. +distributionSha256Sum=68e5a1745a5f5e4b0dfae051f83297e2ea40912b2c3b84d3b7420f463f39260d +wrapperSha256Sum=e63a53cfb9c4d291ebe3c2b0edacb7622bbc480326beaa5a0456e412f52f066a diff --git a/AGENTS.md b/AGENTS.md index 97ef271b6..d6f9eec5b 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -10,7 +10,7 @@ This is mandatory: skipping steps leads to duplicate reports and wasted time for ### Step 1: Read the security model Fetch and read the project's security model before evaluating any finding: -https://raw.githubusercontent.com/apache/logging-site/refs/heads/main-site-pro/src/site/antora/modules/ROOT/pages/_threat-model-common.adoc +https://raw.githubusercontent.com/apache/logging-site/refs/heads/main/src/site/antora/modules/ROOT/pages/_threat-model-common.adoc Use this to answer: - Is this component/behavior in scope at all? @@ -18,6 +18,21 @@ Use this to answer: If the finding is out of scope per the model, **stop here** and inform the researcher. +Two rules from the model account for most of what gets reported wrongly. Read the model itself +rather than relying on this summary, but know them before you start: + +- **Configuration is operator-supplied and trusted**, including configuration URIs and the types, + members and converters that configuration names. A finding that needs the attacker to control + configuration, a watched configuration file, or the format string of a log statement is out of + scope: that is application misuse. Protecting those resources, and transmitting them over a + confidential channel, is a deployer responsibility the model states explicitly. +- **Content is untrusted and must never be rejected**, because rejecting it would turn a malicious + value into a denial of service, so it has to be escaped or sanitized instead. Structural + identifiers, such as logger names or the identifier fields of a structured log message, are + trusted, and there the model allows *rejecting* a malformed value rather than silently altering + it. Getting these two the wrong way round produces a plausible-looking report that proposes + exactly the wrong fix. + ### Step 2: Check previously disclosed vulnerabilities Read the project's Vulnerability Disclosure Report to check for duplicates: @@ -29,7 +44,7 @@ If it overlaps with a known issue, **stop here**, link to the existing advisory ### Step 3: Read the Security FAQ Read the Security FAQ before concluding anything is a vulnerability: -https://raw.githubusercontent.com/apache/logging-site/refs/heads/main-site-pro/src/site/antora/modules/ROOT/pages/security/faq.adoc +https://raw.githubusercontent.com/apache/logging-site/refs/heads/main/src/site/antora/modules/ROOT/pages/security/faq.adoc The FAQ lists behaviors that are **intentional and not vulnerabilities**. If the finding matches an FAQ entry, inform the researcher that it is a known non-issue @@ -52,6 +67,11 @@ Assess the finding: ## Report quality rules +- **Only call something a vulnerability when it really is one.** Name the adversary, then check that + capability against the model. If it needs a misconfiguration, a co-resident local user, or + anything the model does not grant, it is a correctness bug, a reliability defect or hardening, and + saying so is more useful than a severity. Do not inherit the framing of a scanner report that + arrived with severities already attached. - Never speculate about impact beyond what you can demonstrate. - Reproduction steps must be minimal and self-contained. - Do not include unrelated findings in the same report: one issue per report. diff --git a/CLAUDE.md b/CLAUDE.md index 94d7f4639..1aa100c90 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -26,33 +26,33 @@ almost always be doing. (238 of 244 files in `src/log4net`). Copy it verbatim into new files. - File-scoped namespaces (`namespace log4net.Appender;`). Note `.editorconfig` still says `csharp_style_namespace_declarations = block_scoped:silent`, but 242 of 244 files are - file-scoped — follow the code, not that setting. + file-scoped: follow the code, not that setting. - `using` directives outside the namespace, in one contiguous block. ### Language usage -- **Explicit types, not `var`** — all three `csharp_style_var_*` options are `false`. +- **Explicit types, not `var`**: all three `csharp_style_var_*` options are `false`. Write `StringWriter writer = new(...)`. - Target-typed `new()` and collection expressions (`private static readonly char[] _x = [',', ';'];`). - Omit the type wherever the target is known — including `return new(…);` and `=> new(…);`, where + Omit the type wherever the target is known, including `return new(…);` and `=> new(…);`, where the enclosing member's return type supplies it. It cannot be omitted when the target type is an interface or abstract class, as in `Func f = () => new MailKitSmtpTransport();`. -- Expression-bodied members whenever the body fits on one line — this includes constructors +- Expression-bodied members whenever the body fits on one line, including constructors (`resharper_constructor_or_destructor_body = expression_body`). - Braces on `if`/`else` bodies even for a single statement. - `LangVersion` is `latest`, and current C# features are welcome and in use: primary constructors (`csharp_style_prefer_primary_constructors = true`), the `field` keyword in property accessors, list patterns, `switch` expressions. - **Wrap long string literals with a multi-line raw string (`"""`), never with `+` - concatenation.** This includes attribute arguments — see the `[Obsolete(...)]` message on + concatenation.** This includes attribute arguments; see the `[Obsolete(...)]` message on `log4net.Appender.SmtpAppender`. Raw strings have no line-continuation, so each source line break really is a `\n` in the value, but that is fine here: compiler diagnostics render those newlines as spaces, so a wrapped message still reads as one sentence. Raw strings are constant - expressions, so they are legal in attributes, and the feature is purely syntactic — it works on + expressions, so they are legal in attributes, and the feature is purely syntactic, so it works on `net462`/`netstandard2.0` too. - Private fields are `_camelCase`. Private fields and helper methods are commonly placed *after* the public surface of the type rather than at the top. -### Nullability — the big constraint +### Nullability, the big constraint - `Nullable` is enabled solution-wide with `WarningsAsErrors=nullable`: **any nullability warning is a build error**, so it cannot be deferred. - `log4net` targets `net462;netstandard2.0`. **Neither reference assembly is nullable-annotated**, @@ -68,7 +68,7 @@ almost always be doing. - Use the internal `log4net.Util.Log4NetAssert` extensions rather than hand-rolled checks: `EnsureNotNull()`, `EnsureNotNullOrEmpty()`, `EnsureIs()`. They carry `[CallerArgumentExpression(nameof(value))]`, so no argument name is passed at the call site. - This includes constructor and property assignments — write `_x = x.EnsureNotNull();`, + This includes constructor and property assignments: write `_x = x.EnsureNotNull();`, not `_x = x ?? throw new ArgumentNullException(nameof(x));`. - Appenders never let exceptions escape to the caller. The house pattern is `catch (Exception e) when (!e.IsFatal()) { ErrorHandler.Error("...", e); }`. @@ -83,13 +83,44 @@ almost always be doing. requires linking `NotNullAttribute`, `ValidatedNotNullAttribute` and `CallerArgumentExpressionAttribute`, or you get `CS0122`. - Analyzers (`Microsoft.CodeAnalysis.NetAnalyzers`, `AnalysisLevel 8`, `src/log4net.globalconfig`) - run on every build. **The solution builds with 0 warnings — keep it that way.** + run on every build. **The solution builds with 0 warnings, keep it that way.** + +### Documentation comments +- **Every public and protected member gets an XML doc comment**, in test code as well as production + code: test methods, nested helper classes and hand-written fakes included. +- Use `/// ` when the member implements an interface or overrides a base member, and a + real `` for everything else. `Log4NetTransaction` in the AdoNet test doubles is the + pattern to copy. +- When checking whether a member is documented, remember that `[Test]`, `#pragma` and + `// ReSharper disable` lines legitimately sit between the doc comment and the declaration. + +### Writing, in code and everywhere else +- **Never use an em dash (`—`) or en dash (`–`).** Use a plain hyphen, or restructure with a colon, + comma or parentheses. This covers comments, XML docs, commit messages, AsciiDoc and chat. +- In AsciiDoc, ` -- ` is also forbidden: Asciidoctor renders a spaced double hyphen as an em dash, + so it breaks the rule even though the source looks like plain hyphens. Grep touched files for + `[—–]` and ` -- ` before presenting a change. +- No underscores in identifiers, including test method names. `AllContainsEveryFlag`, not + `All_ShouldContainAllFlags`. (Private fields are `_camelCase`, which is the one exception.) ### Tests - NUnit 4, not MSTest, and always the constraint model: `Assert.That(actual, Is.EqualTo(expected))` (810 uses of `Assert.That`, zero of `Assert.AreEqual`). `[TestFixture]`, `[Test]`, `[TestCase]`, with `[SetUp]`/`[TearDown]` for per-test state. -- `NUnit.Analyzers` warnings are errors too — e.g. NUnit1032 requires an `IDisposable` fixture +- Use an expression body for a single-statement test: `public void X() => Assert.That(...);`. +- **`log4net` has no `InternalsVisibleTo`**, so private and internal members are exercised through + reflection, not by widening their accessibility. See `SystemInfoTest`, `LevelMappingTest` and + `UserNameFixingTest` for the `BindingFlags.Static | BindingFlags.NonPublic` pattern. + `log4net.Ext.Mail` does grant `InternalsVisibleTo` to its own test project. +- Mark a test `[NonParallelizable]` when it mutates static state (`LogLog.InternalDebugging`, a + static field on a test double, a process-wide native registration). +- Wrap expected internal logging in `LogLog.ExecuteWithoutEmittingInternalMessages(...)` and capture + it with `LogLog.LogReceivedAdapter` rather than letting it reach the console. Appender errors are + emitted by default, so a test that provokes one will otherwise add noise to the suite output. +- Guard platform-specific tests with `[Platform("Win")]` / `[Platform("Linux")]`. A test that only + runs on Windows leaves the behaviour unverified in local Linux runs, so prefer a cross-platform + home for the assertion when one exists. +- `NUnit.Analyzers` warnings are errors too: for example NUnit1032 requires an `IDisposable` fixture field to be disposed in a `[TearDown]` method. - For code that talks to the outside world, introduce a narrow interface and hand-write a fake; there is no mocking library in any test project. See `ISmtpTransport` / `FakeSmtpTransport`. @@ -97,6 +128,45 @@ almost always be doing. `dotnet test src/.Tests/.Tests.csproj`. - **When inspecting build output, redirect it to a file and read the whole thing; do not pipe MSBuild through line-oriented tools.** `grep`/`Select-String` cannot match across newlines, and - MSBuild's console logger formats differently when piped than when redirected — a multi-line + MSBuild's console logger formats differently when piped than when redirected, so a multi-line diagnostic message then looks truncated when it is not. Before reporting that the toolchain mangles something, re-check with `dotnet build … > out.txt 2>&1` and inspect `out.txt`. + +## Changelog + +Every user-visible change gets an entry in `src/changelog//`, named +`-.xml`. The format is the log4j changelog schema: + +- `type` is one of `added`, `changed`, `fixed`, `removed`, `updated`. +- **Every `` element requires both `id` and `link`**; the export fails with + `missing attribute: link` otherwise, which is only caught by the Maven site build. +- Put anything that has no issue number, such as an external finding identifier, in the description + text rather than inventing an `` for it. +- `src/changelog/3.3.2/298-fix-interprocesslock-mutex-leak.xml` shows the shape for a change that + came out of an external audit. + +## Documentation site + +The manual lives in `src/site/antora/modules/ROOT/pages/`. A new appender page needs three edits, +not one: the page itself, an `xref` line in `nav.adoc` (kept alphabetical), and the appender table +in `manual/configuration/appenders.adoc`. + +## Security findings + +**[AGENTS.md](AGENTS.md) decides whether something is in scope and whether it is a vulnerability.** +Read it before triaging a report, and describe a finding in commit messages and changelog entries +the way it comes out of that assessment: a correctness bug, a reliability defect or hardening is +none the worse for being called one. + +What that leaves for this file is where the answers live in the code: + +- When a report is likely to recur on a path the threat model already settles, leave a short comment + at the site with a link to the model rather than changing the code. `XmlConfigurator` and + `XmlHierarchyConfigurator` carry these for the configuration-is-trusted paths, and + `SystemStringFormat` for the format string. +- `LocalSyslogAppender.EscapeNulCharacters` and `RemoteSyslogAppender.ValidateIdentity` are the two + sides of the content and structural-identifier rule: content is escaped and never rejected, a + malformed identifier is reported rather than quietly repaired. +- Deliberate secure-default choices belong in the changelog with their opt-out named, so that an + upgrade surprise is searchable. See the entries for `SendTimeoutMillis`, `MatchTimeoutMillis` and + `LockTimeoutMillis`. diff --git a/scripts/verify-release.ps1 b/scripts/verify-release.ps1 index f99e4276e..46e0ca02d 100644 --- a/scripts/verify-release.ps1 +++ b/scripts/verify-release.ps1 @@ -5,52 +5,82 @@ Param ( Set-StrictMode -Version Latest $ErrorActionPreference = 'Stop' +# $ErrorActionPreference alone does not apply to native commands: gpg only sets $LASTEXITCODE, so +# without this a failed signature check would still reach the extraction at the end and the script +# would exit 0. Requires PowerShell 7.3+. +$PSNativeCommandUseErrorActionPreference = $true + if (!$Directory) { $Directory = $PSScriptRoot } -function Verify-Hash +function Assert-Hash { param ( - [Parameter(Mandatory=$true, HelpMessage='The file containing the hash.')] + [Parameter(Mandatory=$true, HelpMessage='The artifact to check.')] [System.IO.FileInfo]$File - ) - $Line = @(Get-Content $File.FullName)[0] - $Fields = $Line -split '\s+' - $Hash = $Fields[0].Trim().ToUpper() - $Filename = $Fields[1].Trim() - if ($Filename.StartsWith("*")) - { - $Filename = $Filename.Substring(1).Trim() - } - - $ComputedHash = (Get-FileHash -Algorithm 'SHA512' "$($File.DirectoryName)/$Filename").Hash.ToUpperInvariant() + ) - if($Hash -eq $ComputedHash) + $HashFile = "$($File.FullName).sha512" + if (!(Test-Path $HashFile)) { - "$($Filename): Passed" + throw "$($File.Name): no $($File.Name).sha512 to check it against" } - else + + $Hash = (@(Get-Content $HashFile)[0] -split '\s+')[0].Trim().ToUpperInvariant() + $ComputedHash = (Get-FileHash -Algorithm 'SHA512' $File.FullName).Hash.ToUpperInvariant() + if ($Hash -ne $ComputedHash) { - Write-Error "$($Filename): Not Passed" -ErrorAction Continue - Write-Error "Read from file: $Hash" -ErrorAction Continue - Write-Error "Computed: $ComputedHash" -ErrorAction Continue + throw "$($File.Name): SHA-512 mismatch, read $Hash but computed $ComputedHash" } + + "$($File.Name): hash ok" +} + +# Everything that is not a hash, a signature or the key file has to be covered by both. Driving the +# checks from the artifacts, rather than from the .sha512 and .asc files that happen to be present, +# is what turns a missing signature into a failure instead of one loop iteration fewer. +$Artifacts = @(Get-ChildItem $Directory -File | + Where-Object { $_.Extension -notin '.asc', '.sha512' -and $_.Name -ne 'KEYS' }) + +if ($Artifacts.Count -eq 0) +{ + throw "No artifacts to verify in $Directory" } -foreach ($File in Get-ChildItem $Directory *.sha512) +foreach ($Artifact in $Artifacts) { - Verify-Hash $File + Assert-Hash $Artifact } Invoke-WebRequest https://downloads.apache.org/logging/KEYS -OutFile $Directory/KEYS -gpg --import -q $Directory/KEYS -foreach ($File in Get-ChildItem $Directory *.asc) +# A key ring of its own, holding only the downloaded KEYS. Importing into the default key ring +# would accept a signature from any key this machine already has, not only from a key in the +# Logging Services KEYS file. +$KeyringDirectory = New-Item -ItemType Directory -Path (Join-Path ([System.IO.Path]::GetTempPath()) ([guid]::NewGuid())) +try +{ + $Keyring = Join-Path $KeyringDirectory 'logging-keys.gpg' + gpg --no-default-keyring --keyring $Keyring --batch --quiet --import $Directory/KEYS + + foreach ($Artifact in $Artifacts) + { + $Signature = "$($Artifact.FullName).asc" + if (!(Test-Path $Signature)) + { + throw "$($Artifact.Name): no $($Artifact.Name).asc to verify it with" + } + + gpg --no-default-keyring --keyring $Keyring --batch --verify $Signature $Artifact.FullName + "$($Artifact.Name): signature ok" + } +} +finally { - gpg --verify $File + Remove-Item $KeyringDirectory -Recurse -Force -ErrorAction SilentlyContinue } Expand-Archive $Directory/*source*.zip -DestinationPath $Directory/src diff --git a/scripts/verify-release.sh b/scripts/verify-release.sh index d1b3b9b89..70bdd1acd 100644 --- a/scripts/verify-release.sh +++ b/scripts/verify-release.sh @@ -1,26 +1,62 @@ #!/bin/bash -set -e +set -euo pipefail if ! which unzip >/dev/null 2>&1; then echo "The 'unzip' utility is required, but was not found in your path" >&2 exit 1 fi -TARGET_DIR="$1"; +TARGET_DIR="${1:-}" if test -z "$TARGET_DIR"; then TARGET_DIR="$(pwd)" fi +cd "$TARGET_DIR" -sha512sum --check *.sha512 +# Everything that is not a hash, a signature or the key file has to be covered by both. Driving the +# checks from the artifacts, rather than from the .sha512 and .asc files that happen to be present, +# is what turns a missing signature into a failure instead of one loop iteration fewer. +shopt -s nullglob +artifacts=() +for file in *; do + case "$file" in + *.asc|*.sha512|KEYS) continue ;; + esac + test -f "$file" || continue + artifacts+=("$file") +done + +if test ${#artifacts[@]} -eq 0; then + echo "No artifacts to verify in $TARGET_DIR" >&2 + exit 1 +fi + +for file in "${artifacts[@]}"; do + if test ! -f "$file.sha512"; then + echo "$file: no $file.sha512 to check it against" >&2 + exit 1 + fi + sha512sum --check "$file.sha512" +done wget https://downloads.apache.org/logging/KEYS -gpg --import -q KEYS -for f in $(find "$TARGET_DIR" -iname '*.asc'); do - gpg --verify "$f" + +# A key ring of its own, holding only the downloaded KEYS. Importing into the default key ring +# would accept a signature from any key this machine already has, not only from a key in the +# Logging Services KEYS file. +keyring_dir="$(mktemp -d)" +trap 'rm -rf "$keyring_dir"' EXIT +gpg --no-default-keyring --keyring "$keyring_dir/logging-keys.gpg" --batch --quiet --import KEYS + +for file in "${artifacts[@]}"; do + if test ! -f "$file.asc"; then + echo "$file: no $file.asc to verify it with" >&2 + exit 1 + fi + gpg --no-default-keyring --keyring "$keyring_dir/logging-keys.gpg" --batch --verify "$file.asc" "$file" done mkdir -p src cd src unzip -q -o ../*source*.zip -cd src \ No newline at end of file +cd src diff --git a/src/changelog/3.4.0/310-bound-file-lock-waits.xml b/src/changelog/3.4.0/310-bound-file-lock-waits.xml new file mode 100644 index 000000000..b7f86a8a9 --- /dev/null +++ b/src/changelog/3.4.0/310-bound-file-lock-waits.xml @@ -0,0 +1,17 @@ + + + + + bound the waits for the named mutexes used by `FileAppender.InterProcessLock` and by + `RollingFileAppender` when it decides whether to roll. Both waited without a timeout while the + appender lock was held, so a mutex nobody released suspended every thread logging through the + appender. The wait now stops after `LockTimeoutMillis`, 10000 by default, reporting through the + error handler and dropping the event or skipping the roll check; `Timeout.Infinite` restores the + previous behaviour. `AbandonedMutexException` is handled as the successful acquisition it is, + rather than leaving the mutex held, and the rolling lock is no longer released when it was never + taken (audit 1231d72-f015) + + diff --git a/src/changelog/3.4.0/310-bound-filter-regex-matching.xml b/src/changelog/3.4.0/310-bound-filter-regex-matching.xml new file mode 100644 index 000000000..4650f78a7 --- /dev/null +++ b/src/changelog/3.4.0/310-bound-filter-regex-matching.xml @@ -0,0 +1,17 @@ + + + + + give `RegexToMatch` matching a deadline in `StringMatchFilter` and the filters deriving from it, + `PropertyFilter`, `MdcFilter` and `NdcFilter`. The pattern was matched with + `Regex.InfiniteMatchTimeout` while the appender lock was held, so a pattern that backtracks could + stall everything logging through the appender on some inputs. Matching now stops after + `MatchTimeoutMillis`, 1000 by default, and an abandoned match is reported once and leaves the event + to the rest of the filter chain; 0 restores unbounded matching. The pattern comes from + configuration and is trusted, so this is hardening rather than a vulnerability fix + (audit 1231d72-f013) + + diff --git a/src/changelog/3.4.0/310-contain-per-event-adonet-failures.xml b/src/changelog/3.4.0/310-contain-per-event-adonet-failures.xml new file mode 100644 index 000000000..ec7f3e5bf --- /dev/null +++ b/src/changelog/3.4.0/310-contain-per-event-adonet-failures.xml @@ -0,0 +1,15 @@ + + + + + stop a single logging event that the database rejects from discarding the whole buffer in + `AdoNetAppender`. The events have already been removed from the buffer when they are sent, so a + rolled back transaction lost up to `BufferSize` unrelated events, which an attacker could trigger + repeatedly with content the provider refuses, such as `U+0000` on npgsql (CWE-778). Delivery + becomes at-least-once: events already applied by a batch that then failed may be written again + (audit 1231d72-f004) + + diff --git a/src/changelog/3.4.0/310-escape-nul-in-local-syslog-messages.xml b/src/changelog/3.4.0/310-escape-nul-in-local-syslog-messages.xml new file mode 100644 index 000000000..17a347adf --- /dev/null +++ b/src/changelog/3.4.0/310-escape-nul-in-local-syslog-messages.xml @@ -0,0 +1,14 @@ + + + + + stop a NUL character in logged content from truncating `LocalSyslogAppender` records. The + message is marshaled to libc as a null-terminated string, so everything the layout rendered after + the NUL was silently dropped, including trailing fields and exception text (CWE-158). NUL is now + escaped as `\0`; other control characters are still passed through, because `syslog(3)` encodes + them and newlines are needed for multi-line exception output (audit 1231d72-f008) + + diff --git a/src/changelog/3.4.0/310-flush-uses-the-appender-lock.xml b/src/changelog/3.4.0/310-flush-uses-the-appender-lock.xml new file mode 100644 index 000000000..606d21ca7 --- /dev/null +++ b/src/changelog/3.4.0/310-flush-uses-the-appender-lock.xml @@ -0,0 +1,15 @@ + + + + + make `TextWriterAppender` and the appenders deriving from it, including `FileAppender` and + `RollingFileAppender`, flush under the appender lock. `Flush` synchronized on a private object while + `Append` runs under the lock taken by `DoAppend`, so a flush could run concurrently with a write to + the same `QuietTextWriter`, which is not thread safe, and interleave or lose output. `Flush` also + returned `true` whatever happened and let a failure from the underlying writer escape to its + caller; it now reports through the `ErrorHandler` and returns `false` (audit 1231d72-f020) + + diff --git a/src/changelog/3.4.0/310-pin-maven-wrapper-checksums.xml b/src/changelog/3.4.0/310-pin-maven-wrapper-checksums.xml new file mode 100644 index 000000000..4a4b9bdd7 --- /dev/null +++ b/src/changelog/3.4.0/310-pin-maven-wrapper-checksums.xml @@ -0,0 +1,14 @@ + + + + + pin the Maven wrapper and the Maven distribution it downloads with + `wrapperSha256Sum` and `distributionSha256Sum`. `mvnw` and `MavenWrapperDownloader` already refuse + to run when a download does not match, but neither property was set, so whatever the URLs returned + was executed (CWE-494). Both values were taken from artifacts whose PGP signature verifies against + the Apache Maven KEYS (audit 1231d72-f023) + + diff --git a/src/changelog/3.4.0/310-redact-password-in-connection-string-errors.xml b/src/changelog/3.4.0/310-redact-password-in-connection-string-errors.xml new file mode 100644 index 000000000..5bbe81e36 --- /dev/null +++ b/src/changelog/3.4.0/310-redact-password-in-connection-string-errors.xml @@ -0,0 +1,13 @@ + + + + + stop `AdoNetAppender` from repeating the password when it reports a connection it could not + open. The message named the resolved connection string in full, and the documented examples embed + `Password=...` (CWE-532). Password-bearing keywords are now replaced with `*****`, while the rest + of the connection string is kept so the message stays useful (audit 1231d72-f018) + + diff --git a/src/changelog/3.4.0/310-remove-git-broadcast-workflow.xml b/src/changelog/3.4.0/310-remove-git-broadcast-workflow.xml new file mode 100644 index 000000000..24e801b3b --- /dev/null +++ b/src/changelog/3.4.0/310-remove-git-broadcast-workflow.xml @@ -0,0 +1,13 @@ + + + + + remove the `git-broadcast` workflow. Its push and pull request triggers had been commented out, + leaving it dispatched by hand only, while it still ran `npx git-broadcast@beta`, a dist-tag that can + be repointed at any published version, in a job that checks out with a token able to push to this + repository, using mutable action tags and no `permissions` block (CWE-1357) (audit 1231d72-f011) + + diff --git a/src/changelog/3.4.0/310-report-first-appender-error-by-default.xml b/src/changelog/3.4.0/310-report-first-appender-error-by-default.xml new file mode 100644 index 000000000..d480e1075 --- /dev/null +++ b/src/changelog/3.4.0/310-report-first-appender-error-by-default.xml @@ -0,0 +1,14 @@ + + + + + report the first error of an appender even when `log4net.Internal.Debug` is off, which is the + default. `OnlyOnceErrorHandler` is the default error handler of every appender, so an appender + that stopped delivering events previously did so without leaving any trace (CWE-778). + `log4net.Internal.Quiet` and `LogLog.EmitInternalMessages` remain the ways to silence internal + messages (audit 1231d72-f019) + + diff --git a/src/changelog/3.4.0/310-report-malformed-syslog-identity.xml b/src/changelog/3.4.0/310-report-malformed-syslog-identity.xml new file mode 100644 index 000000000..c731d66cd --- /dev/null +++ b/src/changelog/3.4.0/310-report-malformed-syslog-identity.xml @@ -0,0 +1,15 @@ + + + + + report a `RemoteSyslogAppender` `Identity` that renders control characters, and remove them, so + that it cannot split the record. The identity becomes the TAG of the syslog record and was appended + verbatim, while the message part is filtered, so a line feed in it let the text that followed be + read as a record of its own with an attacker chosen facility and severity. The TAG is a structural + identifier and expected to be a constant, so this is reported as the configuration error it is + rather than being repaired quietly (audit 1231d72-f016) + + diff --git a/src/changelog/3.4.0/310-require-tls-when-enablessl-is-set.xml b/src/changelog/3.4.0/310-require-tls-when-enablessl-is-set.xml new file mode 100644 index 000000000..9e1dbc472 --- /dev/null +++ b/src/changelog/3.4.0/310-require-tls-when-enablessl-is-set.xml @@ -0,0 +1,15 @@ + + + + + add a `TransportSecurity` option to the `log4net.Ext.Mail` `SmtpAppender` and make `EnableSsl` + a shorthand for it. `EnableSsl` requires transport security, selecting implicit TLS on port 465 and + mandatory `STARTTLS` elsewhere, so connecting fails when the server offers no TLS instead of + silently continuing in plaintext, as `System.Net.Mail.SmtpClient.EnableSsl` does. Opportunistic + `STARTTLS` remains available, but only by asking for it with + `TransportSecurity=StartTlsWhenAvailable` (audit 1231d72-f007) + + diff --git a/src/changelog/3.4.0/310-syslog-identity-lifetime.xml b/src/changelog/3.4.0/310-syslog-identity-lifetime.xml new file mode 100644 index 000000000..da0382552 --- /dev/null +++ b/src/changelog/3.4.0/310-syslog-identity-lifetime.xml @@ -0,0 +1,15 @@ + + + + + fix the lifetime of the `LocalSyslogAppender` identity. `openlog` keeps the pointer it is given + rather than a copy of the string, and registers it for the process rather than for an appender. + Each `ActivateOptions` allocated a new buffer and forgot the previous one, leaking it (CWE-401), + while `OnClose` freed a buffer that another instance may still have been logging through. The + handle is now shared, replaced under a lock once `openlog` points at the new string, and left + allocated when an appender closes (audit 1231d72-f017) + + diff --git a/src/changelog/3.4.0/310-telnet-appender-send-timeout.xml b/src/changelog/3.4.0/310-telnet-appender-send-timeout.xml new file mode 100644 index 000000000..0ab86e34c --- /dev/null +++ b/src/changelog/3.4.0/310-telnet-appender-send-timeout.xml @@ -0,0 +1,15 @@ + + + + + stop a Telnet client that connects and then stops reading from suspending all logging. + `TelnetAppender` writes to its clients while the appender lock is held and set no + `Socket.SendTimeout`, so once TCP flow control filled the client's receive window the next write + blocked forever and every thread logging through the appender queued behind it (CWE-833). Writes + now time out after `SendTimeoutMillis` (5000 by default) and the client is disconnected; 0 + restores the previous unbounded behavior (audit 1231d72-f001) + + diff --git a/src/changelog/3.4.0/310-telnet-listen-address.xml b/src/changelog/3.4.0/310-telnet-listen-address.xml new file mode 100644 index 000000000..0d189da95 --- /dev/null +++ b/src/changelog/3.4.0/310-telnet-listen-address.xml @@ -0,0 +1,13 @@ + + + + + add `ListenAddress` to `TelnetAppender`. The listening socket was bound to `IPAddress.Any` with + no way to scope it, so an operator who only wanted to watch the log from the machine itself still + got a listener on every interface. The default is unchanged, and the listening socket now follows + the address family, so an IPv6 address works too (audit 1231d72-f002) + + diff --git a/src/changelog/3.4.0/310-username-honours-the-fix-gate.xml b/src/changelog/3.4.0/310-username-honours-the-fix-gate.xml new file mode 100644 index 000000000..7d115b227 --- /dev/null +++ b/src/changelog/3.4.0/310-username-honours-the-fix-gate.xml @@ -0,0 +1,16 @@ + + + + + stop `LoggingEvent.UserName` reporting the wrong user for an event logged while impersonating. + The property resolved the identity of whichever thread read it, so with a buffering appender the + buffered events were attributed to the thread flushing the buffer rather than the one that logged + them (CWE-282). An event logged while impersonating now takes its user name with it when it is + fixed, and an event read on an impersonating thread reports the not available text instead of that + thread's user. Without impersonation the name is the process identity, which is the same on every + thread, so it is still resolved lazily and nothing changes (audit 1231d72-f014) + + diff --git a/src/changelog/3.4.0/310-verify-release-fails-closed.xml b/src/changelog/3.4.0/310-verify-release-fails-closed.xml new file mode 100644 index 000000000..ba4a1e0e8 --- /dev/null +++ b/src/changelog/3.4.0/310-verify-release-fails-closed.xml @@ -0,0 +1,16 @@ + + + + + make the release verification scripts fail closed. `verify-release.ps1` reported a SHA-512 + mismatch with `-ErrorAction Continue` and never checked the exit code of `gpg`, so it extracted the + archive and exited 0 for a tampered artifact or a broken signature. Both scripts looped over + whichever `.asc` files were present, so deleting them left nothing to verify and the scripts + succeeded. The checks are now driven from the artifacts, each of which must have a `.sha512` and a + `.asc`, and the keys are imported into a key ring of their own so that a signature from any other + key this machine trusts is no longer accepted (audit 1231d72-f009, 1231d72-f010) + + diff --git a/src/changelog/3.4.0/310-warn-about-layout-generated-sql.xml b/src/changelog/3.4.0/310-warn-about-layout-generated-sql.xml new file mode 100644 index 000000000..0a7355965 --- /dev/null +++ b/src/changelog/3.4.0/310-warn-about-layout-generated-sql.xml @@ -0,0 +1,13 @@ + + + + + log an error when `AdoNetAppender` is activated without `CommandText`. In that legacy mode the + rendered `Layout` output is executed as the SQL statement, and because layouts perform no SQL + quoting, logged content becomes part of the statement (CWE-89). Configure `CommandText` with + `AdoNetAppenderParameter` bindings instead (audit 1231d72-f003) + + diff --git a/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs b/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs index bb23df02a..338103951 100644 --- a/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs +++ b/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs @@ -207,15 +207,87 @@ public void EnableSslOffConnectsWithoutTransportSecurity() Assert.That(_transport.SecureSocketOptions, Is.EqualTo(SecureSocketOptions.None)); } + /// + /// SecureSocketOptions.Auto is opportunistic away from port 465, so an attacker who strips + /// STARTTLS from the EHLO response downgrades the session to plaintext. Asking for SSL has to + /// mean mandatory STARTTLS. + /// [Test] - public void EnableSslOnNegotiatesTransportSecurity() + public void EnableSslOnRequiresStartTls() { SmtpAppender appender = CreateAppender(); appender.EnableSsl = true; Append(appender); - Assert.That(_transport.SecureSocketOptions, Is.EqualTo(SecureSocketOptions.Auto)); + Assert.That(_transport.SecureSocketOptions, Is.EqualTo(SecureSocketOptions.StartTls)); + } + + /// + /// Port 465 is implicit TLS: the session is encrypted before the SMTP greeting, so STARTTLS is + /// never offered there and must not be demanded. + /// + [Test] + public void EnableSslOnPort465UsesImplicitTls() + { + SmtpAppender appender = CreateAppender(); + appender.EnableSsl = true; + appender.Port = 465; + + Append(appender); + + Assert.That(_transport.SecureSocketOptions, Is.EqualTo(SecureSocketOptions.SslOnConnect)); + } + + /// + /// A server doing implicit TLS on a port other than 465 cannot be reached with Required, which + /// would try to negotiate STARTTLS there. + /// + [Test] + public void ImplicitTlsUsesSslOnConnectRegardlessOfThePort() + { + SmtpAppender appender = CreateAppender(); + appender.TransportSecurity = SmtpTransportSecurity.ImplicitTls; + appender.Port = 8465; + + Append(appender); + + Assert.That(_transport.SecureSocketOptions, Is.EqualTo(SecureSocketOptions.SslOnConnect)); + } + + /// + /// Opportunistic transport security stays available, but only for an operator who asks for it. + /// + [Test] + public void StartTlsWhenAvailableIsOpportunistic() + { + SmtpAppender appender = CreateAppender(); + appender.TransportSecurity = SmtpTransportSecurity.StartTlsWhenAvailable; + + Append(appender); + + Assert.That(_transport.SecureSocketOptions, Is.EqualTo(SecureSocketOptions.StartTlsWhenAvailable)); + } + + /// + /// EnableSsl and TransportSecurity are the same setting, so they cannot disagree. + /// + [Test] + public void EnableSslIsAShorthandForTransportSecurity() + { + SmtpAppender appender = CreateAppender(); + + Assert.That(appender.TransportSecurity, Is.EqualTo(SmtpTransportSecurity.None)); + Assert.That(appender.EnableSsl, Is.False); + + appender.EnableSsl = true; + Assert.That(appender.TransportSecurity, Is.EqualTo(SmtpTransportSecurity.Required)); + + appender.TransportSecurity = SmtpTransportSecurity.StartTlsWhenAvailable; + Assert.That(appender.EnableSsl, Is.True); + + appender.EnableSsl = false; + Assert.That(appender.TransportSecurity, Is.EqualTo(SmtpTransportSecurity.None)); } [Test] diff --git a/src/log4net.Ext.Mail/Appender/SmtpAppender.cs b/src/log4net.Ext.Mail/Appender/SmtpAppender.cs index 54ce6a917..e2d631a4e 100644 --- a/src/log4net.Ext.Mail/Appender/SmtpAppender.cs +++ b/src/log4net.Ext.Mail/Appender/SmtpAppender.cs @@ -69,6 +69,12 @@ namespace log4net.Ext.Mail.Appender; /// public class SmtpAppender : BufferingAppenderSkeleton { + /// + /// The port reserved for SMTP over implicit TLS, where TLS starts before the SMTP greeting + /// rather than being negotiated with STARTTLS. + /// + private const int ImplicitTlsPort = 465; + private readonly Func _transportFactory; /// @@ -239,18 +245,40 @@ public string? Bcc /// /// /// - /// When , is used, which - /// negotiates implicit TLS or STARTTLS depending on the and - /// what the server advertises. When the connection is not - /// encrypted at all (), matching the behaviour of - /// . + /// This is a shorthand for : setting it to + /// selects and setting it to + /// selects . The two properties + /// are the same setting, so the one assigned last wins. /// /// - /// Use directly via a custom - /// if you need finer control. + /// When , transport security is required: implicit TLS on port 465 and + /// STARTTLS on every other port. Connecting fails if the server does not offer TLS, + /// rather than continuing unencrypted, which matches the behaviour of + /// . Use when + /// the server needs something else. + /// + /// + public bool EnableSsl + { + get => TransportSecurity != SmtpTransportSecurity.None; + set => TransportSecurity = value ? SmtpTransportSecurity.Required : SmtpTransportSecurity.None; + } + + /// + /// Gets or sets how the connection to the SMTP server is secured. + /// + /// + /// One of the values. The default is + /// . + /// + /// + /// + /// is a shorthand for this property and covers the usual cases; set this + /// one when the server expects implicit TLS on a port other than 465, or when only opportunistic + /// STARTTLS is possible. /// /// - public bool EnableSsl { get; set; } + public SmtpTransportSecurity TransportSecurity { get; set; } = SmtpTransportSecurity.None; /// /// Gets or sets the reply-to e-mail address. @@ -315,6 +343,32 @@ protected override void SendBuffer(LoggingEvent[] events) /// protected override bool RequiresLayout => true; + /// + /// Translates into the mail library's own representation. + /// + /// The transport security to connect with. + /// + /// + /// is deliberately never used: away from port 465 it is + /// opportunistic, so an attacker who strips STARTTLS from the EHLO response silently + /// downgrades the session to plaintext, taking the credentials and the log content with it. + /// Opportunistic behavior is available, but only by asking for it with + /// . + /// + /// + private SecureSocketOptions ResolveSecureSocketOptions() => TransportSecurity switch + { + SmtpTransportSecurity.None => SecureSocketOptions.None, + SmtpTransportSecurity.Required => Port == ImplicitTlsPort + ? SecureSocketOptions.SslOnConnect + : SecureSocketOptions.StartTls, + SmtpTransportSecurity.ImplicitTls => SecureSocketOptions.SslOnConnect, + SmtpTransportSecurity.StartTls => SecureSocketOptions.StartTls, + SmtpTransportSecurity.StartTlsWhenAvailable => SecureSocketOptions.StartTlsWhenAvailable, + _ => throw SystemInfo.CreateArgumentOutOfRangeException(nameof(TransportSecurity), TransportSecurity, + $"The value specified for TransportSecurity is not one of the {nameof(SmtpTransportSecurity)} values.") + }; + /// /// Send the email message /// @@ -324,10 +378,7 @@ protected virtual void SendEmail(string messageBody) using MimeMessage message = CreateMessage(messageBody); using ISmtpTransport transport = _transportFactory().EnsureNotNull(); - transport.Connect( - SmtpHost.EnsureNotNullOrEmpty(), - Port, - EnableSsl ? SecureSocketOptions.Auto : SecureSocketOptions.None); + transport.Connect(SmtpHost.EnsureNotNullOrEmpty(), Port, ResolveSecureSocketOptions()); try { switch (Authentication) diff --git a/src/log4net.Ext.Mail/Appender/SmtpTransportSecurity.cs b/src/log4net.Ext.Mail/Appender/SmtpTransportSecurity.cs new file mode 100644 index 000000000..a6ec293ba --- /dev/null +++ b/src/log4net.Ext.Mail/Appender/SmtpTransportSecurity.cs @@ -0,0 +1,79 @@ +#region Apache License +// +// Licensed to the Apache Software Foundation (ASF) under one or more +// contributor license agreements. See the NOTICE file distributed with +// this work for additional information regarding copyright ownership. +// The ASF licenses this file to you under the Apache License, Version 2.0 +// (the "License"); you may not use this file except in compliance with +// the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// +#endregion + +namespace log4net.Ext.Mail.Appender; + +/// +/// How secures its connection to the SMTP server. +/// +/// +/// +/// This mirrors the transport security modes of the underlying mail library without exposing its +/// types, so that the appender's configuration surface stays CLS compliant. +/// +/// +public enum SmtpTransportSecurity +{ + /// + /// The connection is not encrypted. + /// + None, + + /// + /// Transport security is required, and the mechanism follows the port: implicit TLS on port 465, + /// STARTTLS on every other port. + /// + /// + /// + /// Connecting fails when the server does not offer transport security, rather than continuing + /// unencrypted. This is what selects and is the right + /// choice unless the server does something unusual. + /// + /// + Required, + + /// + /// The session is encrypted before the SMTP greeting, without STARTTLS. + /// + /// + /// + /// Use this for a server that expects implicit TLS on a port other than 465, which + /// would try to negotiate with STARTTLS instead. + /// + /// + ImplicitTls, + + /// + /// STARTTLS is required, whatever the port. + /// + StartTls, + + /// + /// STARTTLS is used when the server advertises it, and the connection continues + /// unencrypted when it does not. + /// + /// + /// + /// This is opportunistic: an attacker who can modify the traffic can remove the server's + /// STARTTLS advertisement and the session then proceeds in plaintext, exposing the + /// credentials and the log content. Only choose it for a network where that is acceptable. + /// + /// + StartTlsWhenAvailable +} diff --git a/src/log4net.Tests/Appender/AdoNet/Log4NetCommand.cs b/src/log4net.Tests/Appender/AdoNet/Log4NetCommand.cs index 161d49231..7a44dea23 100644 --- a/src/log4net.Tests/Appender/AdoNet/Log4NetCommand.cs +++ b/src/log4net.Tests/Appender/AdoNet/Log4NetCommand.cs @@ -20,12 +20,16 @@ */ using System; +using System.Collections.Generic; using System.Data; namespace log4net.Tests.Appender.AdoNet; internal sealed class Log4NetCommand : IDbCommand { + /// + /// Initializes a new instance and records it as the . + /// public Log4NetCommand() { MostRecentInstance = this; @@ -33,58 +37,112 @@ public Log4NetCommand() Parameters = new Log4NetParameterCollection(); } + /// public void Dispose() { // empty } + /// public IDbTransaction? Transaction { get; set; } + /// public int ExecuteNonQuery() { + string? payload = null; + foreach (object? parameter in Parameters) + { + if (parameter is IDataParameter { Value: string value }) + { + payload = value; + break; + } + } + payload ??= CommandText; + + if (ExceptionTrigger is not null + && payload?.IndexOf(ExceptionTrigger, StringComparison.Ordinal) >= 0) + { + throw new InvalidOperationException($"Simulated database rejection of [{payload}]"); + } + ExecuteNonQueryCount++; + if (payload is not null) + { + ExecutedPayloads.Add(payload); + } return 0; } + /// + /// The number of successful calls on this instance. + /// public int ExecuteNonQueryCount { get; private set; } + /// + /// When set, throws for every command whose payload + /// contains this string, simulating a database that rejects specific content. + /// + public static string? ExceptionTrigger { get; set; } + + /// + /// The payload - the first string parameter value, or the command text when there are no + /// parameters - of every successful across all instances. + /// + public static List ExecutedPayloads { get; } = []; + + /// public IDbDataParameter CreateParameter() => new Log4NetParameter(); #pragma warning disable CS8766 // Nullability of reference types in return type doesn't match implicitly implemented member (possibly because of nullability attributes). + /// public string? CommandText { get; set; } #pragma warning restore CS8766 + /// public CommandType CommandType { get; set; } + /// public void Prepare() { // empty } + /// public IDataParameterCollection Parameters { get; } + /// + /// The most recently constructed instance, so that a test can inspect what the appender used. + /// public static Log4NetCommand? MostRecentInstance { get; private set; } + /// public void Cancel() => throw new NotImplementedException(); + /// public IDataReader ExecuteReader() => throw new NotImplementedException(); + /// public IDataReader ExecuteReader(CommandBehavior behavior) => throw new NotImplementedException(); + /// public object ExecuteScalar() => throw new NotImplementedException(); + /// public IDbConnection? Connection { get => throw new NotImplementedException(); set => throw new NotImplementedException(); } + /// public int CommandTimeout { get => throw new NotImplementedException(); set => throw new NotImplementedException(); } + /// public UpdateRowSource UpdatedRowSource { get => throw new NotImplementedException(); diff --git a/src/log4net.Tests/Appender/AdoNet/Log4NetConnection.cs b/src/log4net.Tests/Appender/AdoNet/Log4NetConnection.cs index e11411b0c..f5324ea38 100644 --- a/src/log4net.Tests/Appender/AdoNet/Log4NetConnection.cs +++ b/src/log4net.Tests/Appender/AdoNet/Log4NetConnection.cs @@ -30,31 +30,60 @@ internal sealed class Log4NetConnection : IDbConnection { private bool _open; + /// + /// Initializes a new instance and records it as the . + /// public Log4NetConnection() => MostRecentInstance = this; + /// public void Close() => _open = false; + /// public ConnectionState State => _open ? ConnectionState.Open : ConnectionState.Closed; #pragma warning disable CS8766 // Nullability of reference types in return type doesn't match implicitly implemented member (possibly because of nullability attributes). + /// public string? ConnectionString { get; set; } #pragma warning restore CS8766 + /// public IDbTransaction BeginTransaction() => new Log4NetTransaction(); + /// public IDbCommand CreateCommand() => new Log4NetCommand(); - public void Open() => _open = true; - + /// + public void Open() + { + if (FailOnOpen) + { + throw new InvalidOperationException("Simulated failure to open the connection"); + } + _open = true; + } + + /// + /// When set, throws, simulating a connection that cannot be established. + /// + public static bool FailOnOpen { get; set; } + + /// + /// The most recently constructed instance, so that a test can inspect what the appender used. + /// public static Log4NetConnection? MostRecentInstance { get; private set; } + /// public IDbTransaction BeginTransaction(IsolationLevel il) => throw new NotImplementedException(); + /// public void ChangeDatabase(string databaseName) => throw new NotImplementedException(); + /// public int ConnectionTimeout => throw new NotImplementedException(); + /// public string Database => throw new NotImplementedException(); + /// public void Dispose() => throw new NotImplementedException(); } diff --git a/src/log4net.Tests/Appender/AdoNet/Log4NetTransaction.cs b/src/log4net.Tests/Appender/AdoNet/Log4NetTransaction.cs index 27b3bb9ca..81afb218f 100644 --- a/src/log4net.Tests/Appender/AdoNet/Log4NetTransaction.cs +++ b/src/log4net.Tests/Appender/AdoNet/Log4NetTransaction.cs @@ -26,19 +26,21 @@ namespace log4net.Tests.Appender.AdoNet; internal sealed class Log4NetTransaction : IDbTransaction { + /// public void Commit() - { - // empty - } + { } + /// public void Rollback() - { - // empty - } + { } + /// public IDbConnection Connection => throw new NotImplementedException(); + /// public IsolationLevel IsolationLevel => throw new NotImplementedException(); - public void Dispose() => throw new NotImplementedException(); + /// + public void Dispose() + { } } diff --git a/src/log4net.Tests/Appender/AdoNetAppenderTest.cs b/src/log4net.Tests/Appender/AdoNetAppenderTest.cs index 17b4119e7..3e391586c 100644 --- a/src/log4net.Tests/Appender/AdoNetAppenderTest.cs +++ b/src/log4net.Tests/Appender/AdoNetAppenderTest.cs @@ -20,6 +20,7 @@ */ using System; +using System.Collections.Generic; using System.Data; using System.Xml; using log4net.Appender; @@ -264,6 +265,161 @@ public void BufferingWebsiteExample() Assert.That(param.Value, Is.Empty); } + /// + /// The message reporting a failed connection must not repeat the password from the connection + /// string. The appender reports the failure through its ErrorHandler, so this message is what + /// an operator sees on stderr in a default configuration. + /// + [Test] + [NonParallelizable] + public void FailedConnectionDoesNotReportThePassword() + { + const string password = "H0rseBatteryStaple"; + List messages = []; + try + { + Log4NetConnection.FailOnOpen = true; + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + using LogLog.LogReceivedAdapter _ = new(messages); + AdoNetAppender adoNetAppender = new() + { + BufferSize = -1, + ConnectionType = typeof(Log4NetConnection).AssemblyQualifiedName!, + ConnectionString = $"data source=someserver;initial catalog=somedb;User ID=someuser;Password={password}", + CommandText = "INSERT INTO Log ([Message]) VALUES (@message)" + }; + adoNetAppender.ActivateOptions(); + }); + + string reported = string.Join(Environment.NewLine, messages.ConvertAll(m => m.Message)); + + Assert.That(reported, Does.Not.Contain(password)); + Assert.That(reported, Does.Contain("Could not open database connection")); + // The rest of the connection string survives, so the message stays useful for diagnosis. + Assert.That(reported, Does.Contain("someserver")); + } + finally + { + Log4NetConnection.FailOnOpen = false; + } + } + + /// + /// Without CommandText the rendered Layout is executed as the SQL statement, which is open + /// to SQL injection from logged content. Activation has to say so. + /// + [Test] + [NonParallelizable] + public void ActivateOptionsWithoutCommandTextWarnsAboutSqlInjection() + { + List messages = []; + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + using LogLog.LogReceivedAdapter _ = new(messages); + AdoNetAppender adoNetAppender = new() + { + BufferSize = -1, + ConnectionType = typeof(Log4NetConnection).AssemblyQualifiedName! + }; + adoNetAppender.ActivateOptions(); + }); + + Assert.That(messages.ConvertAll(m => m.Message), + Has.Some.Contains("open to SQL injection")); + } + + /// + /// Configuring CommandText is the supported way to use the appender and must not warn. + /// + [Test] + [NonParallelizable] + public void ActivateOptionsWithCommandTextDoesNotWarn() + { + List messages = []; + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + using LogLog.LogReceivedAdapter _ = new(messages); + AdoNetAppender adoNetAppender = new() + { + BufferSize = -1, + ConnectionType = typeof(Log4NetConnection).AssemblyQualifiedName!, + CommandText = "INSERT INTO Log ([Message]) VALUES (@message)" + }; + adoNetAppender.ActivateOptions(); + }); + + Assert.That(messages.ConvertAll(m => m.Message), + Has.None.Contains("open to SQL injection")); + } + + /// + /// An event the database rejects must only lose itself. The other events of the flushed + /// buffer have already been removed from it and cannot be retried later, so they have to + /// be written even though they shared a transaction with the rejected event. + /// + [Test] + [NonParallelizable] + public void RejectedEventDoesNotDiscardTheRestOfTheBuffer() + { + try + { + Log4NetCommand.ExceptionTrigger = "POISON"; + Log4NetCommand.ExecutedPayloads.Clear(); + + XmlDocument log4NetConfig = new(); + log4NetConfig.LoadXml( + """ + + + + + + + + + + + + + + + + + + + + + + """); + + ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); + XmlConfigurator.Configure(rep, log4NetConfig["log4net"]!); + ILog log = LogManager.GetLogger(rep.Name, "RejectedEventDoesNotDiscardTheRestOfTheBuffer"); + + // The appender reports the rejected event through its ErrorHandler; that is expected + // here and should not clutter the test output. + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + log.Debug("before"); + log.Debug("a POISON message"); + log.Debug("after one"); + // The fourth event overflows the buffer of 3 and flushes all four events. + log.Debug("after two"); + }); + + Assert.That(Log4NetCommand.ExecutedPayloads, Has.Member("before")); + Assert.That(Log4NetCommand.ExecutedPayloads, Has.Member("after one")); + Assert.That(Log4NetCommand.ExecutedPayloads, Has.Member("after two")); + Assert.That(Log4NetCommand.ExecutedPayloads, Has.No.Member("a POISON message")); + } + finally + { + Log4NetCommand.ExceptionTrigger = null; + Log4NetCommand.ExecutedPayloads.Clear(); + } + } + [Test] public void NullPropertyXmlConfig() { diff --git a/src/log4net.Tests/Appender/FileAppenderTest.cs b/src/log4net.Tests/Appender/FileAppenderTest.cs index 8537f80d1..ddd55f7ea 100644 --- a/src/log4net.Tests/Appender/FileAppenderTest.cs +++ b/src/log4net.Tests/Appender/FileAppenderTest.cs @@ -1,4 +1,4 @@ -#region Apache License +#region Apache License // // Licensed to the Apache Software Foundation (ASF) under one or more @@ -30,7 +30,9 @@ using System.IO; using System.Linq; using System.Text; +using System.Threading; using System.Threading.Tasks; +using System.Diagnostics; namespace log4net.Tests.Appender; @@ -183,4 +185,84 @@ public void InterProcessLock_AcquireLock_ReleasesMutexWhenStreamIsNull() File.Delete(tempFile); } } + + /// + /// The wait for the inter process lock happens while the appender lock is held, so it has to be + /// bounded by default: a lock nobody releases would otherwise suspend all logging for good. + /// + [Test] + public void LockTimeoutMillisDefaultsToAFiniteValue() + => Assert.That(new FileAppender.InterProcessLock().LockTimeoutMillis, Is.EqualTo(10000)); + + /// + /// Timeout.Infinite restores waiting indefinitely and 0 gives up at once; any other negative + /// value has no meaning and is rejected rather than reinterpreted. + /// + [Test] + public void LockTimeoutMillisRejectsNegativeValuesExceptInfinite() + { + FileAppender.InterProcessLock lockingModel = new(); + + Assert.That(() => lockingModel.LockTimeoutMillis = -2, Throws.TypeOf()); + + lockingModel.LockTimeoutMillis = Timeout.Infinite; + Assert.That(lockingModel.LockTimeoutMillis, Is.EqualTo(Timeout.Infinite)); + + lockingModel.LockTimeoutMillis = 0; + Assert.That(lockingModel.LockTimeoutMillis, Is.EqualTo(0)); + } + + /// + /// When something else holds the lock and does not let go, the event is dropped rather than the + /// logging thread being blocked forever. + /// + [Test] + [NonParallelizable] + public void AcquireLockGivesUpWhenTheLockIsHeldTooLong() + { + const string appenderFile = "log4net_lock_timeout_test"; + string tempFile = Path.GetTempFileName(); + FileAppender appender = new() { File = appenderFile }; + FileAppender.InterProcessLock lockingModel = new() + { + CurrentAppender = appender, + LockTimeoutMillis = 200 + }; + lockingModel.ActivateOptions(); + lockingModel.OpenFile(tempFile, false, Encoding.UTF8); + + using ManualResetEventSlim held = new(); + using ManualResetEventSlim release = new(); + // A mutex has to be taken and released on one thread, so the holder does both. + Task holder = Task.Run(() => + { + using Mutex contender = new(false, appenderFile); + contender.WaitOne(); + held.Set(); + release.Wait(); + contender.ReleaseMutex(); + }); + + try + { + Assert.That(held.Wait(TimeSpan.FromSeconds(10)), Is.True, "the contending thread never took the mutex"); + + Stream? stream = null; + Stopwatch stopwatch = Stopwatch.StartNew(); + LogLog.ExecuteWithoutEmittingInternalMessages(() => stream = lockingModel.AcquireLock()); + stopwatch.Stop(); + + Assert.That(stream, Is.Null, "the lock was reported as acquired while another thread held it"); + Assert.That(stopwatch.Elapsed, Is.LessThan(TimeSpan.FromSeconds(10))); + } + finally + { + release.Set(); + holder.Wait(TimeSpan.FromSeconds(10)); + // CloseFile closes the stream opened by OpenFile; OnClose only disposes the mutex. + lockingModel.CloseFile(); + lockingModel.OnClose(); + File.Delete(tempFile); + } + } } \ No newline at end of file diff --git a/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs b/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs new file mode 100644 index 000000000..be09b7f90 --- /dev/null +++ b/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs @@ -0,0 +1,121 @@ +#region Apache License +// +// Licensed to the Apache Software Foundation (ASF) under one or more +// contributor license agreements. See the NOTICE file distributed with +// this work for additional information regarding copyright ownership. +// The ASF licenses this file to you under the Apache License, Version 2.0 +// (the "License"); you may not use this file except in compliance with +// the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// +#endregion + +using System; +using System.Reflection; + +using log4net.Appender; +using log4net.Layout; + +using NUnit.Framework; + +namespace log4net.Tests.Appender; + +/// +/// Tests for +/// +/// +/// +/// The appender itself writes through syslog(3), whose output cannot be read back from a +/// test, so these tests cover the message preparation that happens before the native call. +/// +/// +[TestFixture] +public class LocalSyslogAppenderTest +{ + /// + /// The message is marshaled to libc as a null-terminated string, so a NUL character in logged + /// content would end the record there and drop everything the layout rendered after it. + /// + [Test] + public void NulCharactersAreEscaped() + => Assert.That(EscapeNulCharacters("priority=high\0user=alice"), Is.EqualTo("priority=high\\0user=alice")); + + /// + /// Several NUL characters must all be escaped, not just the first one. + /// + [Test] + public void EveryNulCharacterIsEscaped() + => Assert.That(EscapeNulCharacters("a\0b\0c"), Is.EqualTo("a\\0b\\0c")); + + /// + /// A message without a NUL character has to come through untouched, including the newlines an + /// exception layout produces: syslog(3) deals with those itself. + /// + [Test] + public void MessagesWithoutNulCharactersAreUnchanged() + { + const string message = "System.InvalidOperationException: boom\r\n at Program.Main()\tfield=1"; + + Assert.That(EscapeNulCharacters(message), Is.EqualTo(message)); + } + + /// + /// An empty message takes the fast path, which must not turn it into anything else. + /// + [Test] + public void EmptyMessageIsUnchanged() + => Assert.That(EscapeNulCharacters(string.Empty), Is.Empty); + + /// + /// openlog registers the identity for the process rather than for an appender, so the + /// handle to it has to be shared instead of being kept per instance. + /// + [Test] + public void TheIdentityHandleBelongsToTheProcess() + { + FieldInfo field = typeof(LocalSyslogAppender) + .GetField("_handleToIdentity", BindingFlags.Static | BindingFlags.NonPublic) + ?? throw new InvalidOperationException("LocalSyslogAppender._handleToIdentity is missing"); + + Assert.That(field.IsStatic, Is.True); + } + + /// + /// Activating twice has to replace the registered identity rather than allocate another one and + /// forget the first, which leaked a buffer per call. + /// + [Test] + [Platform("Linux")] + [NonParallelizable] + public void ActivatingTwiceReplacesTheIdentity() + { + LocalSyslogAppender appender = new() { Identity = "log4net-test-first", Layout = new PatternLayout("%message") }; + appender.ActivateOptions(); + IntPtr first = CurrentIdentityHandle(); + + appender.Identity = "log4net-test-second"; + appender.ActivateOptions(); + IntPtr second = CurrentIdentityHandle(); + + Assert.That(first, Is.Not.EqualTo(IntPtr.Zero)); + Assert.That(second, Is.Not.EqualTo(IntPtr.Zero)); + Assert.That(second, Is.Not.EqualTo(first)); + } + + private static IntPtr CurrentIdentityHandle() + => (IntPtr)typeof(LocalSyslogAppender) + .GetField("_handleToIdentity", BindingFlags.Static | BindingFlags.NonPublic)! + .GetValue(null)!; + + private static string EscapeNulCharacters(string message) + => (string)typeof(LocalSyslogAppender) + .GetMethod("EscapeNulCharacters", BindingFlags.Static | BindingFlags.NonPublic)! + .Invoke(null, [message])!; +} diff --git a/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs b/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs index 99b9c3099..a9f6ed44d 100644 --- a/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs +++ b/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs @@ -26,6 +26,7 @@ using log4net.Core; using log4net.Layout; using log4net.Tests.Appender.Internal; +using log4net.Util; using NUnit.Framework; namespace log4net.Tests.Appender; @@ -117,15 +118,75 @@ public void RemoteSyslogNewLineHandlingSplitTest() Assert.That(Encoding.ASCII.GetString(sentBytes[1]), Is.EqualTo(expectedData1)); } + /// + /// The Identity becomes the TAG of the record. A control character in it would end the record, + /// so that the rest is read as a second record with its own facility and severity. + /// + [Test] + public void IdentityCannotSplitTheRecord() + { + List sentBytes = []; + // The malformed Identity is reported, which is expected here and should not clutter the output. + LogLog.ExecuteWithoutEmittingInternalMessages( + () => sentBytes = ExecuteAppend("Test message", identity: "app\r\n<34>sshd")); + + Assert.That(sentBytes, Has.Count.EqualTo(1)); + const string expectedData = "<14>app<34>sshd: INFO - Test message"; + Assert.That(Encoding.ASCII.GetString(sentBytes[0]), Is.EqualTo(expectedData)); + } + + /// + /// Removing the characters is not enough on its own: a malformed structural identifier is a + /// configuration error and has to be reported rather than quietly repaired. + /// + [Test] + [NonParallelizable] + public void IdentityWithControlCharactersIsReported() + { + List messages = []; + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + using LogLog.LogReceivedAdapter _ = new(messages); + ExecuteAppend("Test message", identity: "app\r\n<34>sshd"); + }); + + Assert.That(messages.ConvertAll(m => m.Message), + Has.Some.Contains("Identity of appender")); + } + + /// + /// An Identity without control characters has to reach the record untouched, including a space, + /// which the application friendly name used by default may well contain. + /// + [Test] + [NonParallelizable] + public void IdentityWithoutControlCharactersIsUnchangedAndNotReported() + { + List messages = []; + List sentBytes = []; + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + using LogLog.LogReceivedAdapter _ = new(messages); + sentBytes = ExecuteAppend("Test message", identity: "My App"); + }); + + Assert.That(sentBytes, Has.Count.EqualTo(1)); + const string expectedData = "<14>My App: INFO - Test message"; + Assert.That(Encoding.ASCII.GetString(sentBytes[0]), Is.EqualTo(expectedData)); + Assert.That(messages.ConvertAll(m => m.Message), Has.None.Contains("Identity of appender")); + } + private static List ExecuteAppend(string message, - RemoteSyslogAppender.SyslogNewLineHandling newLineHandling = default) + RemoteSyslogAppender.SyslogNewLineHandling newLineHandling = default, + string? identity = null) { System.Net.IPAddress ipAddress = new([127, 0, 0, 1]); - RemoteAppender appender = new() - { - RemoteAddress = ipAddress, + RemoteAppender appender = new() + { + RemoteAddress = ipAddress, Layout = new PatternLayout("%-5level - %message"), - NewLineHandling = newLineHandling + NewLineHandling = newLineHandling, + Identity = identity is null ? null : new PatternLayout(identity) }; appender.ActivateOptions(); LoggingEvent loggingEvent = new(new() diff --git a/src/log4net.Tests/Appender/TelnetAppenderTest.cs b/src/log4net.Tests/Appender/TelnetAppenderTest.cs index e8cf95ec5..5d8f37cda 100644 --- a/src/log4net.Tests/Appender/TelnetAppenderTest.cs +++ b/src/log4net.Tests/Appender/TelnetAppenderTest.cs @@ -27,6 +27,7 @@ using log4net.Appender; using log4net.Config; using log4net.Core; +using log4net.Layout; using log4net.Repository; using log4net.Tests.Appender.Internal; using NUnit.Framework; @@ -129,6 +130,84 @@ void WaitForReceived(string what, string expected) } } + /// + /// Writes to a client block while the appender lock is held, so the send timeout has to be + /// finite by default - otherwise a client that stops reading suspends all logging. + /// + [Test] + public void SendTimeoutMillisDefaultsToAFiniteValue() + => Assert.That(new TelnetAppender().SendTimeoutMillis, Is.EqualTo(5000)); + + /// + /// 0 is the documented opt-out that restores blocking indefinitely; a negative timeout has no + /// meaning for and is rejected instead of being silently + /// reinterpreted. + /// + [Test] + public void SendTimeoutMillisRejectsNegativeValuesButAllowsZero() + { + TelnetAppender appender = new(); + + Assert.That(() => appender.SendTimeoutMillis = -1, Throws.TypeOf()); + + appender.SendTimeoutMillis = 0; + Assert.That(appender.SendTimeoutMillis, Is.EqualTo(0)); + + appender.SendTimeoutMillis = 250; + Assert.That(appender.SendTimeoutMillis, Is.EqualTo(250)); + } + + /// + /// The appender accepts connections on every interface unless told otherwise, which is the + /// behaviour it has always had. + /// + [Test] + public void ListenAddressDefaultsToEveryInterface() + => Assert.That(new TelnetAppender().ListenAddress, Is.EqualTo(IPAddress.Any)); + + /// + /// Binding to the loopback address has to keep the port unreachable from other machines, which + /// is what an operator asking for it wants. + /// + [Test] + [NonParallelizable] + public void ListenAddressBindsOnlyThatAddress() + { + int port = FindFreeTcpPort(); + TelnetAppender appender = new() + { + Port = port, + ListenAddress = IPAddress.Loopback, + Layout = new PatternLayout("%message%newline") + }; + appender.ActivateOptions(); + try + { + // The loopback listener accepts a loopback connection. + using (Socket loopback = new(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp)) + { + loopback.Connect(new IPEndPoint(IPAddress.Loopback, port)); + Assert.That(loopback.Connected, Is.True); + } + + // and nothing is listening on the machine's other addresses + IPAddress? routable = Array.Find( + Dns.GetHostAddresses(Dns.GetHostName()), + address => address.AddressFamily == AddressFamily.InterNetwork && !IPAddress.IsLoopback(address)); + if (routable is null) + { + Assert.Ignore("no non-loopback IPv4 address on this machine to test against"); + } + + using Socket external = new(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp); + Assert.That(() => external.Connect(new IPEndPoint(routable!, port)), Throws.TypeOf()); + } + finally + { + appender.Close(); + } + } + /// /// Asks the OS for a currently unused TCP port - a fixed port would collide with /// other tests or processes on the build machine. diff --git a/src/log4net.Tests/Appender/TextWriterAppenderTest.cs b/src/log4net.Tests/Appender/TextWriterAppenderTest.cs new file mode 100644 index 000000000..e9c387c04 --- /dev/null +++ b/src/log4net.Tests/Appender/TextWriterAppenderTest.cs @@ -0,0 +1,116 @@ +#region Apache License +// +// Licensed to the Apache Software Foundation (ASF) under one or more +// contributor license agreements. See the NOTICE file distributed with +// this work for additional information regarding copyright ownership. +// The ASF licenses this file to you under the Apache License, Version 2.0 +// (the "License"); you may not use this file except in compliance with +// the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// +#endregion + +using System; +using System.IO; + +using log4net.Appender; +using log4net.Core; +using log4net.Layout; + +using NUnit.Framework; + +namespace log4net.Tests.Appender; + +/// +/// Tests for +/// +[TestFixture] +public class TextWriterAppenderTest +{ + /// + /// A writer that accepts everything written to it but cannot be flushed, standing in for a full + /// disk or a broken stream. + /// + private sealed class UnflushableWriter : StringWriter + { + /// + public override void Flush() => throw new IOException("Simulated failure to flush"); + } + + /// + /// Swallows what the appender reports, so that the tests observe the return value rather than + /// internal logging. + /// + private sealed class SilentErrorHandler : IErrorHandler + { + /// + public void Error(string message, Exception? e, ErrorCode errorCode) + { } + + /// + public void Error(string message, Exception e) + { } + + /// + public void Error(string message) + { } + } + + /// + /// Flush reported success whatever happened. Its contract is to say whether the events were + /// flushed, and a caller such as a shutdown hook relies on that. + /// + [Test] + public void FlushReportsFailure() + => Assert.That(CreateAppender(new UnflushableWriter()).Flush(1000), Is.False); + + /// + /// A writer that flushes cleanly still has to report success. + /// + [Test] + public void FlushReportsSuccess() + => Assert.That(CreateAppender(new StringWriter()).Flush(1000), Is.True); + + /// + /// A failing flush must not escape to the caller. QuietTextWriter routes failing writes to the + /// ErrorHandler but does not override Flush, so the appender has to catch it. + /// + [Test] + public void FlushDoesNotThrow() + => Assert.That(() => CreateAppender(new UnflushableWriter()).Flush(1000), Throws.Nothing); + + /// + /// With ImmediateFlush there is nothing buffered, so the writer is never touched. + /// + [Test] + public void FlushIsANoOpWhenImmediateFlushIsSet() + { + TextWriterAppender appender = CreateAppender(new UnflushableWriter()); + appender.ImmediateFlush = true; + + Assert.That(appender.Flush(1000), Is.True); + } + + private static TextWriterAppender CreateAppender(TextWriter writer) + { + PatternLayout layout = new("%message%newline"); + layout.ActivateOptions(); + + TextWriterAppender appender = new() + { + Layout = layout, + ImmediateFlush = false, + ErrorHandler = new SilentErrorHandler(), + Writer = writer + }; + appender.ActivateOptions(); + return appender; + } +} diff --git a/src/log4net.Tests/Core/FixingTest.cs b/src/log4net.Tests/Core/FixingTest.cs index 3efe326b2..840431fcc 100644 --- a/src/log4net.Tests/Core/FixingTest.cs +++ b/src/log4net.Tests/Core/FixingTest.cs @@ -22,17 +22,28 @@ using System.Threading; using log4net.Core; +using log4net.Util; using NUnit.Framework; namespace log4net.Tests.Core; +/// +/// Tests for and the fields it captures. +/// [TestFixture] [System.Diagnostics.CodeAnalysis.SuppressMessage("Usage", "CA2201:Do not raise reserved exception types")] public class FixingTest { - const string TestRepository = "Test Repository"; + /// + /// The name of the repository the events under test belong to. + /// + private const string TestRepository = "Test Repository"; + /// + /// Creates the repository the events under test belong to, and names the thread, so that + /// has something stable to capture. + /// [OneTimeSetUp] public void CreateRepository() { @@ -61,8 +72,12 @@ public void CreateRepository() } } + /// + /// has to contain every other flag, so that fixing everything does not + /// quietly leave a field out when a new flag is added. + /// [Test] - public void All_ShouldContainAllFlags() + public void AllContainsEveryFlag() { // Arrange // Act @@ -76,6 +91,9 @@ public void All_ShouldContainAllFlags() } } + /// + /// A newly created event has nothing fixed yet. + /// [Test] public void TestUnfixedValues() { @@ -95,6 +113,9 @@ public void TestUnfixedValues() Assert.That(loggingEvent.Fix, Is.EqualTo(FixFlags.None), "Fixed Fields is incorrect"); } + /// + /// Fixing with reports every field as fixed. + /// [Test] public void TestAllFixedValues() { @@ -116,6 +137,9 @@ public void TestAllFixedValues() Assert.That(loggingEvent.Fix, Is.EqualTo(FixFlags.LocationInfo | FixFlags.UserName | FixFlags.Identity | FixFlags.Partial | FixFlags.Message | FixFlags.ThreadName | FixFlags.Exception | FixFlags.Domain | FixFlags.Properties), "Fixed Fields is incorrect"); } + /// + /// Fixing with leaves the event unfixed. + /// [Test] public void TestNoFixedValues() { @@ -137,6 +161,71 @@ public void TestNoFixedValues() Assert.That(loggingEvent.Fix, Is.EqualTo(FixFlags.None), "Fixed Fields is incorrect"); } + /// + /// Without impersonation the user name is the process identity, which is the same whichever + /// thread asks, so resolving it after the event has been fixed still gives the right answer. An + /// event fixed without must therefore keep reporting it. + /// + [Test] + public void UserNameIsStillResolvedAfterFixingWithoutImpersonation() + { + string expected = CreateEvent().UserName; + LoggingEvent loggingEvent = CreateEvent(); + + // Partial deliberately leaves UserName out, being the documented setting for avoiding its cost. + loggingEvent.Fix = FixFlags.Partial; + + Assert.That(loggingEvent.Fix & FixFlags.UserName, Is.EqualTo(FixFlags.None)); + Assert.That(loggingEvent.UserName, Is.EqualTo(expected)); + Assert.That(loggingEvent.UserName, Is.Not.EqualTo(SystemInfo.NotAvailableText)); + } + + /// + /// Fixing with skips the whole of FixVolatileData but still locks the + /// cache, so the user name has to survive that path too. + /// + [Test] + public void UserNameIsStillResolvedAfterFixingNothing() + { + string expected = CreateEvent().UserName; + LoggingEvent loggingEvent = CreateEvent(); + + loggingEvent.Fix = FixFlags.None; + + Assert.That(loggingEvent.UserName, Is.EqualTo(expected)); + } + + /// + /// Fixing an event with UserName still has to capture it, on the thread that logged the event. + /// + [Test] + public void UserNameIsCapturedWhenItIsFixed() + { + LoggingEvent loggingEvent = CreateEvent(); + + string expected = loggingEvent.UserName; + loggingEvent.Fix = FixFlags.All; + + Assert.That(loggingEvent.UserName, Is.EqualTo(expected)); + Assert.That(loggingEvent.UserName, Is.Not.EqualTo(SystemInfo.NotAvailableText)); + } + + /// + /// Creates an event in the test repository. + /// + /// A new, unfixed event. + private static LoggingEvent CreateEvent() + => new(typeof(FixingTest), + LogManager.GetRepository(TestRepository), + typeof(FixingTest).FullName, + Level.Warn, + "Logging event works", + null); + + /// + /// Builds the event data the tests compare against. + /// + /// Event data with every field set to a known value. private static LoggingEventData BuildStandardEventData() { LoggingEventData loggingEventData = new() @@ -154,6 +243,12 @@ private static LoggingEventData BuildStandardEventData() return loggingEventData; } + /// + /// Asserts that carries the values of + /// . + /// + /// The event to check. + /// The expected values. private static void AssertExpectedLoggingEvent(LoggingEvent loggingEvent, LoggingEventData loggingEventData) { Assert.That(loggingEventData.Domain, Is.EqualTo("ReallySimpleApp"), "Domain is incorrect"); diff --git a/src/log4net.Tests/Core/UserNameFixingTest.cs b/src/log4net.Tests/Core/UserNameFixingTest.cs index 25dfe1ec7..50536c5dd 100644 --- a/src/log4net.Tests/Core/UserNameFixingTest.cs +++ b/src/log4net.Tests/Core/UserNameFixingTest.cs @@ -95,6 +95,49 @@ public void UserNameIsResolvedWhileImpersonating() Assert.That(actual, Is.EqualTo(expected)); } + /// + /// An event logged while impersonating takes the user name with it when it is fixed, even though + /// does not ask for it. Fixing is the last point at which the + /// identity that logged the event is known: a buffering appender reads the property later, from + /// the thread flushing the buffer. + /// + [Test] + public void UserNameIsCapturedWhenFixingAnImpersonatedEvent() + { + using WindowsIdentity identity = WindowsIdentity.GetCurrent(); + string expected = identity.Name; + + LoggingEvent loggingEvent = WindowsIdentity.RunImpersonated(identity.AccessToken, () => + { + LoggingEvent impersonatedEvent = CreateEvent(); + impersonatedEvent.Fix = FixFlags.Partial; + return impersonatedEvent; + }); + + // Read outside the impersonation, as a buffering appender would. + Assert.That(loggingEvent.UserName, Is.EqualTo(expected)); + } + + /// + /// The same holds when nothing at all is fixed, which skips most of FixVolatileData but still + /// locks the cache. + /// + [Test] + public void UserNameIsCapturedWhenFixingNothingOnAnImpersonatedEvent() + { + using WindowsIdentity identity = WindowsIdentity.GetCurrent(); + string expected = identity.Name; + + LoggingEvent loggingEvent = WindowsIdentity.RunImpersonated(identity.AccessToken, () => + { + LoggingEvent impersonatedEvent = CreateEvent(); + impersonatedEvent.Fix = FixFlags.None; + return impersonatedEvent; + }); + + Assert.That(loggingEvent.UserName, Is.EqualTo(expected)); + } + /// /// The process identity name may only be resolved on a thread that is not impersonating. /// Seeding it from an impersonating thread would report that user for every later event in diff --git a/src/log4net.Tests/Filter/StringMatchFilterTest.cs b/src/log4net.Tests/Filter/StringMatchFilterTest.cs new file mode 100644 index 000000000..ff3eced6c --- /dev/null +++ b/src/log4net.Tests/Filter/StringMatchFilterTest.cs @@ -0,0 +1,128 @@ +#region Apache License +// +// Licensed to the Apache Software Foundation (ASF) under one or more +// contributor license agreements. See the NOTICE file distributed with +// this work for additional information regarding copyright ownership. +// The ASF licenses this file to you under the Apache License, Version 2.0 +// (the "License"); you may not use this file except in compliance with +// the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// +#endregion + +using System; +using System.Collections.Generic; +using System.Diagnostics; + +using log4net.Core; +using log4net.Filter; +using log4net.Util; + +using NUnit.Framework; + +namespace log4net.Tests.Filter; + +/// +/// Tests for +/// +[TestFixture] +public class StringMatchFilterTest +{ + /// + /// A pattern that backtracks, with an input that makes it do so. Matching this without a deadline + /// runs for longer than any test would wait. + /// + private const string CatastrophicPattern = "^(a+)+$"; + + private const string CraftedMessage = "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!"; + + /// + /// The match runs while the appender lock is held, so one that backtracks has to be abandoned + /// rather than holding the thread. The event is then left to the rest of the filter chain. + /// + [Test] + public void AMatchThatBacktracksIsAbandoned() + { + StringMatchFilter filter = new() { RegexToMatch = CatastrophicPattern, MatchTimeoutMillis = 100 }; + filter.ActivateOptions(); + + Stopwatch stopwatch = Stopwatch.StartNew(); + FilterDecision decision = FilterDecision.Accept; + LogLog.ExecuteWithoutEmittingInternalMessages(() => decision = filter.Decide(CreateEvent(CraftedMessage))); + stopwatch.Stop(); + + Assert.That(decision, Is.EqualTo(FilterDecision.Neutral)); + Assert.That(stopwatch.Elapsed, Is.LessThan(TimeSpan.FromSeconds(30))); + } + + /// + /// Abandoning the match must not be silent, but it must also not report once per event: the + /// condition repeats for every event that reaches the filter. + /// + [Test] + [NonParallelizable] + public void AnAbandonedMatchIsReportedOnce() + { + StringMatchFilter filter = new() { RegexToMatch = CatastrophicPattern, MatchTimeoutMillis = 100 }; + filter.ActivateOptions(); + + List messages = []; + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + using LogLog.LogReceivedAdapter _ = new(messages); + filter.Decide(CreateEvent(CraftedMessage)); + filter.Decide(CreateEvent(CraftedMessage)); + filter.Decide(CreateEvent(CraftedMessage)); + }); + + Assert.That( + messages.ConvertAll(m => m.Message).FindAll(m => m.IndexOf("was abandoned", StringComparison.Ordinal) >= 0), + Has.Count.EqualTo(1)); + } + + /// + /// A pattern that does not backtrack has to keep working, with the decision unchanged. + /// + [Test] + public void AMatchingPatternStillDecides() + { + StringMatchFilter filter = new() { RegexToMatch = "cat", AcceptOnMatch = true }; + filter.ActivateOptions(); + + Assert.That(filter.Decide(CreateEvent("the cat sat")), Is.EqualTo(FilterDecision.Accept)); + Assert.That(filter.Decide(CreateEvent("the dog sat")), Is.EqualTo(FilterDecision.Neutral)); + } + + /// + /// The deadline has to be finite by default, so that an expensive pattern cannot hold the + /// appender lock indefinitely without the operator having opted into that. + /// + [Test] + public void MatchTimeoutMillisDefaultsToAFiniteValue() + => Assert.That(new StringMatchFilter().MatchTimeoutMillis, Is.EqualTo(1000)); + + /// + /// 0 is the documented opt-out that restores unbounded matching; a negative deadline has no + /// meaning and is rejected rather than being reinterpreted. + /// + [Test] + public void MatchTimeoutMillisRejectsNegativeValuesButAllowsZero() + { + StringMatchFilter filter = new(); + + Assert.That(() => filter.MatchTimeoutMillis = -1, Throws.TypeOf()); + + filter.MatchTimeoutMillis = 0; + Assert.That(filter.MatchTimeoutMillis, Is.EqualTo(0)); + } + + private static LoggingEvent CreateEvent(string message) + => new(new LoggingEventData { Level = Level.Info, Message = message, LoggerName = "TestLogger" }); +} diff --git a/src/log4net.Tests/Util/OnlyOnceErrorHandlerTest.cs b/src/log4net.Tests/Util/OnlyOnceErrorHandlerTest.cs new file mode 100644 index 000000000..a2731edb7 --- /dev/null +++ b/src/log4net.Tests/Util/OnlyOnceErrorHandlerTest.cs @@ -0,0 +1,121 @@ +#region Apache License +// +// Licensed to the Apache Software Foundation (ASF) under one or more +// contributor license agreements. See the NOTICE file distributed with +// this work for additional information regarding copyright ownership. +// The ASF licenses this file to you under the Apache License, Version 2.0 +// (the "License"); you may not use this file except in compliance with +// the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// +#endregion + +using System.Collections.Generic; + +using log4net.Util; + +using NUnit.Framework; + +namespace log4net.Tests.Util; + +/// +/// Used for internal unit testing the class. +/// +[TestFixture] +public class OnlyOnceErrorHandlerTest +{ + /// + /// The first error must reach even when + /// is off, which is the default. An appender that + /// stops delivering events would otherwise leave no trace at all. + /// + [Test] + [NonParallelizable] + public void FirstErrorIsEmittedWithoutInternalDebugging() + { + bool internalDebugging = LogLog.InternalDebugging; + LogLog.InternalDebugging = false; + try + { + List messages = []; + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + using LogLog.LogReceivedAdapter _ = new(messages); + new OnlyOnceErrorHandler("TestAppender").Error("Something went wrong"); + }); + + Assert.That(messages, Has.Count.EqualTo(1)); + Assert.That(messages[0].Message, Does.Contain("Something went wrong")); + } + finally + { + LogLog.InternalDebugging = internalDebugging; + } + } + + /// + /// Only the first error is reported: the handler disables itself afterwards so that a + /// repeatedly failing appender cannot flood the internal log. + /// + [Test] + [NonParallelizable] + public void OnlyTheFirstErrorIsEmitted() + { + bool internalDebugging = LogLog.InternalDebugging; + LogLog.InternalDebugging = false; + try + { + List messages = []; + OnlyOnceErrorHandler handler = new("TestAppender"); + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + using LogLog.LogReceivedAdapter _ = new(messages); + handler.Error("First failure"); + handler.Error("Second failure"); + handler.Error("Third failure"); + }); + + Assert.That(messages, Has.Count.EqualTo(1)); + Assert.That(messages[0].Message, Does.Contain("First failure")); + Assert.That(handler.IsEnabled, Is.False); + } + finally + { + LogLog.InternalDebugging = internalDebugging; + } + } + + /// + /// (the log4net.Internal.Quiet setting) remains the + /// documented way to silence internal messages, including appender errors. + /// + [Test] + [NonParallelizable] + public void QuietModeSuppressesTheError() + { + bool quietMode = LogLog.QuietMode; + LogLog.QuietMode = true; + try + { + List messages = []; + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + using LogLog.LogReceivedAdapter _ = new(messages); + new OnlyOnceErrorHandler("TestAppender").Error("Something went wrong"); + }); + + Assert.That(messages, Is.Empty); + } + finally + { + LogLog.QuietMode = quietMode; + } + } +} diff --git a/src/log4net/Appender/AdoNetAppender.cs b/src/log4net/Appender/AdoNetAppender.cs index 65d3e5463..b4cd22090 100644 --- a/src/log4net/Appender/AdoNetAppender.cs +++ b/src/log4net/Appender/AdoNetAppender.cs @@ -21,6 +21,7 @@ using System.Collections.Generic; using System.Configuration; using System.Data; +using System.Data.Common; using System.IO; using log4net.Util; @@ -243,6 +244,15 @@ public AdoNetAppender() /// If this property is not set, the command text is retrieved by invoking /// . /// + /// + /// Setting this property is strongly recommended. Without it every event is turned into + /// a complete SQL statement by the and executed as + /// it is. Layouts perform no SQL quoting or escaping and offer no way to add it, so any + /// content that reaches a log statement - a user name or a request parameter, for + /// example - is executed as part of the statement, with the privileges of the appender's + /// connection. Use this property together with + /// bindings, which pass the content as database parameters instead. + /// /// public string? CommandText { get; set; } @@ -363,6 +373,17 @@ public override void ActivateOptions() { base.ActivateOptions(); + if (string.IsNullOrWhiteSpace(CommandText)) + { + // Without CommandText every event is turned into a complete SQL statement by the + // Layout and executed as it is. Layouts do not quote or escape anything, so a single + // quote anywhere in the logged content changes the statement that gets executed. + LogLog.Error(_declaringType, + $"AdoNetAppender [{Name}]: CommandText is not configured, so the rendered Layout is executed as the SQL statement. " + + "Layouts perform no SQL quoting, which makes this mode open to SQL injection from logged content. " + + "Configure CommandText together with AdoNetAppenderParameter bindings instead, which pass the content as database parameters."); + } + SecurityContext ??= SecurityContextProvider.DefaultProvider.CreateSecurityContext(this); InitializeDatabaseConnection(); @@ -394,6 +415,8 @@ protected override void OnClose() /// protected override void SendBuffer(LoggingEvent[] events) { + events.EnsureNotNull(); + if (ReconnectOnError && (Connection is null || Connection.State != ConnectionState.Open)) { LogLog.Debug(_declaringType, $"Attempting to reconnect to database. Current Connection State: {((Connection is null) ? SystemInfo.NullText : Connection.State.ToString())}"); @@ -406,30 +429,45 @@ protected override void SendBuffer(LoggingEvent[] events) { if (UseTransactions) { + bool retryPerEvent = false; + // Create transaction // NJC - Do this on 2 lines because it can confuse the debugger - using IDbTransaction dbTran = Connection.BeginTransaction(); - try + using (IDbTransaction dbTran = Connection.BeginTransaction()) { - SendBuffer(dbTran, events); - - // commit transaction - dbTran.Commit(); - } - catch (Exception ex) when (!ex.IsFatal()) - { - // rollback the transaction try { - dbTran.Rollback(); + SendBuffer(dbTran, events); + + // commit transaction + dbTran.Commit(); } - catch (Exception inner) when (!inner.IsFatal()) + catch (Exception ex) when (!ex.IsFatal()) { - // Ignore exception + // rollback the transaction + try + { + dbTran.Rollback(); + } + catch (Exception inner) when (!inner.IsFatal()) + { + // Ignore exception + } + + // Can't insert into the database. That's a bad thing + ErrorHandler.Error("Exception while writing to database", ex); + + retryPerEvent = true; } + } - // Can't insert into the database. That's a bad thing - ErrorHandler.Error("Exception while writing to database", ex); + // The events have already been removed from the buffer, so a rolled back + // transaction would lose all of them - including the events logged before the one + // the database rejected. Retry them one by one, outside the failed transaction, + // so that only the events the database actually rejects are lost. + if (retryPerEvent) + { + SendBufferPerEvent(events); } } else @@ -493,15 +531,26 @@ protected virtual void SendBuffer(IDbTransaction? dbTran, LoggingEvent[] events) // run for all events foreach (LoggingEvent e in events) { - // No need to clear dbCmd.Parameters, just use existing. - // Set the parameter values - foreach (AdoNetAppenderParameter param in m_parameters) + try { - param.FormatValue(dbCmd, e); - } + // No need to clear dbCmd.Parameters, just use existing. + // Set the parameter values + foreach (AdoNetAppenderParameter param in m_parameters) + { + param.FormatValue(dbCmd, e); + } - // Execute the query - dbCmd.ExecuteNonQuery(); + // Execute the query + dbCmd.ExecuteNonQuery(); + } + catch (Exception ex) when (dbTran is null && !ex.IsFatal()) + { + // Without a transaction every event stands alone, so an event the database + // rejects must not stop the remaining events from being written. In transaction + // mode the exception has to propagate - the transaction is in a failed state - + // and SendBuffer retries the events individually after the rollback. + ErrorHandler.Error("Exception while writing a logging event to the database. Continuing with the remaining events.", ex); + } } } else @@ -515,13 +564,61 @@ protected virtual void SendBuffer(IDbTransaction? dbTran, LoggingEvent[] events) // run for all events foreach (LoggingEvent e in events) { - // Get the command text from the Layout - string logStatement = GetLogStatement(e); + try + { + // Get the command text from the Layout + string logStatement = GetLogStatement(e); + + LogLog.Debug(_declaringType, $"LogStatement [{logStatement}]"); + + dbCmd.CommandText = logStatement; + dbCmd.ExecuteNonQuery(); + } + catch (Exception ex) when (dbTran is null && !ex.IsFatal()) + { + // See the parameterized path above: contain per-event failures outside transactions. + ErrorHandler.Error("Exception while writing a logging event to the database. Continuing with the remaining events.", ex); + } + } + } + } - LogLog.Debug(_declaringType, $"LogStatement [{logStatement}]"); + /// + /// Writes each event with its own command, so that an event the database rejects only + /// loses itself. + /// + /// The events to insert into the database. + /// + /// + /// Used as the fallback after a transactional batch failed and was rolled back. The + /// events are sent without a transaction and failures are reported to the + /// without affecting the remaining events. + /// + /// + /// Note that this makes delivery at-least-once rather than exactly-once: if the batch + /// failed after the database had already applied some of its statements - for example + /// when the commit itself failed but the rollback did not take effect - those events are + /// written a second time here. Duplicated events are preferred over silently losing the + /// whole buffer. + /// + /// + private void SendBufferPerEvent(LoggingEvent[] events) + { + foreach (LoggingEvent e in events) + { + if (Connection is not { State: ConnectionState.Open }) + { + // The connection failed rather than a single event - nothing more can be written. + return; + } - dbCmd.CommandText = logStatement; - dbCmd.ExecuteNonQuery(); + try + { + SendBuffer(null, [e]); + } + catch (Exception ex) when (!ex.IsFatal()) + { + ErrorHandler.Error("Exception while writing a logging event to the database. The event has been dropped.", ex); } } } @@ -546,8 +643,16 @@ protected virtual void Prepare(IDbCommand dbCmd) /// /// The event being logged. /// - /// This method can be overridden by subclasses to provide + /// + /// This method can be overridden by subclasses to provide /// more control over the format of the database statement. + /// + /// + /// The returned text is executed as the SQL statement without any quoting, so an override + /// that interpolates event content has to escape that content itself. Prefer configuring + /// with bindings over + /// generating statement text here. + /// /// /// /// Text that can be passed to a . @@ -684,12 +789,65 @@ private void InitializeDatabaseConnection() catch (Exception e) when (!e.IsFatal()) { // Sadly, your connection string is bad. - ErrorHandler.Error($"Could not open database connection [{resolvedConnectionString}]. Connection string context [{connectionStringContext}].", e); + ErrorHandler.Error($"Could not open database connection [{RedactConnectionString(resolvedConnectionString)}]. Connection string context [{connectionStringContext}].", e); Connection = null; } } + /// + /// Replaces the values of password-bearing keywords in a connection string with + /// , so that it can be named in a diagnostic message. + /// + /// The connection string to redact. + /// + /// The connection string with every password value replaced, or if it + /// could not be parsed. + /// + private static string RedactConnectionString(string connectionString) + { + if (string.IsNullOrEmpty(connectionString)) + { + return connectionString; + } + + try + { + DbConnectionStringBuilder builder = new() { ConnectionString = connectionString }; + + List keys = []; + foreach (string key in builder.Keys) + { + keys.Add(key); + } + + foreach (string key in keys) + { + // Providers spell the secret differently - Password, PWD, User Password - so match on + // the keyword rather than on a fixed list. + if (key.IndexOf("password", StringComparison.OrdinalIgnoreCase) >= 0 + || key.Equals("pwd", StringComparison.OrdinalIgnoreCase)) + { + builder[key] = RedactedValue; + } + } + + return builder.ConnectionString; + } + catch (Exception e) when (!e.IsFatal()) + { + // The connection string could not be parsed - which is likely, given that it just failed + // to connect - so redact all of it rather than risk echoing a password. + LogLog.Debug(_declaringType, "Could not parse the connection string in order to redact it", e); + return RedactedValue; + } + } + + /// + /// Stands in for a password in diagnostic messages. + /// + private const string RedactedValue = "*****"; + /// /// Cleanup the existing connection. /// diff --git a/src/log4net/Appender/FileAppender.cs b/src/log4net/Appender/FileAppender.cs index 993e2974e..5887fbfe7 100644 --- a/src/log4net/Appender/FileAppender.cs +++ b/src/log4net/Appender/FileAppender.cs @@ -576,6 +576,42 @@ public class InterProcessLock : LockingModelBase private Mutex? _mutex; private Stream? _stream; private int _recursiveWatch; + private int _lockTimeoutMillis = 10_000; + + /// + /// Gets or sets the time, in milliseconds, to wait for the lock before giving up on an event. + /// + /// + /// A number of milliseconds, 0 to fail immediately when the lock is held, or + /// to wait for as long as it takes. + /// + /// + /// + /// The wait happens while the appender lock is held, so a lock nobody releases would otherwise + /// suspend every thread logging through this appender. An event that cannot get the lock in + /// time is reported and dropped instead. + /// + /// + /// The default value is 10000. Raise it when the file is on storage where the lock is + /// legitimately slow to obtain, such as a network share. + /// + /// + /// + /// The value specified is negative and is not . + /// + public int LockTimeoutMillis + { + get => _lockTimeoutMillis; + set + { + if (value < 0 && value != Timeout.Infinite) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + $"The value specified for LockTimeoutMillis is negative and is not {nameof(Timeout)}.{nameof(Timeout.Infinite)}."); + } + _lockTimeoutMillis = value; + } + } /// /// Open the file specified and prepare for logging. @@ -641,8 +677,23 @@ public override void CloseFile() { if (_mutex is not null) { - // TODO: add timeout? - _mutex.WaitOne(); + bool acquired; + try + { + acquired = _mutex.WaitOne(LockTimeoutMillis); + } + catch (AbandonedMutexException) + { + // Previous owner died without releasing; the wait succeeded and we own the mutex. + acquired = true; + } + + if (!acquired) + { + CurrentAppender?.ErrorHandler.Error( + $"Timeout after {LockTimeoutMillis}ms waiting for the inter process lock on the log file, so the logging event was not written."); + return null; + } // increment recursive watch _recursiveWatch++; diff --git a/src/log4net/Appender/LocalSyslogAppender.cs b/src/log4net/Appender/LocalSyslogAppender.cs index df481c466..6c946a1be 100644 --- a/src/log4net/Appender/LocalSyslogAppender.cs +++ b/src/log4net/Appender/LocalSyslogAppender.cs @@ -308,10 +308,32 @@ public override void ActivateOptions() // create the native heap ansi string. Note this is a copy of our string // so we do not need to hold on to the string itself, holding on to the // handle will keep the heap ansi string alive. - _handleToIdentity = Marshal.StringToHGlobalAnsi(identString); + IntPtr identity = Marshal.StringToHGlobalAnsi(identString); - // open syslog - NativeMethods.openlog(_handleToIdentity, 1, Facility); + lock (_syslogSyncRoot) + { + IntPtr replaced = _handleToIdentity; + try + { + // open syslog + NativeMethods.openlog(identity, 1, Facility); + } + catch + { + Marshal.FreeHGlobal(identity); + throw; + } + + _handleToIdentity = identity; + + // Only now that openlog points at the new string. Freeing it before would leave libc + // dereferencing it for every record, and not freeing it at all leaked one buffer per call, + // which ActivateOptions may be called repeatedly. + if (replaced != IntPtr.Zero) + { + Marshal.FreeHGlobal(replaced); + } + } } /// @@ -331,7 +353,7 @@ public override void ActivateOptions() protected override void Append(LoggingEvent loggingEvent) { int priority = GeneratePriority(Facility, GetSeverity(loggingEvent.EnsureNotNull().Level)); - string message = RenderLoggingEvent(loggingEvent); + string message = EscapeNulCharacters(RenderLoggingEvent(loggingEvent)); // Call the local libc syslog method // The second argument is a printf style format string @@ -339,11 +361,32 @@ protected override void Append(LoggingEvent loggingEvent) } /// - /// Close the syslog when the appender is closed + /// Replaces NUL characters with a visible \0 escape. /// + /// The rendered message. + /// The message with every NUL character escaped. /// /// + /// The message is marshaled to libc as a null-terminated string, so a NUL character anywhere in + /// it would end the record there and silently drop everything the layout rendered after it, + /// including trailing fields and exception text. Logged content is not trusted and may well + /// contain a NUL, so the character is escaped rather than passed through. + /// + /// + /// Other control characters are left alone: syslog(3) encodes them itself, and newlines + /// are needed for the multi-line output an exception layout produces. + /// + /// + private static string EscapeNulCharacters(string message) + => message.IndexOf('\0') < 0 ? message : message.Replace("\0", "\\0"); + + /// /// Close the syslog when the appender is closed + /// + /// + /// + /// closelog applies to the process rather than to this instance, so closing one appender + /// ends the syslog connection for every other instance as well. A later record reopens it. /// /// [System.Security.SecuritySafeCritical] @@ -361,11 +404,9 @@ protected override void OnClose() // Ignore dll not found at this point } - if (_handleToIdentity != IntPtr.Zero) - { - // free global ident - Marshal.FreeHGlobal(_handleToIdentity); - } + // The identity is deliberately not freed. openlog registered it for the whole process, so it + // outlives this appender: another instance may still be logging through it. ActivateOptions + // replaces it rather than letting them accumulate. } /// @@ -432,11 +473,24 @@ private static int GeneratePriority(SyslogFacility facility, SyslogSeverity seve => ((int)facility * 8) + (int)severity; /// - /// Marshaled handle to the identity string. We have to hold on to the - /// string as the openlog and syslog APIs just hold the + /// Marshaled handle to the identity string currently registered with openlog. + /// + /// + /// + /// We have to hold on to the string as the openlog and syslog APIs just hold the /// pointer to the ident and dereference it for each log message. + /// + /// + /// The registration belongs to the process rather than to an instance, so this is static: a + /// second appender replaces the identity of the first instead of adding one. + /// + /// + private static IntPtr _handleToIdentity = IntPtr.Zero; + + /// + /// Guards against two appenders being activated at once. /// - private IntPtr _handleToIdentity = IntPtr.Zero; + private static readonly object _syslogSyncRoot = new(); /// /// Mapping from level object to syslog severity diff --git a/src/log4net/Appender/RemoteSyslogAppender.cs b/src/log4net/Appender/RemoteSyslogAppender.cs index 8b5b21ea2..3d30c5262 100644 --- a/src/log4net/Appender/RemoteSyslogAppender.cs +++ b/src/log4net/Appender/RemoteSyslogAppender.cs @@ -364,7 +364,7 @@ protected override void Append(LoggingEvent loggingEvent) int priority = GeneratePriority(Facility, GetSeverity(loggingEvent.Level)); // Identity - string? identity = Identity?.Format(loggingEvent) ?? loggingEvent.Domain; + string? identity = ValidateIdentity(Identity?.Format(loggingEvent) ?? loggingEvent.Domain); // Message. The message goes after the tag/identity string message = RenderLoggingEvent(loggingEvent); @@ -400,6 +400,64 @@ protected override void Append(LoggingEvent loggingEvent) } } + /// + /// Checks that is usable as the TAG part of a syslog record, and + /// reports it through the when it is not. + /// + /// The formatted . + /// + /// The identity, with any control character removed. + /// + /// + /// + /// The TAG is a structural identifier and therefore expected to be a constant chosen by the + /// developer or operator, not something derived from a logging event. A malformed one is a + /// configuration error rather than untrusted input, so it is reported instead of being altered + /// silently: a carriage return or line feed in the TAG would split the record and let the text + /// after it be read as a second record with its own facility and severity. + /// + /// + /// The offending characters are removed rather than the event being dropped, so that an + /// pattern which does contain event data cannot be used to suppress + /// records. + /// + /// + private string? ValidateIdentity(string? identity) + { + if (identity is null) + { + return null; + } + + StringBuilder? sanitized = null; + for (int i = 0; i < identity.Length; i++) + { + // Control characters only. A carriage return or line feed ends the record, so the text + // after it is read as a record of its own. Printable characters are left alone, including + // the space that an application friendly name may contain, because they cannot break the + // record apart. + if (identity[i] is >= ' ' and not (char)127) + { + sanitized?.Append(identity[i]); + } + else + { + sanitized ??= new StringBuilder(identity.Length).Append(identity, 0, i); + } + } + + if (sanitized is null) + { + return identity; + } + + ErrorHandler.Error( + $"The Identity of appender [{Name}] rendered control characters, which would have split the syslog record, and they were removed. " + + "Identity is a structural identifier and is expected to be a constant rather than a pattern that renders logging event data."); + + return sanitized.ToString(); + } + /// /// Appends the rendered message to the buffer /// diff --git a/src/log4net/Appender/RollingFileAppender.cs b/src/log4net/Appender/RollingFileAppender.cs index 55b300789..a15e8f979 100644 --- a/src/log4net/Appender/RollingFileAppender.cs +++ b/src/log4net/Appender/RollingFileAppender.cs @@ -518,10 +518,32 @@ protected override void Append(LoggingEvent[] loggingEvents) protected virtual void AdjustFileBeforeAppend() { // reuse the file appenders locking model to lock the rolling + bool acquired = false; try { // if rolling should be locked, acquire the lock - _mutexForRolling?.WaitOne(); + if (_mutexForRolling is not null) + { + try + { + acquired = _mutexForRolling.WaitOne(LockTimeoutMillis); + } + catch (AbandonedMutexException) + { + // Previous owner died without releasing; the wait succeeded and we own the mutex. + acquired = true; + } + + if (!acquired) + { + // Rolling without the lock would race another process renaming the same files, so append + // to the current file instead of waiting, which would suspend every logging thread. + ErrorHandler.Error( + $"Timeout after {LockTimeoutMillis}ms waiting for the lock on rolling {File}, so this event was written without checking whether the file should roll."); + return; + } + } + if (_rollDate) { DateTime n = DateTimeStrategy.Now; @@ -541,8 +563,11 @@ protected virtual void AdjustFileBeforeAppend() } finally { - // if rolling should be locked, release the lock - _mutexForRolling?.ReleaseMutex(); + // Only when the wait succeeded: releasing a mutex this thread does not own throws. + if (acquired) + { + _mutexForRolling!.ReleaseMutex(); + } } } @@ -1516,6 +1541,39 @@ protected static DateTime NextCheckDate(DateTime currentDateTime, RollPoint roll /// private Mutex? _mutexForRolling; + private int _lockTimeoutMillis = 10_000; + + /// + /// Gets or sets the time, in milliseconds, to wait for the rolling lock before appending without + /// checking whether the file should roll. + /// + /// + /// A number of milliseconds, 0 to give up immediately when the lock is held, or + /// to wait for as long as it takes. + /// + /// + /// + /// The wait happens while the appender lock is held, so a lock nobody releases would otherwise + /// suspend every thread logging through this appender. The default value is 10000. + /// + /// + /// + /// The value specified is negative and is not . + /// + public int LockTimeoutMillis + { + get => _lockTimeoutMillis; + set + { + if (value < 0 && value != Timeout.Infinite) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + $"The value specified for LockTimeoutMillis is negative and is not {nameof(Timeout)}.{nameof(Timeout.Infinite)}."); + } + _lockTimeoutMillis = value; + } + } + /// /// The 1st of January 1970 in UTC /// diff --git a/src/log4net/Appender/TelnetAppender.cs b/src/log4net/Appender/TelnetAppender.cs index adb4cdae9..a0b04e131 100644 --- a/src/log4net/Appender/TelnetAppender.cs +++ b/src/log4net/Appender/TelnetAppender.cs @@ -40,6 +40,13 @@ namespace log4net.Appender; /// /// The default is 23 (the telnet port). /// +/// +/// This appender is a diagnostic tool for trusted networks. As with any other appender +/// destination, the connecting client is trusted: enabling the appender declares that whoever can +/// reach the port may read the application's log, so no authentication is performed and the stream +/// is not encrypted. Keeping untrusted parties away from the port is the operator's +/// responsibility, exactly as it is for a log file. +/// /// /// Keith Long /// Nicko Cadell @@ -47,6 +54,29 @@ public class TelnetAppender : AppenderSkeleton { private SocketHandler? _handler; private int _listeningPort = 23; + private int _sendTimeoutMillis = 5_000; + private IPAddress _listenAddress = IPAddress.Any; + + /// + /// Gets or sets the address to listen on. + /// + /// + /// The local address to accept connections on. The default is , every + /// interface of the machine. + /// + /// + /// + /// Set this to to accept connections only from the machine the + /// application runs on, which is what the diagnostic use this appender is meant for usually + /// needs. + /// + /// + /// The value specified is . + public IPAddress ListenAddress + { + get => _listenAddress; + set => _listenAddress = value.EnsureNotNull(); + } /// /// The fully qualified type of the TelnetAppender class. @@ -85,6 +115,42 @@ public int Port } } + /// + /// Gets or sets the time, in milliseconds, that a write to a client may block before that + /// client is treated as dead and disconnected. + /// + /// + /// A positive number of milliseconds, or 0 to block indefinitely. + /// + /// + /// + /// Clients are written to synchronously while the appender lock is held, so a client that + /// connects and then stops reading lets TCP flow control fill its receive window and the + /// server send buffer. Without a timeout the next write blocks forever and suspends every + /// thread that logs through this appender. + /// + /// + /// The default value is 5000 (5 seconds). A write that exceeds it fails with a + /// , and the client is then disconnected like any other dead + /// connection. Setting the value to 0 restores the previous behavior of blocking + /// indefinitely and is not recommended. + /// + /// + /// The value specified is negative. + public int SendTimeoutMillis + { + get => _sendTimeoutMillis; + set + { + if (value < 0) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + "The value specified for SendTimeoutMillis is negative."); + } + _sendTimeoutMillis = value; + } + } + /// /// Overrides the parent method to close the socket handler /// @@ -114,8 +180,8 @@ public override void ActivateOptions() base.ActivateOptions(); try { - LogLog.Debug(_declaringType, $"Creating SocketHandler to listen on port [{_listeningPort}]"); - _handler = new SocketHandler(_listeningPort); + LogLog.Debug(_declaringType, $"Creating SocketHandler to listen on [{_listenAddress}]:[{_listeningPort}]"); + _handler = new SocketHandler(_listenAddress, _listeningPort, _sendTimeoutMillis); } catch (Exception ex) { @@ -151,6 +217,7 @@ protected class SocketHandler : IDisposable private const int MaxConnections = 20; private readonly Socket _serverSocket; + private readonly int _sendTimeoutMillis; private readonly List _clients = []; private readonly object _syncRoot = new(); private bool _wasDisposed; @@ -238,13 +305,47 @@ public void Dispose() /// the local port to listen on for connections /// /// - /// Creates a socket handler on the specified local server port. + /// Creates a socket handler on the specified local server port, blocking indefinitely on + /// clients that stop reading. Prefer . /// /// public SocketHandler(int port) + : this(port, 0) + { } + + /// + /// Opens a new server port on + /// + /// the local port to listen on for connections + /// the time, in milliseconds, that a write to a client may + /// block before that client is disconnected, or 0 to block indefinitely + /// + /// + /// Creates a socket handler on the specified local server port. + /// + /// + public SocketHandler(int port, int sendTimeoutMillis) + : this(IPAddress.Any, port, sendTimeoutMillis) + { } + + /// + /// Opens a new server port on of + /// + /// the local address to accept connections on + /// the local port to listen on for connections + /// the time, in milliseconds, that a write to a client may + /// block before that client is disconnected, or 0 to block indefinitely + /// + /// + /// Creates a socket handler on the specified local address and server port. + /// + /// + public SocketHandler(IPAddress listenAddress, int port, int sendTimeoutMillis) { - _serverSocket = new(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp); - _serverSocket.Bind(new IPEndPoint(IPAddress.Any, port)); + _sendTimeoutMillis = sendTimeoutMillis; + // The address decides the family, so that an IPv6 address does not end up on an IPv4 socket. + _serverSocket = new(listenAddress.EnsureNotNull().AddressFamily, SocketType.Stream, ProtocolType.Tcp); + _serverSocket.Bind(new IPEndPoint(listenAddress, port)); _serverSocket.Listen(5); AcceptConnection(); } @@ -332,6 +433,14 @@ private void OnConnect(IAsyncResult asyncResult) // Block until a client connects Socket socket = _serverSocket.EndAccept(asyncResult); LogLog.Debug(_declaringType, $"Accepting connection from [{socket.RemoteEndPoint}]"); + if (_sendTimeoutMillis > 0) + { + // Bound how long a write to this client can block. Clients are written to while the + // appender lock is held, so without a timeout a client that stops reading suspends + // every thread that logs. A timed-out write throws and the client is then evicted + // like any other dead connection. + socket.SendTimeout = _sendTimeoutMillis; + } SocketClient client = new(socket); // clients.Count is an atomic read that can be done outside the lock. diff --git a/src/log4net/Appender/TextWriterAppender.cs b/src/log4net/Appender/TextWriterAppender.cs index 046476c54..7fba8d214 100644 --- a/src/log4net/Appender/TextWriterAppender.cs +++ b/src/log4net/Appender/TextWriterAppender.cs @@ -89,7 +89,7 @@ public virtual TextWriter? Writer get => QuietWriter; set { - lock (_syncRoot) + lock (LockObj) { Reset(); if (value is not null) @@ -204,7 +204,7 @@ protected override void Append(LoggingEvent[] loggingEvents) /// protected override void OnClose() { - lock (_syncRoot) + lock (LockObj) { Reset(); } @@ -222,7 +222,7 @@ public override IErrorHandler ErrorHandler get => base.ErrorHandler; set { - lock (_syncRoot) + lock (LockObj) { if (value is null) { @@ -357,8 +357,6 @@ protected virtual void PrepareWriter() /// protected QuietTextWriter? QuietWriter { get; set; } - private readonly object _syncRoot = new(); - /// /// The fully qualified type of the TextWriterAppender class. /// @@ -381,10 +379,21 @@ public override bool Flush(int millisecondsTimeout) return true; } - // lock(this) will block any Appends while the buffer is flushed. - lock (_syncRoot) + // Taking the appender lock blocks any Append while the buffer is flushed. QuietTextWriter is + // not thread safe, and Append holds this same lock through DoAppend. + lock (LockObj) { - QuietWriter?.Flush(); + try + { + QuietWriter?.Flush(); + } + catch (Exception e) when (!e.IsFatal()) + { + // QuietTextWriter routes failing writes to the ErrorHandler but does not override Flush, + // so a failure here would otherwise escape to the caller of Flush. + ErrorHandler.Error($"Failed to flush appender [{Name}].", e, ErrorCode.FlushFailure); + return false; + } } return true; diff --git a/src/log4net/Config/XmlConfigurator.cs b/src/log4net/Config/XmlConfigurator.cs index e7ffd2db5..ece21ae45 100644 --- a/src/log4net/Config/XmlConfigurator.cs +++ b/src/log4net/Config/XmlConfigurator.cs @@ -491,6 +491,20 @@ private static void InternalConfigure(ILoggerRepository repository, Uri? configU } else { + // The URI is not restricted to a particular scheme and the request below is sent with the + // process credentials. Both are intentional and are not vulnerabilities: + // + // Configuration is operator-supplied and therefore trusted, and the endpoint named here is + // part of that configuration - it is trusted for the same reason an appender destination + // is. Ensuring that configuration is transmitted only over a confidential channel, and + // that the endpoint is one the credentials may be presented to, is a deployer + // responsibility. Nothing here is reachable until an operator supplies a URI, either by + // calling Configure(Uri) or through the log4net.Config appSetting. + // + // See the Apache Logging Services common threat model, sections "Configuration + // (operator-controlled)" and "Adversary capabilities": + // https://raw.githubusercontent.com/apache/logging-site/refs/heads/main/src/site/antora/modules/ROOT/pages/_threat-model-common.adoc + // NETCF dose not support WebClient WebRequest? configRequest = null; @@ -749,6 +763,10 @@ private static void InternalConfigureAndWatch(ILoggerRepository repository, File /// private sealed class ConfigureAndWatchHandler : IDisposable { + // The replaced file is reloaded without re-checking its origin. Keeping the watched file + // writable only by the operator is a deployer responsibility, see + // https://raw.githubusercontent.com/apache/logging-site/refs/heads/main/src/site/antora/modules/ROOT/pages/_threat-model-common.adoc + /// /// Holds the FileInfo used to configure the XmlConfigurator /// diff --git a/src/log4net/Core/LoggingEvent.cs b/src/log4net/Core/LoggingEvent.cs index 016473fa2..4f7c852ee 100644 --- a/src/log4net/Core/LoggingEvent.cs +++ b/src/log4net/Core/LoggingEvent.cs @@ -735,8 +735,63 @@ private static string ReviseThreadName(string? threadName) /// rather than the Windows account the request happens to run as. /// /// - public string UserName => - _data.UserName ??= TryGetCurrentUserName() ?? SystemInfo.NotAvailableText; + public string UserName + { + get + { + if (_data.UserName is null) + { + // Resolving late gives the process identity, which is the same on every thread. On an + // impersonating thread it would give whoever is reading the event instead, so nothing is + // reported; FixVolatileData captures that case up front. + if (_cacheUpdatable || !IsImpersonating()) + { + _data.UserName = TryGetCurrentUserName() ?? SystemInfo.NotAvailableText; + } + } + + return _data.UserName ?? SystemInfo.NotAvailableText; + } + } + + /// + /// Whether the calling thread is impersonating another identity. + /// + /// + /// when the thread runs as an impersonated identity rather than as the + /// process identity, and when it does not or when that cannot be known. + /// + /// + /// + /// Only queries the thread token. Resolving the name behind it is the expensive part and is left + /// to . + /// + /// + private static bool IsImpersonating() + { + try + { + if (_windowsIdentityUnavailable) + { + return false; + } + + if (!IsWindowsIdentitySupported()) + { + _windowsIdentityUnavailable = true; + return false; + } + + using WindowsIdentity? impersonated = WindowsIdentity.GetCurrent(ifImpersonating: true); + return impersonated is not null; + } + catch (Exception e) when (!e.IsFatal()) + { + // As in TryGetCurrentUserName: an unreadable identity must not break logging. + _windowsIdentityUnavailable = true; + return false; + } + } private static string? TryGetCurrentUserName() { @@ -1156,6 +1211,15 @@ protected virtual void FixVolatileData(FixFlags flags) } } + // Last point at which the identity that logged the event is known, so grab it even when it was + // not asked for. Outside the block above, which is skipped when there is nothing to fix while + // the cache is locked all the same. FixFlags.UserName stays unset: the flags report what the + // caller requested. + if (_data.UserName is null && IsImpersonating()) + { + _data.UserName = TryGetCurrentUserName() ?? SystemInfo.NotAvailableText; + } + // Finally lock everything we've cached. _cacheUpdatable = false; } diff --git a/src/log4net/Filter/PropertyFilter.cs b/src/log4net/Filter/PropertyFilter.cs index cef49c75f..c487682b0 100644 --- a/src/log4net/Filter/PropertyFilter.cs +++ b/src/log4net/Filter/PropertyFilter.cs @@ -95,7 +95,7 @@ public override FilterDecision Decide(LoggingEvent loggingEvent) if (m_regexToMatch is not null) { // Check the regex - if (m_regexToMatch.Match(msg).Success == false) + if (!IsRegexMatch(msg)) { // No match, continue processing return FilterDecision.Neutral; diff --git a/src/log4net/Filter/StringMatchFilter.cs b/src/log4net/Filter/StringMatchFilter.cs index e7819913b..d0c79c428 100644 --- a/src/log4net/Filter/StringMatchFilter.cs +++ b/src/log4net/Filter/StringMatchFilter.cs @@ -17,6 +17,7 @@ // #endregion +using System; using System.Text.RegularExpressions; using log4net.Core; @@ -53,14 +54,92 @@ public class StringMatchFilter : FilterSkeleton /// must be called again. /// /// - public override void ActivateOptions() + public override void ActivateOptions() { if (RegexToMatch is not null) { - m_regexToMatch = new(RegexToMatch, RegexOptions.Compiled); + m_regexToMatch = new(RegexToMatch, RegexOptions.Compiled, + _matchTimeoutMillis == 0 + ? Regex.InfiniteMatchTimeout + : TimeSpan.FromMilliseconds(_matchTimeoutMillis)); } } + /// + /// Gets or sets the time, in milliseconds, that matching against a + /// single event may take before the match is abandoned. + /// + /// + /// A positive number of milliseconds, or 0 to let a match run for as long as it takes. + /// + /// + /// + /// A regular expression that backtracks can take a very long time on some inputs. The pattern is + /// matched while the appender lock is held, so an unbounded match would stall everything logging + /// through the appender, and matching is therefore given a deadline. A match that reaches it is + /// treated as no match, leaving the rest of the filter chain to decide. + /// + /// + /// The pattern comes from configuration and is trusted, so this is a guard against a pattern that + /// turns out to be expensive rather than protection against untrusted input. + /// + /// + /// The default value is 1000 (one second). Setting the value to 0 restores unbounded matching and + /// is not recommended. Changing it takes effect when is called. + /// + /// + /// The value specified is negative. + public int MatchTimeoutMillis + { + get => _matchTimeoutMillis; + set + { + if (value < 0) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + "The value specified for MatchTimeoutMillis is negative."); + } + _matchTimeoutMillis = value; + } + } + + private int _matchTimeoutMillis = 1000; + private bool _matchTimeoutReported; + + /// + /// Matches against . + /// + /// The text to match. + /// + /// when the pattern matches, and when it does not + /// or when matching took longer than . + /// + protected bool IsRegexMatch(string value) + { + try + { + return m_regexToMatch!.IsMatch(value); + } + catch (RegexMatchTimeoutException) + { + if (!_matchTimeoutReported) + { + // Once per filter. The condition repeats for every event that reaches it, and a warning + // per event would be a denial of service of its own. + _matchTimeoutReported = true; + LogLog.Warn(_declaringType, + $"Matching the pattern [{RegexToMatch}] took longer than {MatchTimeoutMillis}ms and was abandoned, so the event was not filtered by it. " + + "A pattern that backtracks can take arbitrarily long on some inputs; consider rewriting it or raising MatchTimeoutMillis."); + } + return false; + } + } + + /// + /// The fully qualified type of the class. + /// + private static readonly Type _declaringType = typeof(StringMatchFilter); + /// /// when matching or /// @@ -144,11 +223,11 @@ public override FilterDecision Decide(LoggingEvent loggingEvent) if (m_regexToMatch is not null) { // Check the regex - if (m_regexToMatch.Match(msg).Success == false) + if (!IsRegexMatch(msg)) { // No match, continue processing return FilterDecision.Neutral; - } + } // we've got a match if (AcceptOnMatch) diff --git a/src/log4net/Repository/Hierarchy/XmlHierarchyConfigurator.cs b/src/log4net/Repository/Hierarchy/XmlHierarchyConfigurator.cs index c65b719bc..32df0c2d0 100644 --- a/src/log4net/Repository/Hierarchy/XmlHierarchyConfigurator.cs +++ b/src/log4net/Repository/Hierarchy/XmlHierarchyConfigurator.cs @@ -270,6 +270,9 @@ public void Configure(XmlElement? element) /// protected IAppender? ParseAppender(XmlElement appenderElement) { + // Configuration names the types to load and instantiate. This is by design: configuration is + // trusted input, see + // https://raw.githubusercontent.com/apache/logging-site/refs/heads/main/src/site/antora/modules/ROOT/pages/_threat-model-common.adoc string appenderName = appenderElement.EnsureNotNull().GetAttribute(NameAttr); string typeName = appenderElement.GetAttribute(TypeAttr); @@ -564,6 +567,8 @@ protected void SetParameter(XmlElement element, object target) MethodInfo? methInfo = null; // Try to find a writable property + // Non-public members are reachable on purpose: configuration is trusted input, see + // https://raw.githubusercontent.com/apache/logging-site/refs/heads/main/src/site/antora/modules/ROOT/pages/_threat-model-common.adoc PropertyInfo? propInfo = targetType.GetProperty(name, BindingFlags.Instance | BindingFlags.Public | BindingFlags.NonPublic | BindingFlags.IgnoreCase); if (propInfo is not null && propInfo.CanWrite) { diff --git a/src/log4net/Util/OnlyOnceErrorHandler.cs b/src/log4net/Util/OnlyOnceErrorHandler.cs index d0c9ebe27..909529b22 100644 --- a/src/log4net/Util/OnlyOnceErrorHandler.cs +++ b/src/log4net/Util/OnlyOnceErrorHandler.cs @@ -114,10 +114,11 @@ public virtual void FirstError(string message, Exception? e, ErrorCode errorCode ErrorMessage = message; IsEnabled = false; - if (LogLog.InternalDebugging && !LogLog.QuietMode) - { - LogLog.Error(_declaringType, "[" + _prefix + "] ErrorCode: " + errorCode.ToString() + ". " + message, e); - } + // Emit the first error unconditionally so that an appender which silently stopped + // delivering events leaves a trace in a default configuration. LogLog.Error already + // honors LogLog.QuietMode (log4net.Internal.Quiet) and LogLog.EmitInternalMessages, + // which remain the documented ways to silence internal messages. + LogLog.Error(_declaringType, "[" + _prefix + "] ErrorCode: " + errorCode.ToString() + ". " + message, e); } /// diff --git a/src/log4net/Util/SystemStringFormat.cs b/src/log4net/Util/SystemStringFormat.cs index 0d19571e6..68121368e 100644 --- a/src/log4net/Util/SystemStringFormat.cs +++ b/src/log4net/Util/SystemStringFormat.cs @@ -82,7 +82,10 @@ public sealed class SystemStringFormat(IFormatProvider? provider, string format, return format; } - // Try to format the string + // An alignment such as "{0,2000000000}" allocates before anything can reject it, and the + // OutOfMemoryException is fatal and escapes the catch below. Not guarded against: the format + // string is trusted developer input, see + // https://raw.githubusercontent.com/apache/logging-site/refs/heads/main/src/site/antora/modules/ROOT/pages/_threat-model-common.adoc return string.Format(provider, format, args); } catch (Exception e) when (!e.IsFatal()) diff --git a/src/site/antora/modules/ROOT/nav.adoc b/src/site/antora/modules/ROOT/nav.adoc index 8aadc37df..c6f993eee 100644 --- a/src/site/antora/modules/ROOT/nav.adoc +++ b/src/site/antora/modules/ROOT/nav.adoc @@ -38,6 +38,7 @@ **** xref:manual/configuration/appenders/rollingfileappender.adoc[] **** xref:manual/configuration/appenders/smtpappender.adoc[] **** xref:manual/configuration/appenders/smtppickupdirappender.adoc[] +**** xref:manual/configuration/appenders/telnetappender.adoc[] **** xref:manual/configuration/appenders/traceappender.adoc[] **** xref:manual/configuration/appenders/udpappender.adoc[] *** xref:manual/configuration/filters.adoc[] diff --git a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders.adoc b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders.adoc index e2e0c18a2..d5cf4bae9 100644 --- a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders.adoc @@ -97,8 +97,9 @@ The MailKit based appender from the `log4net.Ext.Mail` package is recommended; t |xref:manual/configuration/appenders/smtppickupdirappender.adoc[] |Sends logging events to an email address but writes the emails to a configurable directory rather than sending them directly via SMTP. -|TelnetAppender +|xref:manual/configuration/appenders/telnetappender.adoc[] |*Clients* connect via Telnet to receive logging events. +The connection is unauthenticated and unencrypted. |xref:manual/configuration/appenders/traceappender.adoc[] |Writes logging events to the .NET trace system (https://web.archive.org/web/20240907024634/https://learn.microsoft.com/en-us/dotnet/api/system.diagnostics.trace?view=net-8.0[System.Diagnostics.Trace]). diff --git a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/adonetappender.adoc b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/adonetappender.adoc index 472b3c696..37a43137a 100644 --- a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/adonetappender.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/adonetappender.adoc @@ -19,7 +19,7 @@ = AdoNetAppender The `AdoNetAppender` is used to log events directly to a database table. -It writes log events in batches (with a default size of 100, controlled by the `BufferSize` setting). +It writes log events in batches (with a default size of 512, controlled by the `BufferSize` setting). The configuration of `AdoNetAppender` depends on the database provider you're using. Here are the key configuration elements: @@ -28,6 +28,18 @@ Here are the key configuration elements: * `ConnectionString`: The connection string that is specific to the database provider (e.g., SQL Server, MySQL). * `CommandText`: Defines the SQL command to execute. This can either be a prepared statement or a stored procedure. In the examples below, a prepared statement is used. +[WARNING] +==== +Always configure `CommandText` together with `parameter` elements, as every example below does. + +If `CommandText` is omitted, the appender falls back to a legacy mode in which the rendered +`Layout` output *is* the SQL statement that gets executed. +Layouts perform no SQL quoting or escaping and offer no way to add it, so anything that reaches +a log statement (a user name, a request parameter, an exception message) is executed as part +of the statement, with the privileges of the appender's connection. +The appender logs an error at startup when it is configured this way. +==== + Each parameter in the prepared statement or stored procedure is defined with: * `Name`: The name of the parameter. diff --git a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/fileappender.adoc b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/fileappender.adoc index e05d8d3ef..a64571d03 100644 --- a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/fileappender.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/fileappender.adoc @@ -63,4 +63,36 @@ This example shows how to configure the appender to use the minimal locking mode ----- \ No newline at end of file +---- + +[#fileappender-lock-timeout] +== Waiting for the lock + +`InterProcessLock` coordinates several processes writing to one file through a named mutex. +The wait for it happens while the appender lock is held, so a lock nobody releases would suspend +every thread logging through the appender. + +The wait is therefore bounded by `lockTimeoutMillis`, 10000 by default. +An event that cannot get the lock in time is reported through the error handler and dropped, and the +appender carries on with the next one. +Raise the value when the file is on storage where the lock is legitimately slow to obtain, such as a +network share, or set it to `-1` to wait for as long as it takes. + +[source,xml] +---- + + + + + + + + + + +---- + +`RollingFileAppender` takes a second mutex around the decision to roll and has its own +`lockTimeoutMillis` for it, with the same default. +An event that cannot get that lock is written to the current file without checking whether it should +roll first, rather than waiting. \ No newline at end of file diff --git a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/smtpappender.adoc b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/smtpappender.adoc index 2f5ca1ee6..0c33679b1 100644 --- a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/smtpappender.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/smtpappender.adoc @@ -190,7 +190,12 @@ This example authenticates against a mail server that requires an encrypted conn |The port the SMTP server listens on. Defaults to `25`. |`enableSsl` -|Whether to secure the connection. Defaults to `false`. See xref:#mailkit-smtpappender-differences[]. +|Whether to require transport security. Defaults to `false`. +Shorthand for `transportSecurity`: `true` selects `Required`, `false` selects `None`. + +|`transportSecurity` +|How the connection is secured. One of `None` (default), `Required`, `ImplicitTls`, `StartTls` or `StartTlsWhenAvailable`. +See xref:#mailkit-smtpappender-transport-security[]. |`authentication` |One of `None` (default), `Basic` or `Ntlm`. `Basic` and `Ntlm` both require `username` and `password`. @@ -222,17 +227,64 @@ This example authenticates against a mail server that requires an encrypted conn `to`, `cc` and `bcc` also accept semicolons as separators, and quoted display names such as `"Doe, John" `. +[#mailkit-smtpappender-transport-security] +=== Transport security + +`enableSsl` covers the usual cases and behaves as it does in the legacy appender: `true` requires +transport security, so connecting fails when the server does not offer it rather than continuing +unencrypted. + +`transportSecurity` is the same setting expressed precisely, for servers that need something else. +The two properties cannot disagree: whichever is assigned last wins. + +[cols="Value,Description"] +|=== +|Value |Description + +|`None` +|The connection is not encrypted. Equivalent to `enableSsl` set to `false`, and the default. + +|`Required` +|Transport security is required and the mechanism follows the port: implicit TLS on port 465, +`STARTTLS` on every other port. Equivalent to `enableSsl` set to `true`. + +|`ImplicitTls` +|The session is encrypted before the SMTP greeting, whatever the port. +Use this for a server expecting implicit TLS on a port other than 465, which `Required` would try +to negotiate with `STARTTLS` instead. + +|`StartTls` +|`STARTTLS` is required, whatever the port. + +|`StartTlsWhenAvailable` +|`STARTTLS` is used when the server advertises it, and the connection continues unencrypted when it +does not. +|=== + +[WARNING] +==== +`StartTlsWhenAvailable` is opportunistic. +An attacker able to modify the traffic can remove the server's `STARTTLS` advertisement, and the +session then proceeds in plaintext, exposing the credentials sent by `authentication` and the log +content itself. +Only choose it for a network where that is acceptable, and prefer `Required`. +==== + [#mailkit-smtpappender-differences] === Differences from the legacy appender The options above are named exactly as in the legacy appender, but a few behave differently: * `smtpHost` is *required*. MailKit has no notion of a machine-wide default SMTP server, so there is nothing to fall back on when the option is omitted. -* `enableSsl` set to `true` negotiates transport security automatically: implicit TLS on port 465, otherwise `STARTTLS` when the server advertises it. -Set to `false`, the connection is not encrypted at all. * `authentication` set to `Ntlm` requires `username` and `password`. MailKit cannot reuse the Windows logon session of the current thread or process, which the legacy appender did. * Semicolon-delimited recipient lists in `to`, `cc` and `bcc` are parsed correctly. +* `transportSecurity` has no counterpart in the legacy appender, which offers only `enableSsl`. + +`enableSsl` keeps its meaning, so a migrated configuration secures the connection exactly as before. +If the legacy appender reached your server with `enableSsl` set to `true`, so does this one. +The new `transportSecurity` option is only needed for a server that the legacy appender could not +reach either, such as one expecting implicit TLS on a port other than 465. [#legacy-smtpappender] == Built-in SmtpAppender (deprecated) diff --git a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/telnetappender.adoc b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/telnetappender.adoc new file mode 100644 index 000000000..6751ca0c6 --- /dev/null +++ b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/telnetappender.adoc @@ -0,0 +1,98 @@ +//// + Licensed to the Apache Software Foundation (ASF) under one or more + contributor license agreements. See the NOTICE file distributed with + this work for additional information regarding copyright ownership. + The ASF licenses this file to You under the Apache License, Version 2.0 + (the "License"); you may not use this file except in compliance with + the License. You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +//// + +[#telnetappender] += TelnetAppender + +The `TelnetAppender` listens for incoming TCP connections and streams rendered log events to +every connected client, so that a running application's log can be watched over a socket with a +telnet client. +Unlike every other appender, it does not write to a destination you configure: it accepts +connections from clients that reach it. +It is intended for diagnostic use on trusted networks; see <>. + +At most 20 clients may be connected at the same time; further connection attempts are answered +with a message and closed. + +The following example configures the appender to listen on port 8023. + +[source,xml] +---- + + + + + + + + +---- + +[#telnetappender-settings] +== Settings + +`port`:: +The TCP port to listen on. +The default is `23`, the telnet port. + +`listenAddress`:: +The local address to accept connections on. +The default is `0.0.0.0`, every interface of the machine. ++ +Set it to `127.0.0.1` to accept connections only from the machine the application runs on, which is +what diagnostic use usually needs. +An IPv6 address may be given instead, and the listening socket follows its family. + +`sendTimeoutMillis`:: +How long, in milliseconds, a write to a client may block before that client is treated as dead +and disconnected. +The default is `5000`. ++ +Clients are written to synchronously while the appender lock is held, so a client that connects +and then stops reading lets TCP flow control fill its receive window. +A finite timeout bounds how long that client can hold up the threads that log through this +appender. +Setting the value to `0` restores blocking indefinitely and is not recommended. + +[#telnetappender-trust] +== Intended use and trust model + +This appender is a *diagnostic tool for trusted networks*. +It is meant for watching the log of a running application during development or while +investigating a problem, not as a general-purpose logging destination. + +Like every other appender destination, the connecting client is *trusted*: by enabling the +appender the operator declares that whoever can reach the port is allowed to read the +application's log. +The appender therefore performs no authentication of its own. + +[WARNING] +==== +The connection is *unauthenticated* and *unencrypted*, and by default the appender listens on *all +network interfaces*. +There is no option to require a credential or to enable TLS. + +Any client that can reach the port receives the full rendered log stream, including whatever the +layout renders: user names, session identifiers, request parameters, stack traces. +Keeping untrusted parties away from the port is the operator's responsibility, exactly as it is +for a log file: + +* Set `listenAddress` to `127.0.0.1` unless clients on other machines really have to connect. +* Only enable this appender on a trusted network. +* Restrict access to the port with a host firewall or network policy. +* Prefer it for local or short-lived diagnostics rather than as a permanent logging destination. +==== diff --git a/src/site/antora/modules/ROOT/pages/manual/configuration/filters.adoc b/src/site/antora/modules/ROOT/pages/manual/configuration/filters.adoc index 5f2e07a69..0c34f84c4 100644 --- a/src/site/antora/modules/ROOT/pages/manual/configuration/filters.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/configuration/filters.adoc @@ -94,3 +94,26 @@ The following filters are defined in the log4net package: |log4net.Filter.StringMatchFilter |Matches events containing a specific substring in the message. |=== + +[#filters-regex-timeout] +== Matching with a regular expression + +`StringMatchFilter`, `PropertyFilter`, `MdcFilter` and `NdcFilter` accept a `regexToMatch` instead +of a `stringToMatch`. + +A regular expression that backtracks can take a very long time on some inputs, and the match runs +while the appender lock is held. +Matching is therefore given a deadline of one second, configurable with `matchTimeoutMillis`. +A match that reaches the deadline is abandoned, the filter reports it once and returns `Neutral`, +and the remaining filters decide the event. +Prefer a pattern that cannot backtrack; the deadline is a safety net, not a substitute. + +[source,xml] +---- + + + + +---- + +Setting `matchTimeoutMillis` to `0` lets a match run for as long as it takes and is not recommended.