fix: per-engine log_prefix — stop clobbering the process-global logger - #173
Merged
Conversation
…er (issue #172) log_prefix was applied via log.SetPrefix() behind a package-level sync.Once: process-global and first-engine-wins. With the v0.10.13 embedding API multiple engines per process are a first-class setup, where every other engine's configured prefix was silently ignored and its log lines carried a foreign prefix. Each Engine now owns a *log.Logger (prefix from WithLogPrefix > JSON log_prefix, same Ldate|Ltime|Lshortfile flags); the global log package is no longer touched. Consumers: - new LoggerAware/LoggerHolder operator injection (DebugHolder embeds LoggerHolder, so DebugAware operators get it for free); Logf and DebugLog use calldepth 3 so Lshortfile reports the operator call site, not the wrapper. - observe_log and transform_redis_set emit through the engine logger. - runtime.Plan.Logger carries it to the scheduler's [pine-debug] snapshot lines. - Engine.Logger() exposes it for embedders that want per-flow lines consistent with engine diagnostics. Tests: prefix-from-JSON / option-override now assert the engine logger and that the global logger is untouched; new per-engine isolation test pins that construction order no longer decides whose prefix wins. export_test.go's ResetLogOnce helper is gone with the sync.Once.
#172) The old path CAS-set a System property (pine.log.prefix) once per process — first-engine-wins with a stderr warning for later engines, and nothing in the codebase ever read the property back (dead state). Engine now stores its resolved prefix (option > JSON config) as an instance field exposed via logPrefix(), injects it into LoggerAware operators (AbstractOperator implements it and provides the logf helper), and prepends it to [pine-debug] snapshot lines. observe_log, transform_redis_set and transform_by_lua diagnostics now carry the owning engine's prefix. No global state is touched. LogPrefixTest mirrors the Go per-engine isolation test and pins that the System property channel stays unset. Full suite: 295 green.
…ware (issue #172) pine-cpp already stored log_prefix per engine instance but nothing in the log paths consumed it. run_dag now takes the engine's prefix and prepends it to [pine-debug] snapshot lines; new LoggerAware interface (mirroring Go/Java) lets operators receive the engine prefix — observe_log implements it and prepends the prefix to its output. Schema description updated away from the Go-specific wording. New doctest case pins two-engine prefix isolation.
…rd log The operator now writes through the engine's logger (issue #172); Go schema source updated and doc/operators regenerated. Java/C++ schema strings were aligned in their respective commits.
Contributor
🔍 PR 审查
整体方向正确：把
|
logf wraps Output directly (one layer), so depth 2 reports logf's caller — the scheduler [pine-debug] line. Depth 3 walked past the goroutine body into the runtime parent frame, printing asm/proc.go locations instead. LoggerHolder.Logf keeps 3 because it goes through two layers (Logf -> logOutput -> Output).
logf and the [pine-debug] line concatenated the user-configured log_prefix into the format string; a literal '%' in the prefix (e.g. "[100%] ") would throw UnknownFormatConversionException at runtime. The prefix is now emitted as a literal (print / %s argument). Also drop the AtomicBoolean import left over from the removed set-once guard.
Contributor
🔍 PR 增量审查
上一轮提出的 3 个问题已全部修复且修复方式正确，可以合并。
|
Reflection per-engine-log-prefix.md: #172 as the third instance of 'new public entrypoint turns old global state into a defect' (after the #169 stop-reachability and Addr-copy regressions), parity audits must trace to consumption points (a stored-but-never-read value is invisible to existence checks — log_prefix had drifted into three different wrong shapes), calldepth is a function of wrapper layers, user-controlled strings never enter printf format strings, and schema description edits fan out to three schema sources + codegen. Promotions: conventions.md adds the consumption-point audit dimension and rewrites the global-side-effect note to ask ownership first; standard-workflow.md adds the global-state ownership audit; operator-contract.md documents the LoggerAware operator logging contract (three-runtime table, printf isolation rule, injection order now four-stage). index synced.
Contributor
🔍 PR 增量审查
自上次审查（截止
|
engineOptions.logPrefix used the empty string for both 'option not
passed' and 'explicitly set to empty', so WithLogPrefix("") fell back
to the JSON prefix — violating the documented option-over-JSON
precedence and diverging from Java (nullable String) and C++
(std::optional), where the same call yields an empty prefix. Now
*string, mirroring WithDebug: nil falls back to JSON, an explicit
empty string wins. Test pins non-empty JSON + empty option -> empty.
Splitting logf into print(prefix) + printf(body) reopened a concurrency window: PrintStream only serializes within a single call, so another engine's line could land between the two writes and produce '[engine-a] [engine-b] message' — breaking exactly the per-engine attribution this feature guarantees. Now the body is formatted first (prefix still never enters the format string) and prefix + body + newline go out in ONE print call. New tests: explicit empty option overrides JSON prefix (tri-state parity), and a concurrency test that captures real stderr from two engines under parallel execute and asserts no interleaved or doubled prefixes.
…iew) std::optional already had the right tri-state semantics; the new case locks it against regressions and mirrors the Go/Java tests.
dag-engine.md still described WithLogPrefix as touching the process logger on one line while the section below said engine-scoped, and the compile-pipeline injection order missed LoggerAware. metrics- observability.md, pine-cpp-runtime.md, design_doc/08_observability.md and design_doc/06_json_config.md all still said log.SetPrefix / process-global. All now state the engine-instance semantics (tri-state option, per-runtime accessors, LoggerAware consumption paths); 08_observability keeps a one-line historical note.
Contributor
🔍 PR 增量审查
自上次审查（截止
|
Sentinel values must not stand in for 'option unset' (use the type system — *string/optional, the *bool precedent was in the same file); a fix must be re-validated against ALL existing constraints of the code path, not just the one being fixed (printf-injection fix reopened the concurrency-attribution window); semantic changes require a repo-wide grep of the doc surface (five docs still said process-global); concurrency attribution tests must capture real output.
Contributor
🔍 PR 增量审查
自上次审查（截止
|
…(review)
The C++ injection order was Metrics -> Resource -> Logger while Go/Java
inject Logger -> Metrics (-> Resource). No operator currently observes
the difference, but the documented cross-runtime invariant ('logger and
debug context available before provider injection') was not true for
C++. Reordered to Logger -> Metrics -> Resource; metadata/debug still
arrive via init(op_cfg), which precedes all injection.
Four places declared three mutually inconsistent 'fixed injection orders', and the declared unified order matched no runtime: Go has no ResourceAware interface at all (resources are ctx-injected at execute time) and C++ injected Logger last. dag-engine invariant 11 now states the actual cross-runtime invariant (metadata/debug before providers, then Logger -> Metrics -> Resource) plus each runtime's real path; the compile-pipeline line, the Java parity section, operator-contract.md and metrics-observability.md (both sites) all reference the same definition instead of restating divergent copies.
Contributor
🔍 PR 增量审查
自上次审查（截止
|
Verify per-runtime code before declaring a cross-runtime invariant (the documented unified order matched no runtime), and keep exactly one authoritative definition of a contract — restated copies drift apart structurally; converge them to a single definition plus references.
Contributor
🔍 PR 增量审查
本次增量仅一处 docs 改动：
|
… log prefixes Three runtime examples for the issue #169/#172 embedding pattern — one process, several pipelines, each on its own endpoint with its own log_prefix, and the legacy /execute deliberately retired to 410 Gone: - pine-go/examples/multi-pipeline: two server.NewServer embedded runtimes (hot-reload + refcounted snapshots intact) behind an app-owned net/http mux; shared feed.json/search.json configs declare "[feed] "/"[search] " prefixes. - pine-java/examples/MultiPipelineServer.java: two PineServer.load() embedded runtimes behind a com.sun.net.httpserver mux, execute() against the live snapshot. - pine-cpp/examples/multi_pipeline_server.cpp: two pine::Engine instances behind a deliberately tiny blocking HTTP loop; built by default (new CMake target multi_pipeline_server) so it cannot rot. All three smoke-verified: stderr shows [feed] / [search] prefixed observe_log lines concurrently from one process, /execute answers 410 with a migration hint. bump-version.sh now also rewrites _PINEAPPLE_VERSION in pine-go/examples configs; README points at the examples from the embedding feature bullet.
Contributor
🔍 PR 增量审查
自上次审查（截止
|
The embedded example bypassed the bundled server's 10 MB default body limit with an unbounded io.ReadAll. Issue #169 treats the body cap as a shared-dispatch-layer safety contract, so the embedding HTTP layer must keep the boundary itself: wrap the body in http.MaxBytesReader and map MaxBytesError to 413.
Four gaps versus the bundled PineServer contracts: - Map Engine.Result.error to HTTP 500 (throw/return split: validation throws, operator failures are returned). PanicError logs its detailed stack server-side while clients only see the safe message. - Enforce the 10 MB request-body cap with a counting reader; over-limit bodies answer 413 instead of growing memory unbounded (issue #169 shared-dispatch-layer safety contract). - Guard every context with exact-path matching: HttpServer contexts use longest-prefix matching, so /api/feed/anything would otherwise run the feed pipeline (the issue #169 routing trap, fixed in wrapHandler). - Make the documented compile/run commands actually work from the repo root: build the Maven runtime classpath via dependency:build-classpath and point at the real config paths under pine-go/examples/.
- Replace the bare ::write with a ::send loop using MSG_NOSIGNAL, handling EINTR and short writes. Every pine-cpp raw-socket write path must suppress SIGPIPE (llmdoc/must/conventions.md) — a client disconnecting mid-response would otherwise kill the whole process. - Route error messages through the Variant serializer instead of hand-concatenating them into JSON: ValidationError text quotes field names, which produced invalid JSON bodies.
Contributor
🔍 PR 增量审查
自上次审查（截止
|
Fourth review round on the multi-pipeline examples found six production contracts missing from 'demo' code (error mapping, body cap, exact routing, SIGPIPE suppression, JSON escaping, runnable doc commands). Append the round-4 lessons to the per-engine-log-prefix reflection and promote the stable rule — examples are bound by every production contract, verify the negative space, keep doc commands actually runnable, build examples by default — into standard-workflow.md.
Contributor
🔍 PR 增量审查
自上次审查（截止
|
The C++ example is a default CMake target and the Go example is compiled by 'go test ./...', but pine-java/examples/ sat outside the Maven source tree — 'mvn package'/'mvn test' never compiled it, so API drift would rot the README-recommended example silently. Attach examples/ as an extra test-source root via build-helper-maven-plugin: 'mvn test-compile' (and CI's 'mvn test -B') now compiles QuickStart and MultiPipelineServer; test scope keeps them out of the library jar, and the surefire *Test name pattern keeps them out of the test run. Update the example's doc commands to the simpler test-compile + target/test-classes form (each command verified from a clean shell).
) Round 4 promoted 'examples must be in the default build' into standard-workflow.md while Java itself did not comply; increment-4 review caught it. Record the lesson (a rule-writing commit must audit all runtimes and fix or note non-compliance on the spot) plus the minimal Maven approach (build-helper add-test-source), and update the stable rule with the per-runtime wiring.
Contributor
🔍 PR 增量审查
自上次审查（截止
|
Contributor
🔍 PR 增量审查
自上次审查（截止
|
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Closes #172
Summary
log_prefixwas applied through process-global state guarded by set-once semantics: Go calledlog.SetPrefix()behind a package-levelsync.Once, Java CAS-set apine.log.prefixSystem property (which nothing ever read back). With the v0.10.13 embedding API, multiple engines per process are a first-class setup — and whichever engine was constructed first won the prefix while every other engine's configuredlog_prefixwas silently ignored, misattributing its log lines.log_prefixis now engine-instance-scoped across all three runtimes:Engineowns a*log.Logger(prefix fromWithLogPrefix> JSONlog_prefix,Ldate|Ltime|Lshortfileflags); the globallogpackage is never touched. Consumers: newLoggerAware/LoggerHolderoperator injection (DebugHolderembeds it, soDebugLogandLogfreport the operator call site via calldepth 3), scheduler[pine-debug]snapshot lines viaruntime.Plan.Logger,observe_log/transform_redis_setdiagnostics, andEngine.Logger()for embedders.Enginestores the resolved prefix (exposed vialogPrefix()), injects it intoLoggerAwareoperators (AbstractOperatorimplements it with alogfhelper), and prepends it to[pine-debug]lines. The dead System-property channel is gone.log_prefix_(already stored, never consumed) is now actually consumed:run_dagprepends it to[pine-debug]lines, and a newLoggerAwareinterface feeds it toobserve_log.The
observe_logschema description ("writes them to Go standard log") was updated in all three schema sources anddoc/operators/regenerated — cross-engine codegen byte-parity holds.Testing
TestLogPrefixPerEngineIsolationpins that construction order no longer decides whose prefix wins. Fullgo test ./...green.LogPrefixTest(per-engine isolation + option override + property channel stays unset). Full suite 295 green.make lintandmake fuzzclean.Compatibility
Single-engine processes see identical log output (same prefix, same flags, same lines). The only observable change is intentional: log lines and
log.Prefix()no longer leak the engine prefix into the process-global logger, and multi-engine processes get correct per-engine attribution.