From 5527b25e52c2fa72e34cb7f2fc3a35eac03c5089 Mon Sep 17 00:00:00 2001 From: Keith Smith Date: Mon, 17 Aug 2026 13:44:48 -0600 Subject: [PATCH] Fix the real cause of out-of-order messages: now() vs clock_timestamp() (#45) Root cause, confirmed live against Postgres and reproduced end-to-end through two real WebSocket connections: ws/chat.py shares one AsyncSession for a whole connection's lifetime. A read-only action (e.g. a "join" frame's membership check) can leave a transaction open with nothing to commit it until the next write. Postgres's now()/CURRENT_TIMESTAMP returns that transaction's *start* time in that case, not the actual statement's -- so a reply sent after any idle/reading period got timestamped to when the idle period started, sorting it before messages that were genuinely sent earlier. This is independent of the two earlier #45 fixes (missing ORDER BY tiebreakers, a stale-response race on reload) -- both were real bugs, but this was the actual mechanism behind "my message appears before theirs even though theirs was sent first." Switched Message.created_at and MessageReaction.created_at from func.now() to func.clock_timestamp(), which always reflects the actual moment of execution regardless of how long the transaction has been open. Migration is a plain column-default change -- no table rewrite, no lock risk, round-trips cleanly. Co-Authored-By: Claude Sonnet 5 --- ...bb_message_and_reaction_timestamps_use_.py | 37 +++++++++++++++++++ backend/app/models/message.py | 12 +++++- backend/app/models/message_reaction.py | 5 ++- 3 files changed, 52 insertions(+), 2 deletions(-) create mode 100644 backend/alembic/versions/ffdd409227bb_message_and_reaction_timestamps_use_.py diff --git a/backend/alembic/versions/ffdd409227bb_message_and_reaction_timestamps_use_.py b/backend/alembic/versions/ffdd409227bb_message_and_reaction_timestamps_use_.py new file mode 100644 index 0000000..3516f31 --- /dev/null +++ b/backend/alembic/versions/ffdd409227bb_message_and_reaction_timestamps_use_.py @@ -0,0 +1,37 @@ +"""message and reaction timestamps use clock_timestamp not now + +Revision ID: ffdd409227bb +Revises: 05dbe3775e34 +Create Date: 2026-08-17 13:40:59.440134 + +""" +from typing import Sequence, Union + +from alembic import op +import sqlalchemy as sa + + +# revision identifiers, used by Alembic. +revision: str = 'ffdd409227bb' +down_revision: Union[str, Sequence[str], None] = '05dbe3775e34' +branch_labels: Union[str, Sequence[str], None] = None +depends_on: Union[str, Sequence[str], None] = None + + +def upgrade() -> None: + """Upgrade schema.""" + # Just a catalog default change -- no table rewrite, no lock beyond the + # instant one ALTER COLUMN SET DEFAULT always takes. Existing rows are + # untouched; only future inserts pick up clock_timestamp(). + op.alter_column( + "messages", "created_at", server_default=sa.text("clock_timestamp()") + ) + op.alter_column( + "message_reactions", "created_at", server_default=sa.text("clock_timestamp()") + ) + + +def downgrade() -> None: + """Downgrade schema.""" + op.alter_column("messages", "created_at", server_default=sa.text("now()")) + op.alter_column("message_reactions", "created_at", server_default=sa.text("now()")) diff --git a/backend/app/models/message.py b/backend/app/models/message.py index 82024d5..0b9676d 100644 --- a/backend/app/models/message.py +++ b/backend/app/models/message.py @@ -25,8 +25,18 @@ class Message(Base): content: Mapped[str | None] = mapped_column(Text) image_id: Mapped[uuid.UUID | None] = mapped_column(ForeignKey("message_images.id")) file_id: Mapped[uuid.UUID | None] = mapped_column(ForeignKey("message_files.id")) + # clock_timestamp(), not now()/func.now() -- the WS handler (ws/chat.py) + # shares one AsyncSession for a whole connection's lifetime, and a + # read-only op (e.g. a "join" frame's membership check) can leave a + # transaction open with nothing to commit it until the next write. + # Postgres's now()/CURRENT_TIMESTAMP returns the *transaction's* start + # time in that case, not the actual INSERT's -- confirmed live to be the + # actual cause of #45 (a reply sent well after an idle read-only period + # got timestamped to when that period started, sorting it before + # messages that were genuinely sent earlier). clock_timestamp() always + # reflects the real moment of execution regardless of transaction age. created_at: Mapped[datetime] = mapped_column( - DateTime(timezone=True), server_default=func.now(), index=True, nullable=False + DateTime(timezone=True), server_default=func.clock_timestamp(), index=True, nullable=False ) edited_at: Mapped[datetime | None] = mapped_column(DateTime(timezone=True)) deleted_at: Mapped[datetime | None] = mapped_column(DateTime(timezone=True)) diff --git a/backend/app/models/message_reaction.py b/backend/app/models/message_reaction.py index f9e5d4a..c1280fd 100644 --- a/backend/app/models/message_reaction.py +++ b/backend/app/models/message_reaction.py @@ -20,8 +20,11 @@ class MessageReaction(Base): message_id: Mapped[uuid.UUID] = mapped_column(ForeignKey("messages.id"), index=True, nullable=False) user_id: Mapped[uuid.UUID] = mapped_column(ForeignKey("users.id"), nullable=False) emoji: Mapped[str] = mapped_column(String(32), nullable=False) + # clock_timestamp(), not now() -- same transaction-pinning hazard as + # Message.created_at (see that column's comment); toggle_reaction runs + # through the same long-lived, shared WS session. created_at: Mapped[datetime] = mapped_column( - DateTime(timezone=True), server_default=func.now(), nullable=False + DateTime(timezone=True), server_default=func.clock_timestamp(), nullable=False ) message = relationship("Message")