fix: suppress misleading backoff library log in user_defined_backoff_handler#981
Conversation
…handler
The backoff library's default logger reported 'Backing off _send(...) for 0.0s'
because user_defined_backoff_handler uses interval=0 (actual sleep happens in
the on_backoff callback). This caused confusion and incorrect bug reports.
Changes:
- Pass logger=None to backoff.on_exception() to suppress the misleading default
log message that reports the interval (0s) instead of the actual sleep time
- Improve sleep_on_ratelimit log to show HTTP status code and actual retry time:
'Rate limit exceeded (HTTP 429). Retrying in {N} seconds.'
- Format elapsed time in log_give_up for consistency
Co-Authored-By: bot_apk <apk@cognition.ai>
🤖 Devin AI EngineerI'll be helping with this pull request! Here's what you should know: ✅ I will automatically:
Note: I can only respond to comments from users who have write access to this repository. ⚙️ Control Options:
|
👋 Greetings, Airbyte Team Member!Here are some helpful tips and reminders for your convenience. 💡 Show Tips and TricksTesting This CDK VersionYou can test this version of the CDK using the following: # Run the CLI from this branch:
uvx 'git+https://github.com/airbytehq/airbyte-python-cdk.git@devin/1775496581-fix-misleading-backoff-log-message#egg=airbyte-python-cdk[dev]' --help
# Update a connector to use the CDK from this branch ref:
cd airbyte-integrations/connectors/source-example
poe use-cdk-branch devin/1775496581-fix-misleading-backoff-log-messagePR Slash CommandsAirbyte Maintainers can execute the following slash commands on your PR:
|
|
enhance logs to inform user that the error comes from UserDefinedBackoffException. |
… feedback Co-Authored-By: bot_apk <apk@cognition.ai>
|
sophiecuiy Done — prepended Pushed in 789ce9d. |
There was a problem hiding this comment.
Pull request overview
Adjusts retry logging for the user_defined_backoff_handler to avoid misleading backoff library messages (reporting 0.0s interval) and to provide a clearer, single log line describing the actual retry delay.
Changes:
- Updates
sleep_on_ratelimitto log a clearer “rate limit exceeded” message including the retry delay. - Tweaks the give-up log message formatting for elapsed time.
- Passes
logger=Nonetobackoff.on_exception()to suppress the library’s default backoff logging.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
…og, kwargs conflict Co-Authored-By: bot_apk <apk@cognition.ai>
|
/ai-prove-fix |
Proof of FixRan a proof script that exercises 1.
|
| Old | New | |
|---|---|---|
| Message | Backing off _send(...) for 0.0s (UserDefinedBackoffException: HTTP Status Code: 429...) |
UserDefinedBackoffException: Rate limit exceeded (HTTP 429). Retrying in 61 seconds. |
| Reported time | 0.0s (misleading) | 61s (accurate) |
| HTTP status | Buried in exception string | Clear (HTTP 429) |
| 429 response logged? | No — if exc.response: was False for 429 |
Yes — exc.response is not None is True |
Full proof script
import logging, sys, time
from unittest.mock import MagicMock, patch
from requests import Response
from airbyte_cdk.sources.streams.http.exceptions import UserDefinedBackoffException
from airbyte_cdk.sources.streams.http.rate_limiting import user_defined_backoff_handler
real_response = Response()
real_response.status_code = 429
real_response._content = b"Too many requests"
call_count = 0
def mock_send(request, kwargs):
global call_count
call_count += 1
if call_count <= 2:
raise UserDefinedBackoffException(backoff=60, request=MagicMock(), response=real_response)
return MagicMock()
decorated = user_defined_backoff_handler(max_tries=3)(mock_send)
with patch("airbyte_cdk.sources.streams.http.rate_limiting.time.sleep") as mock_sleep:
result = decorated(MagicMock(), {})
for i, call in enumerate(mock_sleep.call_args_list):
print(f"sleep({call.args[0]})")
Summary
The
backofflibrary's default logger produces a misleading message whenuser_defined_backoff_handlerretries:The
0.0sis the backoff library'sintervalparameter (set to0), not the actual sleep time. The real sleep happens in theon_backoffcallback (sleep_on_ratelimit) and is typically 60+ seconds. This generates confusion and incorrect bug reports from users.Fix: Pass
logger=Nonetobackoff.on_exception()to suppress the library's default log handler, and improve the customsleep_on_ratelimitcallback to emit a single clear message:No changes to retry logic or sleep behavior — only logging is affected.
Resolves https://github.com/airbytehq/airbyte-internal-issues/issues/16135
Related to https://github.com/airbytehq/oncall/issues/11837
Updates since last revision
UserDefinedBackoffException:to both log messages insleep_on_ratelimitper reviewer feedback, so the error source is immediately visible in logs.if exc.response:→exc.response is not None:requests.Response.__bool__returnsFalsefor status >= 400, so the old check (pre-existing bug) would skip the HTTP status code branch on 429 responses.retry_after + 1) instead of justretry_after, so the logged time matches the real sleep.kwargs.pop("logger", None)before passinglogger=Nonetobackoff.on_exception()to preventTypeErrorif a caller ever passesloggerin kwargs.Review & Testing Checklist for Human
exc.response is not Nonebehavior change: The old code usedif exc.response:which was falsey for HTTP error responses (including 429). The fix means the status code will now appear in logs where it previously did not. Confirm this is the desired behavior.Response Content: {exc.response.content!r}on every retry attempt. The new code omits this in favor of a cleaner user-facing message. Verify this trade-off is acceptable.source-amazon-seller-partner) and confirm: (1) no more"Backing off _send(...) for 0.0s"messages appear, (2) the new"UserDefinedBackoffException: Rate limit exceeded (HTTP 429). Retrying in {N} seconds."message appears instead, (3) retry/sleep behavior is unchanged.Notes
user_defined_backoff_handler. The change is logging-only and isolated to one function.default_backoff_handler,http_client_default_backoff_handler,rate_limit_default_backoff_handler) are not affected — they usebackoff.expowith real intervals so their default log messages are accurate.Link to Devin session: https://app.devin.ai/sessions/2ced27cd22bd409f845816cd10a0c5f4