fix(audit): resolve 8-hour timezone offset in audit log timestamps

## Problem
Audit log timestamps displayed 8 hours later than actual time when JVM
default timezone != UTC. Root cause: `audit_log.created_at` was
`TIMESTAMP without time zone`, and `rs.getTimestamp()` interprets bare
values using JVM timezone.

## Solution
### Backend
- **V42 migration**: Upgrade `audit_log.created_at` from `TIMESTAMP` to
  `TIMESTAMPTZ`, anchor historical data as UTC via `USING created_at AT
  TIME ZONE 'UTC'` (same pattern as V18/V19/V23/V25/V36)
- **Read path**: `AdminAuditLogAppService.readInstant()` uses
  `rs.getObject(col, OffsetDateTime.class).toInstant()`, result
  independent of JVM timezone
- **Write path (filter params)**: `startTime`/`endTime` binding changed
  from `Timestamp.from()` to `OffsetDateTime.ofInstant(instant,
  ZoneOffset.UTC)` via `toUtcOffsetDateTime()` helper, symmetric with
  read path

### Migration Safety
- `SET LOCAL lock_timeout = '30s'` (transaction-scoped, won't leak to pool)
- `DO $$ ... IF data_type = 'timestamp without time zone' THEN ... ELSE
  ... END $$` idempotent guard with dual-branch `RAISE NOTICE`
- Safe retry: re-running won't double-apply `AT TIME ZONE 'UTC'`

### Test Coverage (10 tests, 477 total suite)
- `rowMapper_readsCreatedAtAsInstant` — UTC offset regression
- `rowMapper_normalisesNonUtcOffsetToInstant` — Non-UTC offset (+08:00)
- `rowMapper_returnsNullTimestampWhenColumnIsNull` — Null path
- `rowMapper_isIndependentOfJvmDefaultTimezone` — JVM TZ=Asia/Shanghai
  drift prevention with `verify(rs, never()).getTimestamp()`
- `@ParameterizedTest buildWhereClause_bindsTimeRangeAsOffsetDateTime` —
  3 cases (both/startOnly/endOnly) for filter param binding
- `@BeforeEach setUp()` — Mock isolation to prevent cross-test stub
  accumulation

## Quality Gates
- [x] `make test-backend-app` passes (477 tests, 0 failures)
- [x] No Controller changes, `make generate-api` not needed
- [x] No frontend changes, typecheck/lint/e2e not needed

## Deployment
V42 must run before new code (guaranteed by Spring Boot startup sequence
→ Flyway executes before app accepts traffic). Rolling deployment:
- New pod + migrated column: correct
- Old pod + migrated column: old code reads TIMESTAMPTZ correctly (pgjdbc
  returns absolute instant)

## Related Docs
- `docs/15-backend-time-governance-plan.md` §3.1: V42 progress registered
- `docs/16-backend-time-inventory.md` §3.1: V42 listed
- Same migration pattern: V18/V19/V23/V25/V36
This commit is contained in:
dongmucat 2026-06-02 16:50:34 +08:00
parent 8bd7a6bc1d
commit 969a3c5b85
5 changed files with 196 additions and 8 deletions

View file

@ -57,6 +57,10 @@
- 数据库列统一为 `TIMESTAMPTZ`
- 读写都按 UTC 绝对时间处理
进度登记:
- `audit_log.created_at` 已通过 V42 迁移到 `TIMESTAMPTZ`,详见 `docs/16-backend-time-inventory.md` §3.1
### 3.2 业务输入时间
适用场景:

View file

@ -131,6 +131,8 @@
- `review_task.submitted_at / reviewed_at`
- `promotion_request.submitted_at / reviewed_at`
- `idempotency_record.created_at / expires_at`
- `V42__audit_log_created_at_timestamptz.sql`
- `audit_log.created_at`
### 3.2 当前状态

View file

@ -8,8 +8,11 @@ import org.springframework.stereotype.Service;
import org.springframework.transaction.annotation.Transactional;
import org.springframework.util.StringUtils;
import java.sql.Timestamp;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.time.Instant;
import java.time.OffsetDateTime;
import java.time.ZoneOffset;
import java.util.Collection;
import java.util.List;
@ -109,7 +112,7 @@ public class AdminAuditLogAppService {
rs.getString("request_id"),
rs.getString("target_type"),
toResourceId(rs.getObject("target_id")),
toInstant(rs.getTimestamp("created_at")))
readInstant(rs, "created_at"))
);
return new PageResponse<>(items, total == null ? 0 : total, page, size);
@ -151,15 +154,21 @@ public class AdminAuditLogAppService {
}
if (startTime != null) {
clause.append(" AND al.created_at >= :startTime");
parameters.addValue("startTime", Timestamp.from(startTime));
parameters.addValue("startTime", toUtcOffsetDateTime(startTime));
}
if (endTime != null) {
clause.append(" AND al.created_at <= :endTime");
parameters.addValue("endTime", Timestamp.from(endTime));
parameters.addValue("endTime", toUtcOffsetDateTime(endTime));
}
return clause.toString();
}
// Bind via OffsetDateTime so pgjdbc sends a TIMESTAMPTZ literal anchored to UTC,
// bypassing JVM-default-timezone interpretation that caused the 8h-offset bug.
private static OffsetDateTime toUtcOffsetDateTime(Instant instant) {
return OffsetDateTime.ofInstant(instant, ZoneOffset.UTC);
}
private String renderDetails(String detailJson, String targetType, Object targetId) {
if (StringUtils.hasText(detailJson)) {
return detailJson;
@ -170,8 +179,11 @@ public class AdminAuditLogAppService {
return targetType + ":" + targetId;
}
private Instant toInstant(Timestamp timestamp) {
return timestamp == null ? null : timestamp.toInstant();
// Read via getObject(OffsetDateTime.class) to bypass JVM-TZ interpretation
// that caused the 8h-offset bug (getTimestamp() applies JVM default TZ).
private static Instant readInstant(ResultSet rs, String column) throws SQLException {
OffsetDateTime odt = rs.getObject(column, OffsetDateTime.class);
return odt == null ? null : odt.toInstant();
}
private String toResourceId(Object targetId) {

View file

@ -0,0 +1,39 @@
-- Fix audit_log.created_at timezone issue
-- Background: TIMESTAMP (without timezone) causes 8-hour offset when JVM timezone != UTC
-- Solution: Upgrade to TIMESTAMPTZ and anchor existing data as UTC
-- Related: docs/15-backend-time-governance-plan.md section 3.1
--
-- Operational notes:
-- * ALTER COLUMN ... TYPE rewrites the entire audit_log table and rebuilds
-- idx_audit_log_created_at, idx_audit_log_actor_time, idx_audit_log_action_time
-- under ACCESS EXCLUSIVE lock. Run during a low-traffic window.
-- * Before applying in production, check table size:
-- SELECT pg_size_pretty(pg_total_relation_size('audit_log'));
-- Tables in the multi-GB range may need a maintenance window.
-- * SET LOCAL lock_timeout below makes a contended ALTER fail fast (rather than
-- queueing behind long-running readers); operators may re-run the migration
-- after clearing contention. The DO block guards against re-running on a
-- column that has already been migrated, so retries are safe.
SET LOCAL lock_timeout = '30s';
DO $$
DECLARE
current_type text;
BEGIN
SELECT data_type
INTO current_type
FROM information_schema.columns
WHERE table_schema = current_schema()
AND table_name = 'audit_log'
AND column_name = 'created_at';
IF current_type = 'timestamp without time zone' THEN
ALTER TABLE audit_log
ALTER COLUMN created_at TYPE TIMESTAMPTZ
USING created_at AT TIME ZONE 'UTC';
RAISE NOTICE 'V42: audit_log.created_at -> TIMESTAMPTZ (UTC anchored)';
ELSE
RAISE NOTICE 'V42: audit_log.created_at already % (skipped)', current_type;
END IF;
END $$;

View file

@ -2,13 +2,21 @@ package com.iflytek.skillhub.service;
import com.iflytek.skillhub.dto.AuditLogItemResponse;
import com.iflytek.skillhub.dto.PageResponse;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;
import org.junit.jupiter.params.ParameterizedTest;
import org.junit.jupiter.params.provider.CsvSource;
import org.mockito.ArgumentCaptor;
import org.springframework.jdbc.core.RowMapper;
import org.springframework.jdbc.core.namedparam.MapSqlParameterSource;
import org.springframework.jdbc.core.namedparam.NamedParameterJdbcTemplate;
import java.sql.ResultSet;
import java.time.Instant;
import java.time.OffsetDateTime;
import java.time.ZoneOffset;
import java.util.List;
import java.util.TimeZone;
import static org.assertj.core.api.Assertions.assertThat;
import static org.mockito.ArgumentMatchers.*;
@ -16,8 +24,14 @@ import static org.mockito.Mockito.*;
class AdminAuditLogAppServiceTest {
private final NamedParameterJdbcTemplate jdbcTemplate = mock(NamedParameterJdbcTemplate.class);
private final AdminAuditLogAppService service = new AdminAuditLogAppService(jdbcTemplate);
private NamedParameterJdbcTemplate jdbcTemplate;
private AdminAuditLogAppService service;
@BeforeEach
void setUp() {
jdbcTemplate = mock(NamedParameterJdbcTemplate.class);
service = new AdminAuditLogAppService(jdbcTemplate);
}
@Test
void listAuditLogs_returnsJdbcBackedPage() {
@ -62,4 +76,121 @@ class AdminAuditLogAppServiceTest {
any(MapSqlParameterSource.class),
any(RowMapper.class));
}
/**
* Regression for the 8-hour offset bug: row mapper must read created_at via
* getObject(OffsetDateTime.class) so the returned Instant is independent of
* the JVM default timezone.
*/
@Test
void rowMapper_readsCreatedAtAsInstant() throws Exception {
RowMapper<AuditLogItemResponse> rowMapper = captureRowMapper();
ResultSet rs = stubRowWithCreatedAt(
OffsetDateTime.of(2026, 5, 29, 8, 53, 0, 0, ZoneOffset.UTC));
AuditLogItemResponse item = rowMapper.mapRow(rs, 0);
assertThat(item).isNotNull();
assertThat(item.timestamp()).isEqualTo(Instant.parse("2026-05-29T08:53:00Z"));
verify(rs, never()).getTimestamp(anyString());
}
@Test
void rowMapper_normalisesNonUtcOffsetToInstant() throws Exception {
RowMapper<AuditLogItemResponse> rowMapper = captureRowMapper();
ResultSet rs = stubRowWithCreatedAt(
OffsetDateTime.of(2026, 5, 29, 16, 53, 0, 0, ZoneOffset.ofHours(8)));
AuditLogItemResponse item = rowMapper.mapRow(rs, 0);
assertThat(item.timestamp()).isEqualTo(Instant.parse("2026-05-29T08:53:00Z"));
}
@Test
void rowMapper_returnsNullTimestampWhenColumnIsNull() throws Exception {
RowMapper<AuditLogItemResponse> rowMapper = captureRowMapper();
ResultSet rs = stubRowWithCreatedAt(null);
AuditLogItemResponse item = rowMapper.mapRow(rs, 0);
assertThat(item.timestamp()).isNull();
}
@ParameterizedTest
@CsvSource(nullValues = "NULL", value = {
"2026-03-13T00:00:00Z, 2026-03-14T00:00:00Z",
"2026-03-13T00:00:00Z, NULL",
"NULL, 2026-03-14T00:00:00Z"
})
void buildWhereClause_bindsTimeRangeAsOffsetDateTime(String startStr, String endStr) {
when(jdbcTemplate.queryForObject(contains("COUNT(*)"), any(MapSqlParameterSource.class), eq(Long.class)))
.thenReturn(0L);
when(jdbcTemplate.query(contains("FROM audit_log"), any(MapSqlParameterSource.class), any(RowMapper.class)))
.thenReturn(List.of());
Instant startTime = startStr == null ? null : Instant.parse(startStr);
Instant endTime = endStr == null ? null : Instant.parse(endStr);
service.listAuditLogs(0, 20, null, null, null, null, null, null, startTime, endTime);
ArgumentCaptor<MapSqlParameterSource> paramsCaptor = ArgumentCaptor.forClass(MapSqlParameterSource.class);
verify(jdbcTemplate).query(contains("FROM audit_log"), paramsCaptor.capture(), any(RowMapper.class));
MapSqlParameterSource params = paramsCaptor.getValue();
if (startTime != null) {
assertThat(params.getValue("startTime"))
.isEqualTo(OffsetDateTime.ofInstant(startTime, ZoneOffset.UTC));
} else {
assertThat(params.hasValue("startTime")).isFalse();
}
if (endTime != null) {
assertThat(params.getValue("endTime"))
.isEqualTo(OffsetDateTime.ofInstant(endTime, ZoneOffset.UTC));
} else {
assertThat(params.hasValue("endTime")).isFalse();
}
}
@Test
void rowMapper_isIndependentOfJvmDefaultTimezone() throws Exception {
TimeZone original = TimeZone.getDefault();
try {
TimeZone.setDefault(TimeZone.getTimeZone("Asia/Shanghai"));
RowMapper<AuditLogItemResponse> rowMapper = captureRowMapper();
ResultSet rs = stubRowWithCreatedAt(
OffsetDateTime.of(2026, 5, 29, 8, 53, 0, 0, ZoneOffset.UTC));
AuditLogItemResponse item = rowMapper.mapRow(rs, 0);
assertThat(item).isNotNull();
assertThat(item.timestamp()).isEqualTo(Instant.parse("2026-05-29T08:53:00Z"));
verify(rs, never()).getTimestamp(anyString());
} finally {
TimeZone.setDefault(original);
}
}
@SuppressWarnings("unchecked")
private RowMapper<AuditLogItemResponse> captureRowMapper() {
when(jdbcTemplate.queryForObject(contains("COUNT(*)"), any(MapSqlParameterSource.class), eq(Long.class)))
.thenReturn(0L);
ArgumentCaptor<RowMapper<AuditLogItemResponse>> captor = ArgumentCaptor.forClass(RowMapper.class);
when(jdbcTemplate.query(contains("FROM audit_log"), any(MapSqlParameterSource.class), captor.capture()))
.thenReturn(List.of());
service.listAuditLogs(0, 20, null, null, null, null, null, null, null, null);
return captor.getValue();
}
private static ResultSet stubRowWithCreatedAt(OffsetDateTime createdAt) throws Exception {
ResultSet rs = mock(ResultSet.class);
when(rs.getLong("id")).thenReturn(1L);
when(rs.getString("action")).thenReturn("PROMOTION_SUBMIT");
when(rs.getString("actor_user_id")).thenReturn("user-1");
when(rs.getString("display_name")).thenReturn("alice");
when(rs.getString("detail_json")).thenReturn("{}");
when(rs.getString("target_type")).thenReturn("PROMOTION");
when(rs.getObject("target_id")).thenReturn(42L);
when(rs.getString("client_ip")).thenReturn("127.0.0.1");
when(rs.getString("request_id")).thenReturn("req-1");
when(rs.getObject("created_at", OffsetDateTime.class)).thenReturn(createdAt);
return rs;
}
}