Skip to content

fix(telemetry): write fixed-width UTC timestamps - #821

Merged
ParidelPooya merged 3 commits into
mainfrom
fix/telemetry-timestamp-format
Oct 23, 2026
Merged

ParidelPooya merged 3 commits into
mainfrom
fix/telemetry-timestamp-format

Conversation

@ParidelPooya

@ParidelPooya ParidelPooya commented Oct 23, 2026 •

Copy link
Copy Markdown
Contributor

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.

Summary

Every Durable Execution Telemetry record timestamp now has one fixed-width UTC format: YYYY-MM-DDTHH:MM:SS.sssZ. The fraction always has 3 digits. The value always ends with the literal Z. This is the format of JavaScript's Date.prototype.toISOString().

Why:

  1. We deployed the JS, Python and Java exporters and ran the same workflow through each.
  2. Java wrote startTime with 3 fraction digits. In the same record it wrote endTime and emittedAt with 9, for example 2026-10-23T18:42:44.078757096Z.
  3. The cause is Instant.toString(). It writes as many fraction digits as the value needs. It writes no fraction when the fraction is zero, for example 2026-10-23T18:42:40Z.
  4. JS always writes 3 digits. Python writes 6.
  5. DynamoDB, CloudWatch Logs Insights, and string columns compare these values as text.
  6. Text order equals time order only when every value has the same width.
  7. We measured the effect. …40Z sorts after …40.500Z, because Z sorts after .. The filter endtime >= '2026-10-23T18:42:46Z' excluded all 7 records that ended in that second.
  8. So every SDK will write one fixed-width format. JS already writes it. So that format is the one we use.

Changes:

  • emittedAt, startTime and endTime on the record, and startTime and endTime on each operation, now go through one helper: Timestamps.format(Instant).
  • The helper uses DateTimeFormatter.ofPattern("uuuu-MM-dd'T'HH:mm:ss.SSS'Z'").withZone(ZoneOffset.UTC). Digits below the millisecond are dropped, not rounded. So .078757096 becomes .078, and .999999999 becomes .999.
  • TelemetryPlugin produces all record timestamps. No other main code in telemetry-exporter produces a record timestamp string.
  • LambdaLogExporter had its own identical formatter for the envelope timestamp. It now calls the same helper. Its output is unchanged.
  • The helper must be public, because LambdaLogExporter is in the exporters package. I put it in the existing telemetry.internal package, next to FatalErrors, instead of adding a method to the public Json class. So the change adds no public API outside internal.
  • A missing timestamp stays absent, as before.
  • The README has a new "Timestamps" section with the format contract. The LambdaLogExporter section now points to it.
  • No CHANGELOG exists in the repository, so there is no entry. There is no version bump, because the exporter is unpublished.

Python gets the same change in a sibling PR. JS already writes this format.

Testing

  • mvn -o -pl telemetry-exporter -am spotless:apply: no remaining changes.
  • mvn -o -pl telemetry-exporter -am verify: BUILD SUCCESS. sdk: 1589 tests, 0 failures, 3 skipped. sdk-testing: 53 tests, 0 failures. telemetry-exporter: 243 tests, 0 failures.
  • New RecordTimestampFormatTest:
    • Timestamps.format gives .000Z for zero nanos, .078Z for 078757096 ns, and .999Z for 999999999 ns.
    • A whole second sorts before the same second plus 500 ms when compared as text.
    • A record built by the plugin has emittedAt, startTime, endTime, and each operation's startTime and endTime matching ^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z$, with the exact expected values for the three cases above.
  • Two existing tests asserted START.toString() (2026-08-05T00:00:00Z) as the record startTime. They now assert 2026-08-05T00:00:00.000Z. Hand-built test records now use the same format as the plugin.

Follow-up: emittedAt is unique within one invocation

emittedAt has millisecond precision. With ON_CHANGE, one invocation can build two records in the same millisecond, for example the last RUNNING record and the terminal record. SQSExporter builds the FIFO deduplication id from executionArn and emittedAt. DynamoDBExporter uses emittedAt as its default sort key. So SQS dropped the second message, and DynamoDB overwrote the first item.

Commit 28fa366 applies the rule of aws/aws-durable-execution-sdk-js#1071. TelemetryPlugin keeps the last emittedAt it assigned, in epoch milliseconds. If the clock is past that value, the clock is used. Otherwise the last value plus 1 ms is used. So emittedAt strictly increases within one plugin instance, and one instance serves one invocation. Hook threads can build records at the same time, so the last value is an AtomicLong updated with updateAndGet(prev -> Math.max(prev + 1, now)).

New EmittedAtOrderingTest: with a frozen clock, the RUNNING, RUNNING and SUCCEEDED records get .123Z, .124Z and .125Z. When the clock moves past the last value, the clock is used. 8 threads × 2000 calls give 16000 distinct values. Without the rule, all three tests fail. verify: telemetry-exporter 246 tests, 0 failures.

Record timestamps were written with Instant.toString(). That method
writes 0, 3, 6 or 9 fraction digits, depending on the value. So one
record could hold startTime with 3 digits and endTime with 9.

Destinations such as DynamoDB and CloudWatch Logs Insights compare these
values as text. Text order equals time order only when every value has
the same width. So mixed widths sort and filter incorrectly.

emittedAt, startTime and endTime, on the record and on each operation,
now use YYYY-MM-DDTHH:MM:SS.sssZ. This is the format of JavaScript's
Date.prototype.toISOString(). Digits below the millisecond are dropped.
The new internal Timestamps.format writes it. LambdaLogExporter uses
the same method for the envelope timestamp, so its output is unchanged.
@ParidelPooya
ParidelPooya requested a review from a team October 23, 2026 19:10
@ParidelPooya
ParidelPooya deployed to ai-pr-review-runtime October 23, 2026 19:10 — with GitHub Actions Active
@ParidelPooya
ParidelPooya deployed to ai-pr-review-runtime October 23, 2026 19:11 — with GitHub Actions Active
@github-actions

This comment has been minimized.

emittedAt has millisecond precision. With ON_CHANGE, one invocation can
build two records in the same millisecond. One example is the last
RUNNING record and the terminal record. So both records got the same
emittedAt.

SQSExporter builds the FIFO deduplication id from executionArn and
emittedAt. DynamoDBExporter uses emittedAt as its default sort key. So
SQS dropped the second message, and DynamoDB overwrote the first item.

TelemetryPlugin now keeps the last emittedAt it assigned, in epoch
milliseconds. If the clock is past that value, the clock is used.
Otherwise the last value plus 1 ms is used. So emittedAt strictly
increases within one plugin instance. One instance serves one
invocation. This is the rule of aws/aws-durable-execution-sdk-js#1071.

Hook threads can build records at the same time. No lock serializes
the builds. So the last value is an AtomicLong, and the read and the
update are one updateAndGet(prev -> Math.max(prev + 1, now)).
@ParidelPooya
ParidelPooya deployed to ai-pr-review-runtime October 23, 2026 20:15 — with GitHub Actions Active
@github-actions

This comment has been minimized.

@ParidelPooya
ParidelPooya deployed to ai-pr-review-runtime October 23, 2026 22:21 — with GitHub Actions Active
@github-actions

Copy link
Copy Markdown
Contributor

Codex AI review

No actionable findings. The prior same-millisecond emission collision is addressed. Residual test risk: tests were inspected but not executed under the review constraints.

Reviewed commit a5fb2095044a73b3aed106c4602371f04a806b9d. Workflow run

ParidelPooya added a commit to aws/aws-durable-execution-sdk-js that referenced this pull request Oct 23, 2026
## Summary

`emittedAt` has millisecond precision. With `emitMode: "on-change"`, two
records of one execution can be built within the same millisecond, for
example a RUNNING record and the final record. They then get the same
`emittedAt`.

Two exporters key on `executionArn` + `emittedAt`:

- `SQSExporter` derives the FIFO deduplication id from
`executionArn:emittedAt`. So SQS dropped the second message as a
duplicate, and that can be the final record.
- `DynamoDBExporter` uses `emittedAt` as its default sort key. So the
second item overwrote the first.

This change makes `emittedAt` strictly increase within one plugin
instance, which serves one invocation. A record built in the same
millisecond as the previous one, or earlier, gets the previous value
plus 1 ms. Otherwise it gets the current time. The format and the record
shape do not change.

Codex raised this on the Python and Java PRs that pin record timestamps
to the same millisecond format
(aws/aws-durable-execution-sdk-python#821,
aws/aws-durable-execution-sdk-java#821). JS already wrote milliseconds,
so it already had the collision. Those two PRs get the same rule.

## Testing

- Two new tests in `index.test.ts`:
- With `Date.now` frozen, an on-change invocation's three records
(RUNNING, RUNNING, SUCCEEDED) get `.123Z`, `.124Z`, `.125Z`.
- When the clock moves past the previous record, the record uses the
current time.
  - Both tests fail without the change.
- Exporter: build passes, 161 tests pass.
- `biome ci` is clean on the exporter source and the CHANGELOG.
@ParidelPooya
ParidelPooya merged commit ef5483d into main Oct 23, 2026
20 checks passed
@ParidelPooya
ParidelPooya deleted the fix/telemetry-timestamp-format branch October 23, 2026 22:32
ParidelPooya added a commit to aws/aws-durable-execution-sdk-js that referenced this pull request Oct 23, 2026
…#1070)

## Summary

A deployed test ran the same workflow on the JS, Python, and Java
exporters, writing to S3 and Aurora. It found two problems with how
record timestamps are compared.

1. The bundled Athena table declares `emittedat`, `starttime`,
`endtime`, and the operation `starttime`/`endtime` as `string`. So
Athena compares them as text. Measured on the deployed records: `endtime
>= '2026-10-23T18:42:46Z'` returned none of the 7 records that ended in
that second, because `.` sorts before `Z`. The same filter on a
`timestamp` column returned all 7.
2. `list_executions` interpolated `since` and `until` as given. On
destinations that compare text (DynamoDB, CloudWatch Logs Insights), a
bound without a fraction, or with an offset such as `-07:00`, returned
the wrong records. With an offset the error is hours.

Changes:

- **Athena table:** the CDK Glue table (`cdk/stack.ts`) and the
telemetry-core DDL (`athena.ts`) declare those columns as `timestamp`.
The S3 objects do not change; the OpenX JSON SerDe parses the ISO
strings into the typed columns.
- **Athena schema prompt (`schema.ts`):** the columns are listed as
`timestamp (UTC)`. A new dialect rule says to compare them with
`TIMESTAMP` literals or timestamp expressions, never strings.
- **MCP `list_executions`:** a new `normalizeTimestamp` validates each
bound, including the calendar (it rejects `2026-02-30`, which
`Date.parse` would roll forward to March 2). A bound with no offset is
read as UTC. Each dialect then writes its own literal:
- Typed time columns (Athena `timestamp`, Aurora and Redshift
`timestamptz`, OpenSearch `date`) compare instants. The bound keeps
every digit the caller gave, because an existing table can hold values
finer than a millisecond. Athena gets a `TIMESTAMP '…'` literal; the
others get a quoted UTC string.
- Text comparisons (DynamoDB, Logs Insights) get the stored format: UTC,
3 fraction digits, `Z`. A finer bound is rounded so it selects the same
records: `since` up to the next millisecond, `until` down.
- **Docs:** the exporter README has a new "Timestamps" section that
states the format contract. The MCP README describes how bounds are
read. Both CHANGELOG entries are under Fixed. The Athena entry includes
a migration note: a table created earlier keeps `string` columns until
it is recreated or altered.

JS already writes every record timestamp with `toISOString()`, so the
record format does not change here. Python and Java change to the same
fixed-width format in sibling PRs:

- aws/aws-durable-execution-sdk-python#821
- aws/aws-durable-execution-sdk-java#821

## Testing

- Deployed check against the 18 real records in S3:
- I created a temporary Athena table from the new `buildCreateTableDdl`
output, then dropped it.
- The SQL that `buildListExecutionsSql` now builds for `since:
"2026-10-23T11:42:46-07:00"` returned the 3 executions in that window,
from all three SDKs.
  - `date_diff('millisecond', starttime, endtime)` equals `durationms`.
  - Operation `starttime`/`endtime` read as timestamps.
  - A string comparison fails with `TYPE_MISMATCH`, as the prompt says.
- New `timeBounds.test.ts` (21 tests): the normalized forms, rejection
of invalid dates and injection attempts, text order equal to time order
after normalization, and the literal per destination. Updated the two
`injection.test.ts` expectations.
- Package tests: MCP 427, core 385, exporter 159, vscode 34, desktop 48.
All passed.
- `biome ci` on the repo: clean.
- Not run: a CDK deploy of the changed Glue table.

This branch was successfully deployed

1 active deployment
ai-pr-review-runtime — a5fb2095 Deployed Oct 23, 2026 by ParidelPooya via ai-pr-review / Codex review / Generate Codex review #2671
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.

2 participants