Conversation
There was a problem hiding this comment.
Code Review
This pull request introduces a new retry logging mechanism to diagnose silently retried transient errors and resumed downloads in the GCS client library, adding retry_logging.h and retry_logging.cc along with comprehensive unit tests. The reviewer feedback correctly identifies several violations of the repository style guide where absl::string_view was used instead of std::string_view in includes, function signatures, and implementations.
|
|
||
| #include "google/cloud/status.h" | ||
| #include "google/cloud/version.h" | ||
| #include "absl/strings/string_view.h" |
There was a problem hiding this comment.
According to the repository style guide, std::string_view should be used instead of absl::string_view. Please include <string_view> instead of "absl/strings/string_view.h".
#include <string_view>References
- Use
std::string_viewinstead ofabsl::string_view. (link)
There was a problem hiding this comment.
Done. Note this file belongs to #16467 (it only shows up in this PR's diff because this branch is stacked on that one), so the fix landed there and is included here via the rebase.
| void LogTransientRetry(char const* where, absl::string_view resource, | ||
| Status const& status, int attempt); | ||
|
|
||
| /// Formats @p bucket_name and @p object_name for the `resource` argument above. | ||
| std::string RetryLogResource(absl::string_view bucket_name, | ||
| absl::string_view object_name); | ||
|
|
||
| /** | ||
| * Formats a resumable upload session URL for the `resource` argument above. | ||
| * | ||
| * A resumable upload session URL carries an `upload_id`, and that id is a | ||
| * bearer capability: anyone who has it can append to, or finalize, the upload | ||
| * without any other credential. These diagnostics are always on and usually | ||
| * end up in a log aggregator that more people can read than the bucket itself, | ||
| * so only a short prefix of the id is kept. That is enough to correlate the | ||
| * log lines belonging to one upload, and not enough to hijack it. | ||
| */ | ||
| std::string RetryLogUploadResource(absl::string_view upload_session_url); |
There was a problem hiding this comment.
According to the repository style guide, std::string_view should be used instead of absl::string_view in function signatures.
void LogTransientRetry(char const* where, std::string_view resource,
Status const& status, int attempt);
/// Formats @p bucket_name and @p object_name for the `resource` argument above.
std::string RetryLogResource(std::string_view bucket_name,
std::string_view object_name);
/**
* Formats a resumable upload session URL for the `resource` argument above.
*
* A resumable upload session URL carries an `upload_id`, and that id is a
* bearer capability: anyone who has it can append to, or finalize, the upload
* without any other credential. These diagnostics are always on and usually
* end up in a log aggregator that more people can read than the bucket itself,
* so only a short prefix of the id is kept. That is enough to correlate the
* log lines belonging to one upload, and not enough to hijack it.
*/
std::string RetryLogUploadResource(std::string_view upload_session_url);References
- Use
std::string_viewinstead ofabsl::string_view. (link)
There was a problem hiding this comment.
Done in #16467; included here via the rebase.
df4c144 to
58f96d9
Compare
When GCS returns a transient error the client backs off and retries with
no output at all. From the application's point of view a read just takes
a long time. There is nothing to grep for, so an operator cannot tell a
slow network from a server that is shedding load, and the only way to
see the retries is to enable the `rawclient` tracing component and pay
for a full dump of every request and response.
This adds one WARNING record per retried attempt on the synchronous
paths, which cover both the JSON/REST and the gRPC transports (GCS gRPC
sync goes through `RestRetryLoop`, because `GenericStub` takes a
`RestContext&` regardless of transport).
[gcs-retry] ReadObject/open: transient error on attempt 1,
resource=my-bucket/my-object, status=UNAVAILABLE: ...
Call sites:
- `ConnectionImpl::ReadObject`, the retry lambda passed to
`RestRetryLoop` -- an attempt failed to open the stream.
- `RetryObjectReadSource::Read` -- the stream broke mid-download and is
being resumed from the last received byte.
- `ConnectionImpl::UploadChunk` -- an attempt to upload a chunk of a
resumable upload failed.
The severity is WARNING and the record is not gated behind a tracing
component. `StdClogBackend`, the default backend, drops everything below
FATAL, so this is invisible to a default OSS build; it becomes visible
to anyone who installs a `LogBackend`. A log that has to be turned on
first is not useful during the first occurrence of an incident, which is
exactly when it is needed.
Two details worth calling out:
- The status is flattened to a single line. GCS error bodies end with a
newline, which would otherwise push the backend's `(file:line)` suffix
onto a second line and make the record unusable with `grep`. It also
removes a log-injection hazard, since the message is service-supplied.
- `UploadChunkRequest` only exposes the resumable session URL, and the
`upload_id` in it is a bearer capability: anyone holding it can append
to or finalize the upload for the lifetime of the session. Only the
bucket and an 8-character prefix of the id are logged, which is enough
to tell concurrent uploads apart.
Also makes `LoggingStub::ReadObject` report the status on failure. It
cannot use `LogWrapper` because `unique_ptr<ObjectReadSource>` has no
`operator<<`, so it previously logged nothing about why the call failed.
Verified against the storage-testbench using its fault-injection API, in
addition to the unit tests.
Follow-up to the synchronous paths. The asynchronous gRPC reads and the
bidi `Open` streams run through `AsyncRetryLoop` and the resume policies
instead of `RestRetryLoop`, so they need their own call sites. Same
format, same rationale: one WARNING per retried attempt, nothing at all
on success.
[gcs-retry] Open/resume: transient error on attempt 1,
resource=projects/_/buckets/my-bucket/my-object,
status=UNAVAILABLE: ...
Call sites:
- `AsyncConnectionImpl::Open` -- an attempt to open a bidi stream failed.
- `AsyncConnectionImpl::ReadObject`, in the connection factory -- an
attempt to start the read stream failed.
- `ReaderConnectionResume::OnRead` -- a read stream broke and is being
resumed.
- `ObjectDescriptorImpl::OnFinish` -- a bidi stream broke and is being
resumed.
Three things the async paths need that the sync ones did not:
- `AsyncStatusTraits` treats `kAborted` as transient while the sync
`StatusTraits` does not, so an aborted read would be retried but never
logged. `async/connection_impl.cc` uses a local predicate that matches
what the async retry loop actually does. It cannot live in the shared
helper: `storage/async/retry_policy.h` belongs to
`google_cloud_cpp_storage_grpc`, which the base `google_cloud_cpp_storage`
target cannot depend on.
- `LimitedErrorCountResumePolicy::OnFinish` returns `kContinue` for an OK
status, so `ObjectDescriptorImpl::Resume()` also runs after a clean
close. Without a guard every healthy bidi download logged a bogus
`status=OK` retry. `ReaderConnectionResume` is not affected, since
`OnRead()` returns early on OK.
- The attempt counter in `MakeReaderConnectionFactory` is shared across
the whole download, so it kept climbing over successive resumes and
reported things like "attempt 47". It is now reset before each
`AsyncRetryLoop`.
Depends on the `retry_logging` helper added for the synchronous paths.
Verified against the storage-testbench using its fault-injection API, in
addition to the unit tests.
58f96d9 to
bd9f7db
Compare
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## main #16468 +/- ##
==========================================
+ Coverage 92.34% 92.36% +0.01%
==========================================
Files 2246 2248 +2
Lines 214568 214945 +377
==========================================
+ Hits 198136 198524 +388
+ Misses 16432 16421 -11 ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
Important
Stacked on #16467. This branch is
retry-logging-sync+ the async commit.GitHub will not accept a fork branch as the base, so the diff below includes
#16467 until that one merges; it will narrow automatically afterwards.
For the async-only diff (9 files, 1 commit), see
retry-logging-sync...retry-logging-async.Please review #16467 first.
Context
#16467 explains the problem: transient GCS errors are retried with no output at
all, so a stalled read looks identical to a slow network and there is nothing to
grep for. That PR covers the synchronous paths and adds the shared
retry_logginghelper.The asynchronous gRPC reads and the bidi
Openstreams run throughAsyncRetryLoopand the resume policies rather thanRestRetryLoop, so theyneed their own call sites. Same format, same rationale: one
WARNINGperretried attempt, nothing at all on success.
Call sites
whereAsyncConnectionImpl::OpenOpenAsyncConnectionImpl::ReadObject(connection factory)ReadObject/openReaderConnectionResume::OnReadReadObject/resumeObjectDescriptorImpl::OnFinishOpen/resumeThree things the async paths needed that the sync ones did not
1. Async classifies
kAbortedas transient; sync does notAsyncStatusTraitstreatskAbortedas transient, while the synchronousStatusTraitsdoes not. Reusing the sharedIsTransientError()on the asyncsites would silently drop the diagnostic for exactly the aborted reads the async
loop does retry — the worst possible failure mode for a debugging aid.
The predicate could not be hoisted into the shared helper:
storage/async/retry_policy.hbelongs togoogle_cloud_cpp_storage_grpc, whichthe base
google_cloud_cpp_storagetarget cannot depend on. Soasync/connection_impl.ccuses a file-localIsAsyncTransient()in itsanonymous namespace, matching what the async retry loop actually does.
Pinned by
AsyncConnectionImplTest.LogsAbortedWhichOnlyAsyncRetries.2. Healthy bidi downloads were logging a bogus
status=OKretryLimitedErrorCountResumePolicy::OnFinishreturnskContinuefor an OKstatus, so
ObjectDescriptorImpl::Resume()also runs after a clean close. Thefirst version therefore emitted one
status=OK“retry” per successfuldownload — which would have been worse than no logging at all, since it trains
operators to ignore the prefix.
Fixed with a
bool const failed = !status.ok();guard.Pinned by
ObjectDescriptorImpl.CleanFinishIsNotReportedAsRetry.ReaderConnectionResumeis not affected:OnRead()returns early on OK.3. The attempt counter was never reset
The counter in
MakeReaderConnectionFactoryis shared across the wholedownload, so it kept climbing over successive resumes and reported things like
“attempt 47” on what was really the second attempt of a fresh retry loop. It is
now reset before each
AsyncRetryLoop.Testbench verification
Same harness as #16467 —
storage-testbench
v0.61.0,fault injection via
POST /retry_testwith the id passed throughinternal::GrpcSetupOptionas gRPC metadata,GOOGLE_CLOUD_CPP_ENABLE_CLOG=yes.AsyncClient::ReadObjectstorage.objects.get: 503 ×2(GRPC)ReadObject/resumeAsyncClient::Open(bidi)storage.objects.get: 503 ×2(GRPC)Openreturn-broken-stream-after-256K(GRPC)Open/resumeThe healthy-download control in #16467 stayed silent, which also exercises the
status=OKguard described above.Note
Scenario 5 produced
ReadObject/resume, not theReadObject/openinMakeReaderConnectionFactory. That is correct: for a gRPC server-streamingread
Start()succeeds and the error only surfaces on the firstRead(), sothe resume layer handles it. The
make_rpcsite only fires when the streamitself fails to start, which the testbench cannot provoke — it stays covered
by
AsyncConnectionImplTest.ReadObjectTooManyTransients.Tests
bazel test //google/cloud/storage:all→ 175 / 175 PASSED.New coverage in
connection_impl_open_test.cc,connection_impl_read_test.cc,object_descriptor_impl_test.cc,reader_connection_resume_test.cc— includingthe three regression tests named above and negative tests asserting nothing is
logged on a clean stream.
Internal ref: b/547926601