Lab P3: Debugging a Failed Cross-Plugin Request

Background

A request that fails inside one repo is easy: read the stack trace, fix the code. A request that fails at the boundary between core and a plugin is the hard case, because the stack trace spans two repositories that were built separately, the relevant log lines are split across two logging configurations, and the "obvious" frame often belongs to the wrong owner. This lab teaches you to read a failure that crosses the core↔plugin seam: enable TRACE logging on both sides, read a stack trace whose frames alternate between org.opensearch.<core> and the plugin's package, and decide which side owns the bug.

It is the prerequisite for P4: Bug Attribution, which formalizes the decision into a flowchart. Here you build the raw skill of reading the cross-stack failure; there you make it mechanical. It assumes the plugin↔SPI map from P2 and the request path from P1 and the Action Framework deep dive.

Why This Lab Matters for Contributors

The most common mistake on cross-repo issues is anchoring on the top frame of a stack trace. If the top frame is org.opensearch.action.search.TransportSearchAction, the reflex is "core bug." But the trace continues into the plugin's query builder, and the Caused by is in the plugin's native engine. The top frame is just core calling the plugin. The skill is to find the frame in actionable code and read the Caused by chain, exactly as the Tez curriculum's H4 does for Hive/Tez. Get this wrong and you file on core; the core maintainer bounces it to the plugin repo a week later; everyone loses.

Prerequisites

Two boundary failure shapes

There are two archetypal cross-plugin failures. You will reproduce one and read the other.

flowchart TD
  R[Incoming request]
  R --> AF{ActionFilter chain<br/>security plugin}
  AF -->|denies| F403[403 — security owns this]
  AF -->|allows| TA[core TransportAction]
  TA --> Q{query / field type<br/>from a SearchPlugin/MapperPlugin}
  Q -->|mapping/engine mismatch| F500[search_phase_execution_exception<br/>core surfaces, plugin or Lucene owns]
  Q -->|ok| OK[normal response]

• Shape A — authorization (security): the request never reaches core's action logic; the security action filter denies it and returns a 403. Owner: the security plugin (or the role config), almost never core.
• Shape B — mapping/engine mismatch (k-NN): the request reaches core's search fan-out, which calls the plugin's query against a field whose mapping or engine doesn't match — core surfaces a search_phase_execution_exception but the bug is in the plugin layer (or Lucene below it).

Step-by-Step Tasks

Step 1 — Turn on TRACE on both sides

Core and the plugin both log through log4j2, but to different loggers. You must raise the level on both package roots. Set it dynamically (no restart) for the relevant loggers:

curl -s -XPUT 'localhost:9200/_cluster/settings' -H 'Content-Type: application/json' -d '{
  "transient": {
    "logger.org.opensearch.action.search": "TRACE",
    "logger.org.opensearch.search": "TRACE",
    "logger.org.opensearch.knn": "TRACE",
    "logger.org.opensearch.security": "TRACE"
  }
}'

Note: Dynamic logger.<package> cluster settings work for any package, including plugin packages — that's the whole trick. If a plugin's logger isn't taking effect, confirm the package root with grep -rn "LogManager.getLogger" <plugin>/src/main/java | head and set that exact prefix. For startup-time failures that happen before settings apply, edit config/log4j2.properties and restart instead.

Step 2 — Reproduce Shape B (k-NN mapping/engine mismatch)

Create the mismatch deliberately: index a field as a plain float (not knn_vector) and then run a knn query against it. Core's search will invoke the plugin's query builder against a field type it can't handle.

curl -s -XPUT localhost:9200/badvec -H 'Content-Type: application/json' -d '{
  "mappings": { "properties": { "v": { "type": "float" } } } }'    # NOT knn_vector
curl -s -XPOST localhost:9200/badvec/_doc -H 'Content-Type: application/json' \
  -d '{"v":[1,2,3]}'
curl -s -XPOST localhost:9200/badvec/_refresh >/dev/null

curl -s localhost:9200/badvec/_search -H 'Content-Type: application/json' -d '{
  "query": { "knn": { "v": { "vector": [1,2,3], "k": 2 } } } }' | python3 -m json.tool

You get a search_phase_execution_exception. The top-level type is core's; the reason and root_cause name the k-NN class that rejected the field. That split — core's exception type wrapping a plugin's root cause — is the signature of Shape B.

Step 3 — Read the stack trace across the seam

A representative trace for the mismatch (class names vary by branch; the structure is the point):

org.opensearch.action.search.SearchPhaseExecutionException: all shards failed
        at org.opensearch.action.search.AbstractSearchAsyncAction.onPhaseFailure(...)   <- core: surfaces
        at org.opensearch.action.search.AbstractSearchAsyncAction.executeNextPhase(...) <- core
        ...
Caused by: org.opensearch.OpenSearchException: [knn] requires field [v] to be of type [knn_vector]
        at org.opensearch.knn.index.query.KNNQueryBuilder.doToQuery(KNNQueryBuilder.java:...) <- PLUGIN: owns
        at org.opensearch.index.query.AbstractQueryBuilder.toQuery(AbstractQueryBuilder.java:...) <- core: calls plugin
        at org.opensearch.search.SearchService.parseSource(SearchService.java:...)              <- core
        ...

Read it with the P4 rule, applied here:

Attribution: the immediate fault is user error (wrong mapping). But note the shape: core's toQuery called the plugin's doToQuery, which threw. That toQuery → doToQuery transition is the exact core↔plugin SPI seam from P2. If the k-NN message had been unclear (say a raw ClassCastException instead of "requires knn_vector"), that would be a k-NN bug worth filing — the diagnostics lab P6 is about making exactly this message actionable.

Step 4 — Confirm with the two-side logs

With TRACE on, the boundary is visible in the logs as adjacent lines from different package roots:

grep -E "org.opensearch.search|org.opensearch.knn" logs/*.log | tail -30

You will see core's SearchService log entering the query phase, immediately followed by k-NN's logger reporting the field-type check. The handoff is right there in the timeline — core, then plugin, then the exception. That adjacency is how you see the seam, not just infer it from the stack trace.

Step 5 — Read Shape A (a security 403)

You may not have security configured locally, so read this from a real trace shape. A denied action returns:

{ "status": 403,
  "error": { "type": "security_exception",
    "reason": "no permissions for [indices:data/read/search] and User [name=guest, ...]" } }

There is usually no core stack trace at all — because core's action never ran. The security action filter (SecurityFilter.apply, the ActionFilter from P2) short-circuited the chain before TransportSearchAction.doExecute. The diagnostic is:

# With security TRACE on, find the filter decision
grep -E "org.opensearch.security|privilege|SecurityFilter|no permissions" logs/*.log | tail -20

Attribution: Shape A is owned by the security plugin's policy, not its code and not core. The "bug," if any, is a missing role mapping. It is a core bug only if core mis-declared an action's required privilege name — a rare, specific case you'd confirm by checking which ActionType string the filter evaluated.

Reading rules for cross-plugin failures

The discipline: the top frame tells you who surfaced the error; the Caused by root and the frame that called across the SPI tell you who owns it.

Expected Output

• A reproduced search_phase_execution_exception whose root_cause is a k-NN class, captured as JSON.
• The stack trace annotated frame-by-frame as core-surface vs plugin-owner, with the toQuery → doToQuery SPI seam identified.
• TRACE log excerpts showing core's logger and the plugin's logger on adjacent lines around the failure.
• A one-paragraph attribution for each of Shape A and Shape B.

Troubleshooting

Stretch Goals

1. Reproduce a real plugin bug shape: configure k-NN with one engine (faiss) in the mapping but query expecting another behavior, and read where the engine mismatch surfaces.
2. Turn on error_trace=true and compare the response body's stack to the server log's — note what the HTTP body omits.
3. Write the same failure twice: once where the plugin message is actionable and once where it's a raw ClassCastException. Argue which one you'd file.

Coding Exercises

Reading a cross-seam trace is the skill; the proof is code that reproduces the seam and a test that pins which side owns the failure. These exercises produce an integ test, a diagnostics patch, and a parser — all grounded in the toQuery → doToQuery boundary. Locate the real classes with rg first; names drift by branch.

1. (warm-up) Turn Shape B into a JSON fixture and an assertion. Run the Step 2 mismatch (knn query on a float field), capture the response JSON with ?error_trace=true, and write a small program (Python or Java) that parses it and asserts the root_cause[0].type names a k-NN class while the top-level type is core's search_phase_execution_exception. Exit non-zero if the split isn't present. You have made "core surfaces, plugin owns" machine-checkable.

2. (core) Write a parse/throw unit test for the seam. Find the boundary method (rg -n "toQuery|doToQuery" ~/OpenSearch/server/src/main/java/org/opensearch/index/query/AbstractQueryBuilder.java). Then, in a plugin checkout, write a unit test that constructs the plugin's QueryBuilder against a wrong field type and asserts it throws with an actionable message (assertThat(e.getMessage(), containsString("knn_vector"))). This codifies the difference between a fileable bug and user error from Step 3.

3. (core) Reproduce Shape B as a cross-plugin integ test. Write an OpenSearchIntegTestCase with nodePlugins() returning the plugin class (find the pattern: rg -l "nodePlugins" ~/k-NN/src or in core's plugin tests), create the index with the wrong mapping, run the plugin query, and expectThrows(SearchPhaseExecutionException.class, ...), asserting the cause chain reaches the plugin frame. This is the white-box twin of the curl repro — it runs the real core↔plugin seam in one JVM.

4. (core) Write a stack-trace attributor. Implement a small program that takes a raw stack trace (from logs/ or error_trace=true) and prints the owner: find the deepest Caused by root, classify its package (org.opensearch.knn.* ⇒ plugin, org.apache.lucene.* ⇒ Lucene, org.opensearch.security.* ⇒ security, else core), and identify the frame just above it that called across the SPI. Validate it against the Step 3 trace and a security 403 (which has no core stack — it must say "security policy"). This makes the lab's reading rules executable.

5. (advanced challenge) Build a diagnostics-improving patch with a regression test. Pick a boundary error whose message is unclear (e.g. a raw ClassCastException path in the plugin's query builder — find it with rg -n "ClassCastException|instanceof .*FieldType" ~/k-NN/src/main/java). Replace it with a message that names the plugin, the field, and the expected type (the P6 three-question rule), add the CHANGELOG entry and DCO sign-off, and write an integ test reproducing the cross-plugin failure that asserts the new wording. Run ./gradlew integTest --tests "*YourIT*". You have turned a confusing seam failure into one that attributes itself — the highest- leverage cross-repo contribution.

Issues to Practice On

Cross-seam failures get mis-filed constantly; practicing on real traces from both trackers trains the "who surfaced vs who owns" reflex.

# Core — exceptions it surfaces from plugin/Lucene calls:
gh issue list --repo opensearch-project/OpenSearch --label "bug" --label "Search" --state open
gh issue list --repo opensearch-project/OpenSearch --label "good first issue" --state open
# k-NN — the plugin most often named in a root_cause:
gh issue list --repo opensearch-project/k-NN --label "bug" --state open
gh label list --repo opensearch-project/OpenSearch | grep -iE "search|exception|error"

Labels move; confirm on each tracker before relying on a name.

Two representative patterns:

• "search_phase_execution_exception with a confusing root cause." Often mis-filed on core because core's type is on top. Reproduce, read the Caused by to its root, attribute via the package, and either re-file on the owning repo or — if the root is a raw ClassCastException/NPE in plugin code — propose a clearer message there. This is the exact Step 3 → P4 move.
• "Plugin logger won't emit at TRACE." Reproduce, find the real package root (rg -n "LogManager.getLogger" <plugin>/src/main/java | head), and document the correct logger.<pkg> cluster setting — a small docs/diagnostics contribution that saves the next debugger hours.

Planted-bug drill. In a plugin checkout, find the field-type guard the query builder uses (rg -n "requires field|knn_vector|instanceof" $(find ~/k-NN -name "KNNQueryBuilder.java")). Replace the descriptive exception with a bare throw new ClassCastException() (or remove the guard so the cast fails downstream). Rebuild, run the Step 2 repro, and watch the root_cause become uninformative — proving how a missing diagnostic sends the issue to the wrong repo. Then restore the guard, and add a unit test that asserts the message contains the field name and expected type so the actionable wording can never silently regress.

Etiquette: Claim an issue before working it; reproduce first; attribute with a trace before you file; every PR needs a test + a CHANGELOG entry + a DCO Signed-off-by (git commit -s). See community interaction and the PR-review lab.

Validation / Self-check

1. Given a search_phase_execution_exception with a k-NN frame in root_cause, which repo owns it, and what single line in the trace told you?
2. Why does a security 403 usually have no core stack trace?
3. What is the toQuery → doToQuery transition, and why is it the most important frame pair in a cross-plugin search failure?
4. How do you enable TRACE on a plugin's package at runtime without a restart, and when must you fall back to editing log4j2.properties?
5. Distinguish "core surfaced the error" from "core owns the error" using the frames of a trace you reproduced.
6. When is a security 403 actually a core bug rather than a policy issue?