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 <noreply@anthropic.com>
This commit is contained in:
2026-08-17 13:44:48 -06:00
co-authored by Claude Sonnet 5
parent f2046efeaf
commit 5527b25e52
3 changed files with 52 additions and 2 deletions
@@ -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()"))
+11 -1
View File
@@ -25,8 +25,18 @@ class Message(Base):
content: Mapped[str | None] = mapped_column(Text) content: Mapped[str | None] = mapped_column(Text)
image_id: Mapped[uuid.UUID | None] = mapped_column(ForeignKey("message_images.id")) image_id: Mapped[uuid.UUID | None] = mapped_column(ForeignKey("message_images.id"))
file_id: Mapped[uuid.UUID | None] = mapped_column(ForeignKey("message_files.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( 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)) edited_at: Mapped[datetime | None] = mapped_column(DateTime(timezone=True))
deleted_at: Mapped[datetime | None] = mapped_column(DateTime(timezone=True)) deleted_at: Mapped[datetime | None] = mapped_column(DateTime(timezone=True))
+4 -1
View File
@@ -20,8 +20,11 @@ class MessageReaction(Base):
message_id: Mapped[uuid.UUID] = mapped_column(ForeignKey("messages.id"), index=True, nullable=False) 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) user_id: Mapped[uuid.UUID] = mapped_column(ForeignKey("users.id"), nullable=False)
emoji: Mapped[str] = mapped_column(String(32), 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( 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") message = relationship("Message")