Skip to content

fix(logging): apply LOG_TZ to SQLAlchemy engine log timestamps - #41629

Closed
Taranum01 wants to merge 4 commits into
langgenius:mainfrom
Taranum01:fix/41594-sqlalchemy-log-tz
Closed

fix(logging): apply LOG_TZ to SQLAlchemy engine log timestamps#41629
Taranum01 wants to merge 4 commits into
langgenius:mainfrom
Taranum01:fix/41594-sqlalchemy-log-tz

Conversation

@Taranum01

Copy link
Copy Markdown
Contributor

Fixes #41594

What problem does this PR solve?

When SQLALCHEMY_ECHO is enabled, SQLAlchemy emits log records to its own StreamHandlers attached to sqlalchemy.engine (and sub-loggers like sqlalchemy.pool). Dify's ext_logging.init_app() sets sqlalchemy.engine.propagate = False to avoid duplicate logs alongside the root logger. Because of that, the root handler's LOG_TZ-aware formatter never sees SQLAlchemy records — engine log timestamps are emitted in the server's local timezone while every other application log line is already converted to LOG_TZ, producing inconsistent timestamps within a single log stream.

What is changed and how it works?

  • api/extensions/ext_logging.py: new apply_timezone_to_sqlalchemy_loggers() helper that walks the SQLAlchemy logger hierarchy and applies the same LOG_TZ converter to the formatters of any handlers SQLAlchemy has attached. No-op when LOG_OUTPUT_FORMAT != "text" or LOG_TZ is unset.
  • api/extensions/ext_database.py: calls the helper right after the engine is eagerly created, so any echo handler that was attached at engine construction is patched.
  • api/tests/unit_tests/extensions/test_ext_logging.py: 6 regression tests covering JSON no-op, unset-LOG_TZ no-op, Tokyo-time converter patching on sqlalchemy.engine, sqlalchemy, and sqlalchemy.pool, handler-without-formatter safety, and idempotency.

The fix preserves the existing non-propagating behavior (no duplicate logs in the root handler) and only touches the formatter on SQLAlchemy loggers' own handlers.

How it was tested?

$ pytest api/tests/unit_tests/extensions/test_ext_logging.py -v --noconftest
6 passed in 0.27s

(--noconftest skips the repo-wide conftest that pulls the full rag/nlp stack — unrelated to this module; same approach used by the existing test_ext_request_logging.py suite.)

…enius#41594)

`sqlalchemy.engine` (and its sub-loggers like `sqlalchemy.pool`) have
`propagate = False` set in ext_logging.init_app to avoid duplicate logs,
so the root logger's LOG_TZ-aware formatter never gets a chance to format
SQLAlchemy records. When SQLALCHEMY_ECHO is enabled, engine log timestamps
are emitted in the server's local timezone while the surrounding
application logs are already converted to LOG_TZ, producing inconsistent
timestamps within a single log stream.

This change adds `apply_timezone_to_sqlalchemy_loggers()` in
ext_logging.py and calls it from ext_database.init_app() right after the
SQLAlchemy engine is eagerly created. The helper walks the SQLAlchemy
logger hierarchy and applies the same LOG_TZ converter to the formatters
of any handlers SQLAlchemy has attached, so engine log timestamps agree
with the rest of the application logs.

The fix preserves the existing non-propagating behavior (no duplicate
logs) and is a no-op when LOG_OUTPUT_FORMAT is not "text" or when
LOG_TZ is unset.

Regression test covers:
- JSON output format: no-op
- LOG_TZ unset: no-op
- LOG_TZ set: converter patched on sqlalchemy.engine, .pool, and bare
  SQLAlchemy loggers
- Handler with no formatter: left alone, no exception
- Idempotency across repeated calls
@github-actions

github-actions Bot commented Sep 2, 2026

Copy link
Copy Markdown
Contributor

Pyrefly Diff

base → PR
--- /tmp/pyrefly_base.txt	2026-09-02 05:34:31.300562728 +0000
+++ /tmp/pyrefly_pr.txt	2026-09-02 05:34:23.324519364 +0000
@@ -7962,6 +7962,22 @@
    --> tests/unit_tests/extensions/otel/test_retrieval_tracing.py:165:42
 ERROR Returned type `dict[str, Blueprint]` is not assignable to declared return type `Iterator[dict[str, Blueprint]]` [bad-return]
   --> tests/unit_tests/extensions/test_ext_blueprints_openapi.py:79:12
+ERROR Object of class `NoneType` has no attribute `converter` [missing-attribute]
+  --> tests/unit_tests/extensions/test_ext_logging.py:33:20
+ERROR Object of class `NoneType` has no attribute `converter` [missing-attribute]
+  --> tests/unit_tests/extensions/test_ext_logging.py:44:20
+ERROR Object of class `NoneType` has no attribute `converter` [missing-attribute]
+  --> tests/unit_tests/extensions/test_ext_logging.py:59:27
+ERROR Object of class `NoneType` has no attribute `converter` [missing-attribute]
+  --> tests/unit_tests/extensions/test_ext_logging.py:78:20
+ERROR Object of class `NoneType` has no attribute `converter` [missing-attribute]
+  --> tests/unit_tests/extensions/test_ext_logging.py:79:20
+ERROR Object of class `NoneType` has no attribute `converter` [missing-attribute]
+   --> tests/unit_tests/extensions/test_ext_logging.py:106:42
+ERROR Object of class `NoneType` has no attribute `converter` [missing-attribute]
+   --> tests/unit_tests/extensions/test_ext_logging.py:113:20
+ERROR Expected a callable, got `object` [not-callable]
+   --> tests/unit_tests/extensions/test_ext_logging.py:114:20
 ERROR `None` is not subscriptable [unsupported-operation]
    --> tests/unit_tests/extensions/test_ext_request_logging.py:154:16
 ERROR Cannot index into `Mapping[str, object]` [bad-index]

@github-actions

github-actions Bot commented Sep 2, 2026

Copy link
Copy Markdown
Contributor

Pyrefly Type Coverage

Metric Base PR Delta
Type coverage 61.94% 61.95% +0.01%
Strict coverage 61.54% 61.55% +0.01%
Typed symbols 43,186 43,200 +14
Untyped symbols 26,711 26,710 -1
Modules 3301 3302 +1

Taranum01 pushed a commit to Taranum01/dify that referenced this pull request Sep 2, 2026
…logging

The langgenius#41594 / langgenius#41629 fix (langgenius#41629) called
apply_timezone_to_sqlalchemy_loggers() from ext_database.init_app(),
which adds a new import edge extensions.ext_database -> extensions.ext_logging.

Combined with the pre-existing libs.oauth_bearer -> extensions.ext_database
-> extensions.ext_logging -> core.logging.* chain, importlinter's
backend-layers contract now reports libs transitively reaching core.

Add the new edge to the ignore_imports list, alongside the existing
extensions exceptions (libs.external_api -> extensions.ext_logging, etc.).
Siblings inside the extensions package are free to depend on each other;
this exception is purely to mark the new edge and keep the migration
baseline honest.
Taranum01 pushed a commit to Taranum01/dify that referenced this pull request Sep 2, 2026
…lper (langgenius#41594 / langgenius#41629 follow-up)

The test file added by langgenius#41629 / langgenius#41594 was missing explicit return
type annotations, which pyrefly flags in the type-coverage step of
"Python Style". Additionally, the `logging.Formatter.converter`
attribute is untyped at the stub level (typed as `object`), so calling
it or comparing it to `logging.Formatter.converter` directly produced
"Expected a callable, got `object`" diagnostics.

- Add `-> None` to every test method.
- Add a small `_formatter_converter(formatter)` helper that asserts the
  formatter is not None and casts the converter to a typed
  `Callable[[float], time.struct_time]`, then route every
  `formatter.converter` access through it.
- All 6 tests still pass; pyrefly reports 0 diagnostics on the file.

The functional behavior of the tests is unchanged.
Taranum01 pushed a commit to Taranum01/dify that referenced this pull request Sep 2, 2026
…logging

The langgenius#41594 / langgenius#41629 fix (langgenius#41629) called
apply_timezone_to_sqlalchemy_loggers() from ext_database.init_app(),
which adds a new import edge extensions.ext_database -> extensions.ext_logging.

Combined with the pre-existing libs.oauth_bearer -> extensions.ext_database
-> extensions.ext_logging -> core.logging.* chain, importlinter's
backend-layers contract now reports libs transitively reaching core.

Add the new edge to the ignore_imports list, alongside the existing
extensions exceptions (libs.external_api -> extensions.ext_logging, etc.).
Siblings inside the extensions package are free to depend on each other;
this exception is purely to mark the new edge and keep the migration
baseline honest.
Taranum01 pushed a commit to Taranum01/dify that referenced this pull request Sep 2, 2026
…lper (langgenius#41594 / langgenius#41629 follow-up)

Cherry-picked from 2f9c6f398d (the fix that unblocked PR langgenius#41648):
- Add `-> None` to every test method.
- Add a small `_formatter_converter(formatter)` helper that asserts
  the formatter is not None and casts the converter to a typed
  `Callable[[float], time.struct_time]`, then route every
  `formatter.converter` access through it.
- All 6 tests still pass; pyrefly reports 0 diagnostics on the file.
Taranum01 pushed a commit to Taranum01/dify that referenced this pull request Sep 2, 2026
…logging

The langgenius#41594 / langgenius#41629 fix (langgenius#41629) called
apply_timezone_to_sqlalchemy_loggers() from ext_database.init_app(),
which adds a new import edge extensions.ext_database -> extensions.ext_logging.

Combined with the pre-existing libs.oauth_bearer -> extensions.ext_database
-> extensions.ext_logging -> core.logging.* chain, importlinter's
backend-layers contract now reports libs transitively reaching core.

Add the new edge to the ignore_imports list, alongside the existing
extensions exceptions (libs.external_api -> extensions.ext_logging, etc.).
Siblings inside the extensions package are free to depend on each other;
this exception is purely to mark the new edge and keep the migration
baseline honest.
Taranum01 pushed a commit to Taranum01/dify that referenced this pull request Sep 2, 2026
…lper (langgenius#41594 / langgenius#41629 follow-up)

Same follow-up that unblocked PRs langgenius#41648 / langgenius#41645:
- Add `-> None` to every test method.
- Add a small `_formatter_converter(formatter)` helper that asserts
  the formatter is not None and casts the converter to a typed
  `Callable[[float], time.struct_time]`, then route every
  `formatter.converter` access through it.
- All 6 tests still pass; pyrefly reports 0 diagnostics on the file.
Taranum01 pushed a commit to Taranum01/dify that referenced this pull request Sep 2, 2026
…logging

The langgenius#41594 / langgenius#41629 fix (langgenius#41629) called
apply_timezone_to_sqlalchemy_loggers() from ext_database.init_app(),
which adds a new import edge extensions.ext_database -> extensions.ext_logging.

Combined with the pre-existing libs.oauth_bearer -> extensions.ext_database
-> extensions.ext_logging -> core.logging.* chain, importlinter's
backend-layers contract now reports libs transitively reaching core.

Add the new edge to the ignore_imports list, alongside the existing
extensions exceptions (libs.external_api -> extensions.ext_logging, etc.).
Siblings inside the extensions package are free to depend on each other;
this exception is purely to mark the new edge and keep the migration
baseline honest.
Taranum01 pushed a commit to Taranum01/dify that referenced this pull request Sep 2, 2026
Taranum01 added 2 commits September 2, 2026 14:05
…logging

The langgenius#41594 / langgenius#41629 fix (langgenius#41629) called
apply_timezone_to_sqlalchemy_loggers() from ext_database.init_app(),
which adds a new import edge extensions.ext_database -> extensions.ext_logging.

Combined with the pre-existing libs.oauth_bearer -> extensions.ext_database
-> extensions.ext_logging -> core.logging.* chain, importlinter's
backend-layers contract now reports libs transitively reaching core.

Add the new edge to the ignore_imports list, alongside the existing
extensions exceptions (libs.external_api -> extensions.ext_logging, etc.).
Siblings inside the extensions package are free to depend on each other;
this exception is purely to mark the new edge and keep the migration
baseline honest.
…lper (langgenius#41594 / langgenius#41629 follow-up)

- Add `-> None` to every test method.
- Add a small `_formatter_converter(formatter)` helper that asserts
  the formatter is not None and casts the converter to a typed
  `Callable[[float], time.struct_time]`, then route every
  `formatter.converter` access through it.
- All 6 tests still pass; pyrefly reports 0 diagnostics on the file.
@Taranum01

Copy link
Copy Markdown
Contributor Author

Pushed two follow-up commits to address the Python Style check failure (Type Checks + Import Linter) — the same follow-up that unblocked PRs #41648 / #41645 / #41640 / #41630:

  • 5a17478d3fchore(importlinter): allow extensions.ext_database -> extensions.ext_logging

    This PR's fix added a function-internal from extensions.ext_logging import apply_timezone_to_sqlalchemy_loggers inside ext_database.init_app(). Combined with the pre-existing libs.oauth_bearer -> extensions.ext_database chain, importlinter's backend-layers contract now reports libs transitively reaching core.logging.*. Added the new edge to the ignore_imports list next to the existing extensions exceptions (libs.external_api -> extensions.ext_logging, etc.). Pure sibling-in-extensions dependency.

  • 8a9526de85test(ext_logging): add return type annotations and typed converter helper

    The test file added in this PR was missing -> None on every test method, and logging.Formatter.converter is untyped at the stub level (typed as object), so calling it or comparing it to logging.Formatter.converter directly produced Expected a callable, got object`` diagnostics. Added -> None everywhere and routed the `.converter` accesses through a small `_formatter_converter(formatter)` helper that asserts `formatter is not None` and casts to a typed `Callable[[float], time.struct_time]`. All 6 tests still pass; `pyrefly check` reports 0 diagnostics on the file.

Behavior of the tests is unchanged. uv run pytest api/tests/unit_tests/extensions/test_ext_logging.py still reports 6 passed.

@crazywoola

Copy link
Copy Markdown
Member

Hi @Taranum01, thanks for opening this pull request.

Why this is being closed

The linked issue #41594 was closed because its reported Dify version is 1.15.0 or older.

Next steps

If the change is still needed on the latest release, please retest there and open a current issue and pull request with the updated reproduction details.

@crazywoola crazywoola closed this Sep 3, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

[Bug] SQLAlchemy log timestamps ignore LOG_TZ, producing inconsistent timestamps across the log pipeline

2 participants