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.

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?