Repository navigation
Added Outbox Workder Logging - #27
Conversation
dushyantpant5
left a comment
dushyantpant5
left a comment
There was a problem hiding this comment.
Overall the MDC/structured-logging idea is solid, but there are a few correctness issues worth fixing before merge.
|
|
||
| private void processEvent(T event) { | ||
| try { | ||
| OutboxMdc.putEventContext(event); |
There was a problem hiding this comment.
Bug — MDC cleared before this scope finishes.
publisher.publish() calls OutboxMdc.clear() in its own finally block before returning. So by the time publish() returns (or throws), MDC is already empty. The log.info("Event marked PROCESSED…") a few lines below and every log inside handleFailure will have blank event_id/job_id in the Logback pattern.
Fix: only one level should own the MDC lifetime. Either remove OutboxMdc.putEventContext + clear from publish() (let the caller manage context) or remove it from here (let publish manage its own scope and accept that markProcessed / handleFailure won't carry MDC).
| if (nextRetryCount >= event.getMaxRetries()) { | ||
| repository.markDead(event.getId(), nextRetryCount, errorMsg); | ||
| log.error("Event {} permanently dead after {} retries: {}", event.getId(), nextRetryCount, e.getMessage()); | ||
| log.error("Event moved to DEAD after {} retries: {}", nextRetryCount, errorMsg); |
There was a problem hiding this comment.
Bug — event.getId() dropped while MDC is already empty.
The old log line passed event.getId() as a format argument. This replacement relies entirely on MDC for the event ID — but publish()'s finally clears MDC before handleFailure is ever reached. Result: every DEAD-event log line has no event identity anywhere (not in the message, not in the Logback %X{event_id} field).
| repository.reschedule(event.getId(), nextRetryCount, backoffSeconds, errorMsg); | ||
| log.warn("Event {} failed, retry {}/{} scheduled in {}s", | ||
| event.getId(), nextRetryCount, event.getMaxRetries(), backoffSeconds); | ||
| log.warn("Publish failed, retry {}/{} scheduled in {}s: {}", |
There was a problem hiding this comment.
Same issue as the log.error above — event.getId() was removed from the format args and MDC is empty by the time this runs. Retry log lines will have no event identity.
| } | ||
|
|
||
| private String truncate(String s, int max) { | ||
| public static String truncate(String s, int max) { |
There was a problem hiding this comment.
Package cycle.
Making this public static so RabbitMQEventPublisher can call OutboxPollingService.truncate(…) creates a publisher → service → publisher cycle (OutboxPollingService depends on IEventPublisher which lives in publisher). Move truncate to OutboxMdc or a small string-utility class that neither package owns.
| import com.clipforge.outboxworker.config.OutboxProperties; | ||
| import com.clipforge.outboxworker.logging.OutboxMdc; | ||
| import com.clipforge.outboxworker.model.IOutboxEvent; | ||
| import com.clipforge.outboxworker.service.OutboxPollingService; |
There was a problem hiding this comment.
Package cycle — publisher importing a service class.
OutboxPollingService (service package) depends on IEventPublisher (this package). Adding the reverse dependency here creates a cycle. Any module-boundary tooling (ArchUnit, Maven Enforcer) will flag this. See the comment on OutboxPollingService.truncate for the fix.
| jdbc.update(""" | ||
| UPDATE events.job_events | ||
| SET status = 'PENDING', locked_by = NULL, locked_at = NULL | ||
| WHERE id = :id |
There was a problem hiding this comment.
TOCTOU race — no status guard on the per-row UPDATE.
The old code's atomic UPDATE … WHERE status = 'PROCESSING' AND locked_at < … AND retry_count < max_retries was safe: it only touched rows still matching all conditions. This WHERE id = :id has no re-check of status.
Scenario: event X is selected as a stale candidate at T=0. At T=1, a worker completes processing and calls markProcessed (sets status = 'PROCESSED'). At T=2, this UPDATE fires and silently resets status back to 'PENDING'. The polling loop picks the event up again and publishes it a second time to RabbitMQ — a silent duplicate.
Fix: add AND status = 'PROCESSING' to the WHERE clause (and ideally the timeout condition too).
| for (RecoveredLease lease : resetLeases) { | ||
| jdbc.update(""" | ||
| UPDATE events.job_events | ||
| SET status = 'PENDING', locked_by = NULL, locked_at = NULL |
There was a problem hiding this comment.
Minor: updated_at is not refreshed here. The dead-lease UPDATE below correctly sets updated_at = now(), but this PENDING-reset UPDATE leaves the column stale. Any monitoring query tracking event age via updated_at will miss recovered leases.
| UPDATE events.job_events | ||
| SET status = 'DEAD', locked_by = NULL, locked_at = NULL, | ||
| last_error = 'Stale lease: processing timed out', updated_at = now() | ||
| WHERE id = :id |
There was a problem hiding this comment.
Same TOCTOU race as the reset-lease UPDATE above — WHERE id = :id with no status guard. An event could be moved out of PROCESSING between the SELECT and this UPDATE, causing the blind overwrite to corrupt its state.
| } | ||
|
|
||
| public static void clear() { | ||
| MDC.clear(); |
There was a problem hiding this comment.
MDC.clear() removes all MDC context, not just the keys this class added. If Spring Security, a request-tracing library, or any other framework has set MDC keys on this thread, they'll be silently dropped.
Prefer:
MDC.remove("event_id");
MDC.remove("job_id");| <?xml version="1.0" encoding="UTF-8"?> | ||
| <configuration> | ||
| <property name="CONSOLE_LOG_PATTERN" | ||
| value="%d{ISO8601} %-5level [event_id=%X{event_id}, job_id=%X{job_id}] %logger - %msg%n"/> |
There was a problem hiding this comment.
When MDC values are absent (startup logs, heartbeat, shutdown), %X{event_id} and %X{job_id} render as empty strings, so every such line will print [event_id=, job_id=]. This clutters logs and causes grep 'event_id=' to match far more than intended.
Use the default-value form to suppress blanks:
%X{event_id:- } %X{job_id:- }
or wrap in a conditional if your Logback version supports it.
2 participants
No description provided.