Random UPDATE_COLLISION errors

Bugs
1

Issue Summary

  • When creating a new post, in 30% of cases I receive UPDATE_COLLISION error
  • This does not happen all the time and it’s not clear what triggers this

Steps to Reproduce

  1. Create a new post
  2. Fill in title and contents and publish - all done within 3-4 seconds
  3. In 30% of cases I receive UPDATE_COLLISION in logs

Setup information

Ghost Version
5.68.0

Node.js Version
Self-hosted - Node.js 16.20.2

How did you install Ghost?
Clone Ghost repo, run yarn archive and install via ghost-cli

Provide details of your host & operating system
Rocky Linux 9, Ghost running in Docker, Varnish for caching.
Varnish ignores all paths starting with /ghost

Database type
MySQL 8

Browser & OS version
Chrome 117.0.5938.149, but really any other browser

Relevant log / error output
When a post is successfully published there’s just one PUT call, such as:

[2023-10-09 08:48:17] INFO "GET /ghost/api/admin/slugs/post/1231231/" 200 49ms
[2023-10-09 08:48:17] INFO Triggering webhook for "site.changed" with url "https://xxx"
[2023-10-09 08:48:17] INFO "GET /ghost/api/admin/slugs/post/1231231/" 200 53ms
[2023-10-09 08:48:17] INFO Triggering webhook for "site.changed" with url "https://xxx"
[2023-10-09 08:48:17] INFO PostAddedEvent received, adding post 6523be51da56be000187f4bb to matching collections
[2023-10-09 08:48:17] INFO "POST /ghost/api/admin/posts/?formats=mobiledoc%2Clexical" 201 166ms
[2023-10-09 08:48:17] INFO "GET /ghost/api/admin/settings/?group=site%2Ctheme%2Cprivate%2Cmembers%2Cportal%2Cnewsletter%2Cemail%2Camp%2Clabs%2Cslack%2Cunsplash%2Cviews%2Cfirstpromoter%2Ceditor%2Ccomments%2Canalytics%2Cannouncement%2Cpintura%2Cdonations%2Crecommendations" 200 28ms
[2023-10-09 08:48:17] INFO "GET /ghost/api/admin/newsletters/?status=active&limit=all&include=count.active_members" 200 32ms
[2023-10-09 08:48:17] INFO "GET /ghost/api/admin/members/?limit=1&include=newsletters%2Clabels" 200 34ms
[2023-10-09 08:48:19] INFO "GET /ghost/api/admin/posts/?formats=mobiledoc%2Clexical&filter=status%3Apublished&limit=1" 200 71ms
[2023-10-09 08:48:19] INFO Adding one-off job to queue with current length = 0 called 'sendWebmentions'
[2023-10-09 08:48:19] INFO PostEditedEvent received, updating post 6523be51da56be000187f4bb in matching collections
[2023-10-09 08:48:19] INFO "PUT /ghost/api/admin/posts/6523be51da56be000187f4bb/?formats=mobiledoc%2Clexical" 200 185ms
[2023-10-09 08:48:19] INFO Triggering webhook for "site.changed" with url "https://xxx"

However when there’s an update collision, there are two PUT calls, such as:

[2023-10-09 08:32:18] INFO "GET /ghost/api/admin/snippets/?formats=mobiledoc%2Clexical&limit=all" 200 46ms
[2023-10-09 08:32:19] INFO "GET /ghost/api/admin/slugs/post/123123/" 200 50ms
[2023-10-09 08:32:19] INFO Triggering webhook for "site.changed" with url "https://xxx"
[2023-10-09 08:32:19] INFO PostAddedEvent received, adding post 6523ba93da56be000187f47e to matching collections
[2023-10-09 08:32:19] INFO "POST /ghost/api/admin/posts/?formats=mobiledoc%2Clexical" 201 169ms
[2023-10-09 08:32:19] INFO "GET /ghost/api/admin/settings/?group=site%2Ctheme%2Cprivate%2Cmembers%2Cportal%2Cnewsletter%2Cemail%2Camp%2Clabs%2Cslack%2Cunsplash%2Cviews%2Cfirstpromoter%2Ceditor%2Ccomments%2Canalytics%2Cannouncement%2Cpintura%2Cdonations%2Crecommendations" 200 38ms
[2023-10-09 08:32:19] INFO "GET /ghost/api/admin/newsletters/?status=active&limit=all&include=count.active_members" 200 40ms
[2023-10-09 08:32:19] INFO "GET /ghost/api/admin/members/?limit=1&include=newsletters%2Clabels" 200 44ms
[2023-10-09 08:32:22] INFO "GET /ghost/api/admin/posts/?formats=mobiledoc%2Clexical&filter=status%3Apublished&limit=1" 200 84ms
[2023-10-09 08:32:23] INFO Adding one-off job to queue with current length = 0 called 'sendWebmentions'
[2023-10-09 08:32:23] INFO PostEditedEvent received, updating post 6523ba93da56be000187f47e in matching collections
[2023-10-09 08:32:23] INFO "PUT /ghost/api/admin/posts/6523ba93da56be000187f47e/?formats=mobiledoc%2Clexical" 200 983ms
[2023-10-09 08:32:24] INFO Triggering webhook for "site.changed" with url "https://xxx"
[2023-10-09 08:32:24] ERROR "PUT /ghost/api/admin/posts/6523ba93da56be000187f47e/?formats=mobiledoc%2Clexical" 409 674ms

Saving failed! Someone else is editing this post.
Error ID:
    5efe7170-667e-11ee-92f4-c72adf9f4cfb
Error Code:
    UPDATE_COLLISION
Details:
    changedFields:
      - status
      - published_at
    clientUpdatedAt: 2023-10-09T08:32:19.000Z
    serverUpdatedAt: 2023-10-09T08:32:23.000Z
----------------------------------------
UpdateCollisionError: Saving failed! Someone else is editing this post.
    at Sync.update (/home/node/ghost/versions/5.68.0/node_modules/@tryghost/bookshelf-collision/lib/bookshelf-collision.js:64:31)

Any ideas what could be going on?

2

I suspect there is some race-condition during post publishing.

Based on the network tab in dev tools the first PUT request is saving status: draft and the second status: published.

The second PUT request does not wait for the first one to finish though.

The first PUT request is started with a correct updated_at timestamp.
The second PUT request does not wait for the first one to finish. It starts with the same updated_at timestamp while it shall wait for the first request to finish and take the new updated_at timestamp from the response.

This makes Ghost think the second PUT request for status: published has incorrect timestamp and Ghost returns a 409 UPDATE_COLLISION error.

3

It could also be related to publishing a post while autosaving a draft is in progress.
It seems waiting a bit between the publish button clicks resolves the issue.

4

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.