Skip to content

Commit 102dd62

Browse files
authored
fix(telemetry): write fixed-width UTC record timestamps (#821)
* fix(telemetry): write fixed-width UTC timestamps Record timestamps now use YYYY-MM-DDTHH:MM:SS.sssZ. The fraction always has 3 digits. The plugin converts each time to UTC and truncates it to milliseconds. JavaScript's Date.prototype.toISOString() writes the same format. Before, isoformat() wrote 6 fraction digits. It wrote no fraction when microseconds were 0. Stores compare these values as text. Text order equals time order only when every value has the same width. So mixed widths sorted records out of time order. * fix(telemetry): keep emittedAt unique per invocation emittedAt has millisecond precision. In on-change mode, one invocation can build two records in the same millisecond, for example RUNNING and then the terminal record. The SQS FIFO deduplication id is executionArn:emittedAt. The default DynamoDB sort key is emittedAt. So SQS dropped the second message, and DynamoDB overwrote the first item. So emittedAt now strictly increases within one plugin instance. The instance serves one invocation. The instance keeps the last emittedAt in epoch milliseconds. Each record takes the current time, truncated to milliseconds, when it is later than the last value. Otherwise it takes the last value plus 1. The JavaScript plugin uses the same rule. Record building runs outside _lock by design, because it runs customer transforms. Snapshot admission runs under _lock, and builds on different threads can be admitted concurrently. So the value is chosen during admission and carried on the snapshot to the build.
1 parent 748ca48 commit 102dd62

6 files changed

Lines changed: 389 additions & 13 deletions

File tree

‎packages/aws-durable-execution-sdk-python-telemetry-exporter/README.md‎

Lines changed: 17 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -257,6 +257,23 @@ and `top-level` vs `full-tree` operation detail all mirror the JS plugin.
257257
Behavior is validated cross-SDK by the `telemetry` conformance suite
258258
(`aws-durable-execution-conformance-tests-telemetry`).
259259

260+
Record timestamps (`emittedAt`, `startTime`, `endTime`, and each operation's
261+
`startTime` and `endTime`) use one fixed-width UTC format:
262+
`YYYY-MM-DDTHH:MM:SS.sssZ`, for example `2026-10-23T18:42:40.784Z`. The
263+
fraction always has exactly 3 digits, and the suffix is always `Z`. The plugin
264+
converts each time to UTC and truncates it to milliseconds. JavaScript's
265+
`Date.prototype.toISOString()` writes the same format. Stores such as DynamoDB
266+
compare these values as text. Text order equals time order only when every
267+
value has the same width. So a text comparison of two record timestamps orders
268+
them by time.
269+
270+
`emittedAt` strictly increases within one invocation. In `on-change` mode, one
271+
invocation can build two records in the same millisecond. The SQS FIFO
272+
deduplication id and the default DynamoDB sort key both use `emittedAt`. So
273+
equal values would drop or overwrite a record. So when the clock has not
274+
passed the previous `emittedAt`, the plugin writes the previous value plus 1
275+
millisecond.
276+
260277
> **Note (asynchronous export).** Export rendering, truncation, `export()`, and
261278
> `flush()` run on one lazy background worker per registered factory. Checkpoint
262279
> hooks only replace the latest pending snapshot and wake the worker. Consecutive

‎packages/aws-durable-execution-sdk-python-telemetry-exporter/src/aws_durable_execution_sdk_python_telemetry_exporter/exporters/otel_exporter.py‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -43,7 +43,8 @@ def _kv(key: str, value: str | int) -> dict[str, Any]:
4343

4444

4545
def _to_nano(iso: str) -> str:
46-
# Keep the record's full microsecond precision (integer math, no float).
46+
# Keep every fraction digit of the parsed timestamp, up to microseconds.
47+
# Integer math avoids float rounding.
4748
delta = parse_iso_datetime(iso) - _EPOCH
4849
seconds = delta.days * 86_400 + delta.seconds
4950
return str(seconds * 1_000_000_000 + delta.microseconds * 1_000)

‎packages/aws-durable-execution-sdk-python-telemetry-exporter/src/aws_durable_execution_sdk_python_telemetry_exporter/plugin.py‎

Lines changed: 64 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -149,9 +149,35 @@ def _resolve_sampling_rate(rate: float | None) -> float:
149149
return float(rate)
150150

151151

152+
def _format_record_timestamp(ts: datetime.datetime) -> str:
153+
"""Format a record timestamp as ``YYYY-MM-DDTHH:MM:SS.sssZ`` in UTC.
154+
155+
Stores such as DynamoDB compare these values as text. Text order equals
156+
time order only when every value has the same width. Plain ``isoformat()``
157+
writes 6 fraction digits, and no fraction when microseconds are 0. So this
158+
always writes exactly 3 fraction digits and a literal ``Z``. JavaScript's
159+
``Date.prototype.toISOString()`` writes the same format.
160+
``timespec="milliseconds"`` truncates the microseconds; it does not round.
161+
"""
162+
return (
163+
ts.astimezone(datetime.UTC)
164+
.isoformat(timespec="milliseconds")
165+
.replace("+00:00", "Z")
166+
)
167+
168+
169+
_EPOCH = datetime.datetime(1970, 1, 1, tzinfo=datetime.UTC)
170+
_ONE_MS = datetime.timedelta(milliseconds=1)
171+
172+
173+
def _utc_now_ms() -> int:
174+
"""Return the current UTC time in whole epoch milliseconds, truncated."""
175+
return (datetime.datetime.now(datetime.UTC) - _EPOCH) // _ONE_MS
176+
177+
152178
def _iso(ts: Any) -> str | None:
153179
if isinstance(ts, datetime.datetime):
154-
return ts.astimezone(datetime.UTC).isoformat().replace("+00:00", "Z")
180+
return _format_record_timestamp(ts)
155181
return None
156182

157183

@@ -382,6 +408,7 @@ class _EmissionSnapshot:
382408
operations: Mapping[str, OperationInfo]
383409
revision: int
384410
closing: bool
411+
emitted_at: str
385412

386413

387414
class _HookFrames(threading.local):
@@ -428,9 +455,10 @@ class DurableExecutionTelemetryPlugin(DurableInstrumentationPlugin, _ExportState
428455
Two locks, disjoint field sets, and neither is ever taken to reach the
429456
other's fields:
430457
431-
* ``_lock`` guards ``_closed``, ``_build_revision``, the ``_operations``
432-
rebind and the snapshot-admission/scheduler-handoff boundaries. Record
433-
building and customer transforms run outside this lock.
458+
* ``_lock`` guards ``_closed``, ``_build_revision``, ``_last_emitted_ms``,
459+
the ``_operations`` rebind and the snapshot-admission/scheduler-handoff
460+
boundaries. Record building and customer transforms run outside this
461+
lock.
434462
* ``_ExportScheduler._condition``'s lock guards the export bookkeeping this
435463
instance carries for the scheduler; nothing outside the scheduler reads or
436464
writes those fields, and the scheduler never touches the fields above.
@@ -480,6 +508,9 @@ def __init__(
480508
# operation snapshot. Customer callbacks can start a newer build on this
481509
# or another thread, so the hand-off must reject an overtaken snapshot.
482510
self._build_revision = 0
511+
# The epoch milliseconds of the last emittedAt this instance assigned.
512+
# None until the first admitted build.
513+
self._last_emitted_ms: int | None = None
483514
# Only snapshot admission and the checked scheduler hand-off are locked.
484515
# Holding this lock across a customer callback deadlocks two invocations
485516
# whose transforms synchronously call each other's plugin hooks.
@@ -506,7 +537,34 @@ def _snapshot_emission_locked(self, *, closing: bool = False) -> _EmissionSnapsh
506537
if not closing:
507538
self._build_revision += 1
508539
revision = self._build_revision
509-
return _EmissionSnapshot(self._operations, revision, closing)
540+
return _EmissionSnapshot(
541+
self._operations, revision, closing, self._next_emitted_at_locked()
542+
)
543+
544+
def _next_emitted_at_locked(self) -> str:
545+
"""Return the emittedAt for the build being admitted.
546+
547+
1. ``emittedAt`` has millisecond precision.
548+
2. In ``on-change`` mode, one invocation can admit two builds in the
549+
same millisecond. An example is RUNNING, then the terminal record.
550+
3. The SQS FIFO deduplication id is ``executionArn:emittedAt``. The
551+
default DynamoDB sort key is ``emittedAt``, under the partition key
552+
``executionArn``.
553+
4. So two records with an equal ``emittedAt`` make SQS drop the second
554+
message, and make DynamoDB overwrite the first item.
555+
5. So ``emittedAt`` strictly increases within this instance. This
556+
instance serves one invocation.
557+
558+
The value is the current time when it is later than the last value.
559+
Otherwise it is the last value plus 1 millisecond. Builds on different
560+
threads can be admitted concurrently. So callers hold ``self._lock``,
561+
which serializes the admissions that read and write the last value.
562+
"""
563+
now_ms = _utc_now_ms()
564+
last = self._last_emitted_ms
565+
ms = now_ms if last is None or now_ms > last else last + 1
566+
self._last_emitted_ms = ms
567+
return _format_record_timestamp(_EPOCH + ms * _ONE_MS)
510568

511569
# -- hooks ----------------------------------------------------------------
512570

@@ -746,9 +804,7 @@ def _emit(
746804
record: dict[str, Any] = {
747805
"recordType": "DurableExecutionTelemetry",
748806
"schemaVersion": "1.0",
749-
"emittedAt": datetime.datetime.now(datetime.UTC)
750-
.isoformat()
751-
.replace("+00:00", "Z"),
807+
"emittedAt": snapshot.emitted_at,
752808
"executionArn": self._execution_arn,
753809
}
754810
if arn.get("executionName"):

‎packages/aws-durable-execution-sdk-python-telemetry-exporter/src/aws_durable_execution_sdk_python_telemetry_exporter/truncation.py‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -73,8 +73,9 @@ def truncate_record(
7373

7474
ops: list[dict[str, Any]] = [dict(op) for op in record.get("operations", [])]
7575
kept = [True] * len(ops)
76-
# Oldest-first by ISO startTime string (UTC 'Z' ISO timestamps sort
77-
# chronologically as strings); operations without a startTime sort last.
76+
# Oldest-first by the startTime string. Every record timestamp has the same
77+
# fixed-width UTC format, so text order equals time order. Operations
78+
# without a startTime sort last.
7879
order = sorted(
7980
range(len(ops)), key=lambda i: (ops[i].get("startTime") or "\uffff", i)
8081
)

‎packages/aws-durable-execution-sdk-python-telemetry-exporter/tests/test_plugin.py‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -508,7 +508,7 @@ def test_cold_resume_reports_prior_terminal_ops_with_fresh_plugin():
508508
assert names == ["greet", "pause"] # prior terminal ops present on cold resume
509509
# Comment 7: start time is the original execution start (T0), not the resume
510510
# time -> duration is measured from T0 and is non-negative.
511-
assert rec["startTime"] == "2026-01-01T00:00:00Z"
511+
assert rec["startTime"] == "2026-01-01T00:00:00.000Z"
512512
assert rec["durationMs"] is not None and rec["durationMs"] >= 0
513513

514514

@@ -1124,7 +1124,7 @@ def test_operation_change_after_invocation_end_emits_nothing():
11241124
assert [record["status"] for record in exporter.records][-1] == "SUCCEEDED"
11251125
# No fabricated start time: every record still reports the execution start.
11261126
assert {record["startTime"] for record in exporter.records} == {
1127-
"2026-01-01T00:00:00Z"
1127+
"2026-01-01T00:00:00.000Z"
11281128
}
11291129

11301130

0 commit comments

Comments
 (0)