Return 503 instead of 500 when the metastore fails during authentication - #5247
Return 503 instead of 500 when the metastore fails during authentication#5247shyundev wants to merge 4 commits into
Conversation
| Arguments.of(new ValidationException("invalid"), 400)); | ||
| Arguments.of(new ValidationException("invalid"), 400), | ||
| // The JAX-RS exception, not Iceberg's; handled by the WebApplicationException case. | ||
| Arguments.of(new ServiceUnavailableException("service unavailable"), 503)); |
There was a problem hiding this comment.
Is this exception type passed to IcebergExceptionMapper? My assumption was that JAX-RS exceptions did not need any mapper. If it's not passed to IcebergExceptionMapper, then I'm not sure it should be tested at all.
There was a problem hiding this comment.
Good point!
Also, this exception is not specific to "iceberg", so even if we do need an explicit mapper case of it, it should probably be handled by PolarisExceptionMapper. WDYT?
There was a problem hiding this comment.
@adutra Yes, it is. I checked with a request whose authentication throws it, and the client gets:
{"error":{"message":"Unable to fetch principal grants","type":"ServiceUnavailableException","code":503}}You're right that the status needs no mapper: with none registered, RESTEasy returns the exception's own 503. What decides whether a mapper is consulted at all, for a WebApplicationException, is whether its Response already carries a body. RESTEasy Reactive's RuntimeExceptionMapper short-circuits only when it does, and ServiceUnavailableException(String) builds Response.status(SERVICE_UNAVAILABLE).build(), so resolution falls through to IcebergExceptionMapper, the ExceptionMapper<RuntimeException>. The body comes from there.
So I'd rather pin it than drop the case: resolvePrincipalEntity has thrown the JAX-RS exception since #5085 and DefaultAuthenticatorTest asserts that type, but nothing asserts the status a client ends up with for it.
There was a problem hiding this comment.
@dimas-b PolarisExceptionMapper is the right home, and now that #5206 has landed it needs no change at all: the status would come from PolarisServiceUnavailableException.httpStatusCode(). Nor does this PR add a case to IcebergExceptionMapper: the generic case WebApplicationException already covers the JAX-RS type, and the test only pins the result. The case sits in IcebergExceptionMapperTest because that is the mapper handling it today, not because the exception is Iceberg-specific; it moves across with the type. What would change is the exception thrown by metaStoreUnavailable, the helper this PR adds for all three lookups.
I'd put that in a follow-up. It changes what clients see: the type in the error body goes from ServiceUnavailableException to PolarisServiceUnavailableException, and the constructor takes a retryAfterSeconds, so there is a Retry-After to decide on. It also touches the same lines as the generic messages you raised on the error-disclosure thread, so both go in one pass. I'll fold it into the follow-up I proposed there.
There was a problem hiding this comment.
@adutra This case goes away with the type switch: the helper now throws PolarisServiceUnavailableException, so nothing here produces the JAX-RS type any more, and ExceptionMapperTest already pins the new one. IcebergExceptionMapperTest is back to its state on main.
| LOGGER | ||
| .atError() | ||
| .addKeyValue(StructuredLogKeys.ERR_MSG, cause.getMessage()) | ||
| .addKeyValue(StructuredLogKeys.STACK_TRACE, Throwables.getStackTraceAsString(cause)) |
There was a problem hiding this comment.
Why not also pass cause to .setCause()? That will ensure logging the stack trace in plain test loggers too. We can certainly keep the STACK_TRACE attribute for backward compatibility.
There was a problem hiding this comment.
Done: .setCause(cause) added in metaStoreUnavailable, with the STACK_TRACE attribute kept as you suggested. One thing that turned up while checking it: slf4j-jboss-logmanager's Slf4jLogger is not LoggingEventAware, so slf4j merges key-values into the message text instead of passing them through, and with the default %s%e format the trace now appears twice, once inside the message and once from the cause. I kept the attribute anyway, since that merged text is what anything reading stackTrace= today already sees.
| Arguments.of(new ValidationException("invalid"), 400)); | ||
| Arguments.of(new ValidationException("invalid"), 400), | ||
| // The JAX-RS exception, not Iceberg's; handled by the WebApplicationException case. | ||
| Arguments.of(new ServiceUnavailableException("service unavailable"), 503)); |
There was a problem hiding this comment.
Good point!
Also, this exception is not specific to "iceberg", so even if we do need an explicit mapper case of it, it should probably be handled by PolarisExceptionMapper. WDYT?
| principalGrantResults = metaStoreManager.loadGrantsToGrantee(polarisContext, principal); | ||
| } catch (Exception e) { | ||
| throw metaStoreUnavailable( | ||
| e, "Unable to load grants for principal", "Unable to fetch principal grants"); |
There was a problem hiding this comment.
Since we're touching this code... I believe it is preferable not to disclose any error details to the client before it has been properly authorized (to reduce the risk of disclosing valuable information about the server to malicious clients).
In this case I believe we ought to log these messages (Unable to fetch principal grants, etc.) with a UUID and pass the UUID back to the client with a generic "service unavailable" message.
The admin user will be able to correlate the client-side error UUID to specific failures in Polaris logs if it comes to debugging.
There was a problem hiding this comment.
If you agree, we probably need to rebase this PR on top of #5119 and redo those new messages too.
There was a problem hiding this comment.
Agreed. On the UUID, #5011 points at something already in place: the response carries the request id as X-Request-ID and the default log format prints the same id, so there is nothing new to mint. #4406 took that route on the 403 path, and I checked a 503 raised during authentication comes back with the header set.
That leaves the message, and it should cover the existing Unable to fetch principal entity too, otherwise two of the three lookups go generic and one keeps its current text. Doing that here rewrites a message that has already shipped, so I'd rather put all three in one follow-up together with the exception type from the other thread, since both come down to what metaStoreUnavailable throws. I'll open it as soon as this is in.
On the rebase: in DefaultAuthenticator the only lines both PRs change are the resolvePrincipalEntity catch block, so nothing here has to wait. If #5119 goes in first I'll rebase onto it.
There was a problem hiding this comment.
Narrowing that follow-up to the three messages, since the exception type is now in this PR.
|
Thanks for your contribution, @shyundev ! |
c5a95a7 to
8bdd65f
Compare
| .addKeyValue(StructuredLogKeys.ERR_MSG, cause.getMessage()) | ||
| .addKeyValue(StructuredLogKeys.STACK_TRACE, Throwables.getStackTraceAsString(cause)) | ||
| .log(logMessage); | ||
| return new ServiceUnavailableException(responseMessage); |
There was a problem hiding this comment.
I'm a bit confused... Why not PolarisServiceUnavailableException? It would be more specific and hopefully easier to process as a result.
There was a problem hiding this comment.
You're right, switching. metaStoreUnavailable now returns PolarisServiceUnavailableException(0, ...), so PolarisExceptionMapper handles it and the status comes from httpStatusCode(). This covers resolvePrincipalEntity as well, so its error-body type changes too; the status stays 503 there and the CHANGELOG now says so. I passed 0 for retryAfterSeconds since Polaris has no basis for estimating when the metastore recovers, and the mapper omits the header at 0. I checked over HTTP that it is still 503 with the same message and no Retry-After.
There was a problem hiding this comment.
Per IRC spec clients are not supposed to retry non-idempotent requests, unless Retry-After is set.
The recent "idempotency" code uses 1 (at least) for Retry-After.
I think using 1 is preferable to omitting Retry-After in this case, because we do not want to prevent clients from re-trying on these internal and likely transient failures.
WDYT?
There was a problem hiding this comment.
There was a problem hiding this comment.
Done. PolarisExceptionMapper now sends the header when retryAfterSeconds >= 0 and skips negatives, so the three authentication 503s carry Retry-After: 0. The only other places that throw it pass 3 and Math.max(1, ...), so nothing else changes. I checked the header over HTTP.
DefaultAuthenticator.authenticate()reaches the metastore in three places, and only one of themtranslates a backend failure into a retryable error:
findPrincipalById/findPrincipalByNameresolvePrincipalEntityServiceUnavailableException-> 503loadGrantsToGranteeloadPrincipalGrantsloadEntityloadSecurableEntityfallbackNothing between the query and the response turns that failure into a 503.
JdbcBasePersistenceImpl.loadAllGrantRecordsOnGranteereports aSQLExceptionas a plainRuntimeException, neitherAtomicOperationMetaStoreManager.loadGrantsToGranteenorloadPrincipalGrantscatches it, andIcebergExceptionMapperfalls through todefault -> INTERNAL_SERVER_ERROR.Running first does not make
resolvePrincipalEntitya gate in front of the other two. It shields themonly when its own query fails, and a backend that fails some queries and not others lets the request
through:
authenticate()issues fourqueries for a principal that has grants: the principal lookup, then
lookupEntityGrantRecordsVersion,loadAllGrantRecordsOnGranteeandlookupEntitiesinsideloadGrantsToGrantee. Only the first returns 503 today. A saturated connection pool, an overloadednode or a timeout under variable load fails individual queries rather than all of them at once, and
three of the four are the unwrapped ones. The same is true when a full outage begins: a request
already past the principal lookup takes the 500 path.
entitiesby an indexed key: by id, orby the unique name constraint.
loadAllGrantRecordsOnGranteefiltersgrant_recordsby grantee, andon the CockroachDB schemas in this repo the only index on that table is its primary key, which puts
the securable columns ahead of the grantee ones.
This is not a new status-mapping proposal: it applies a decision the project already made. During the
#5085 review @flyrain
flagged exactly this on the
entity path:
and @adutra
replied:
That amend covered
resolvePrincipalEntity. The grants lookup and theloadEntityfallback never cameup in that review.
The logging follows the status. Today neither of these two sites logs anything when its query throws,
so the failure is described by the mapper's fall-through:
ERROR "Unhandled exception returning INTERNAL_SERVER_ERROR", which reports it as a condition theserver does not recognize. After the change the ERROR names the failure where it happens, and the
mapper takes its non-500 path at INFO, which is what the entity lookup already does.
Change
Both unwrapped lookups now go through the same translation as the entity lookup. That made the logging
block identical in three places, so it moves into a private helper; the existing log and response messages
are passed in unchanged. The helper throws
PolarisServiceUnavailableException, so all three lookups nowreport that as the error
type,resolvePrincipalEntityincluded; the status stays 503 there.It passes
0forretryAfterSeconds, so the three responses carryRetry-After: 0. Nothing inauthenticate()can predict when the metastore recovers, and the Iceberg REST spec has a client retry anon-idempotent request only when the header is present.
PolarisExceptionMappersent the header for anon-zero value only, so it now sends it for any non-negative one.
This fixes the one method where the project has already decided what the status should be:
authenticate()treats one of its own three lookups as a 503 on purpose, and the other two were leftbehind.
Tests
DefaultAuthenticatorTest:loadGrantsToGranteethrowing, theloadEntityfallbackthrowing, and the existing
testFetchPrincipalThrowsServiceExceptionOnMetastoreException, which nowexpects the same exception. Each pins
retryAfterSecondsat0. RevertingDefaultAuthenticatortomainfails all three.ExceptionMapperTestnow drives itsRetry-Aftercase with3,0and-1, covering the values themapper sends as a header and the one it skips. The 503 status itself was already pinned there.
Checklist
CHANGELOG.mdsite/content/in-dev/unreleased(not needed; no page documents these status codes)