Request does not exist, commit to stream rejected and timeouts

nax · May 17, 2023, 2:22pm

I’m having some issues on my node where things are timing out and then commits are being rejected.

The ipfs node seems to be running okay, CPU is active around 100%, I can’t see anything in the logs.

Any idea what could be causing this? It seems to happen periodically.

This is the relevant output from the node logs:

May 17 14:11:33: [2023-05-17T14:11:33.961Z] ERROR: Request does not exist
May 17 14:11:38: Timeout error while loading CID bafyreigd3z4zjssl2l4fc3ratqbjytrbddinew7lsxmtqvizf763yjggte from IPFS. 2 retries remain
May 17 14:11:53: [2023-05-17T14:11:53.001Z] ERROR: Error: Commit to stream kjzl6kcym7w8y6t4mkijmgkt75i1k644vvl3t3r2yy5vqz9qmspnfg95o6fox01 rejected because it builds on stale state. Calling 'sync()' on the stream handle will synchronize the stream state in the client with that on the Ceramic node.  Rejected commit CID: bagcqceraqm7adsckh6acimxsfff55g2cpwuvzhcd4kvvc6l4x6vwpzrlcx3a. Current tip: bafyreidjbuiphnmy6md6vlwxlj6afffcvaf72qvzzavveqxdm5jotpu6sm
May 17 14:11:53: [2023-05-17T14:11:53.127Z] ERROR: Error: Commit to stream kjzl6kcym7w8y6t4mkijmgkt75i1k644vvl3t3r2yy5vqz9qmspnfg95o6fox01 rejected because it builds on stale state. Calling 'sync()' on the stream handle will synchronize the stream state in the client with that on the Ceramic node.  Rejected commit CID: bagcqceramo6gp3k7twxmucehbthvsk572znxqbguutakkcyj7gaczn3pcvna. Current tip: bafyreidjbuiphnmy6md6vlwxlj6afffcvaf72qvzzavveqxdm5jotpu6sm
May 17 14:12:34: [2023-05-17T14:12:34.173Z] ERROR: Request does not exist
May 17 14:12:39: [2023-05-17T14:12:39.779Z] ERROR: Error: Commit to stream kjzl6kcym7w8y6t4mkijmgkt75i1k644vvl3t3r2yy5vqz9qmspnfg95o6fox01 rejected because it builds on stale state. Calling 'sync()' on the stream handle will synchronize the stream state in the client with that on the Ceramic node.  Rejected commit CID: bagcqcerau3olttl4rn7i6pb2jm3bju37vl6tyyrodhrfcldt7jz2egguutaq. Current tip: bagcqceragvbii5sxswf4nz57ymtu6e3znxoxpih4y2rhoatur3na3f4mbgyq
May 17 14:13:34: [2023-05-17T14:13:34.008Z] ERROR: Request does not exist
May 17 14:13:39: [2023-05-17T14:13:39.571Z] ERROR: TimeoutError: Request timed out
May 17 14:14:34: [2023-05-17T14:14:34.393Z] ERROR: Request does not exist

And in the errors that come in the browser:

And these are the requests that time out:

The requests are making a small update.

spencer · May 17, 2023, 9:21pm

ooh there seems to be several issues going on at once here.

First, you’re getting timeouts loading data from your IPFS node, likely related to it being at 100% CPU. I’d suggest restarting your IPFS node to see if that helps, though if it quickly gets back to the full CPU load then you may just be creating more load than the node can handle.

Second the builds on stale state errors indicate that your http client is operating on outdated state relative to what your Ceramic node knows about. Do you maintain handles to Ceramic documents/streams for a long time in your app? If so it may be that when your updates get anchored your node learns about the anchor but the client handle doesn’t have the anchor. If you don’t keep long-lived stream handles in your app frontend, then the other way this could happen is if a stream is being updated by another node on the network at the same time as your app is trying to update it. Do you run multiple nodes in a load-balanced way?

Third, the Request does not exist error comes from the CAS (Ceramic Anchor Service). Somehow your node got into a state where it is polling the status for an anchor request that the CAS doesn’t know anything about. That shouldn’t really be possible. @ukstv - do you have any ideas how this could get triggered?

nax · May 22, 2023, 9:50am

Thanks for the help!

We’re still seeing issues with the IPFS node being busy. Restarting the IPFS node doesn’t seem to help. I have added 2 more cores so now it has 4 cores, but requests to the ceramic node are still timing out. These are some more logs:

I haven’t seen the validation ignored error or the failed to enqueue CID one before…

[2023-05-22T09:30:44.361Z] ERROR: HTTPError: validation ignored
[2023-05-22T09:30:44.363Z] ERROR: HTTPError: validation ignored
[2023-05-22T09:31:47.918Z] ERROR: TimeoutError: Request timed out
[2023-05-22T09:31:48.622Z] ERROR: TimeoutError: Request timed out
[2023-05-22T09:31:48.947Z] ERROR: TimeoutError: Request timed out
[2023-05-22T09:33:05.427Z] ERROR: HTTPError: failed to enqueue CID: shutting down
[2023-05-22T09:33:05.525Z] ERROR: TimeoutError: Request timed out
[2023-05-22T09:33:05.529Z] ERROR: TimeoutError: Request timed out
[2023-05-22T09:33:05.532Z] ERROR: TimeoutError: Request timed out
[2023-05-22T09:33:05.536Z] ERROR: TimeoutError: Request timed out
[2023-05-22T09:33:05.539Z] ERROR: TimeoutError: Request timed out
[2023-05-22T09:33:05.542Z] ERROR: TimeoutError: Request timed out

Regarding your other point on the client state. I think what happens is that we’re sending multiple changes in rapid succession. The interface we’re building is visual so you can drag nodes around and quickly edit, so it seems like maybe requests are building up and so the state on the node is changed, and there’s still requests backed up that are using the old state? That’s the only thing I can think of.

nax · May 22, 2023, 9:59am

It appears to only time out when making updates to a document. These are the requests it makes when updating (I replaced the URL with node-url):

When updating a field:

This one works:

curl 'https://node-url/api/v0/multiqueries' \
  -H 'content-type: application/json' \
  --data-raw '{"queries":[{"streamId":"kjzl6kcym7w8y80lqqgaj1q3rc669nsmk2bc3x93rkgzh2uhou7clhe71gyo1e9"}]}'

This one times out:

curl 'https://node-url/api/v0/commits' \
  -H 'content-type: application/json' \
  --data-raw '{"streamId":"kjzl6kcym7w8y80lqqgaj1q3rc669nsmk2bc3x93rkgzh2uhou7clhe71gyo1e9","commit":{"jws":{"payload":"AXESIJRsBtE0PUQYi0u9gVQPH0R1zeolQk4UErNjEecsDnxY","signatures":[{"protected":"eyJhbGciOiJFZERTQSIsImNhcCI6ImlwZnM6Ly9iYWZ5cmVpY3J1ZnIzNDJmeTVmaWlpcjYyZDVwdGFuNW9icTJmeW9mdnI0c2ZrdjZ5M21odDd6bnVrZSIsImtpZCI6ImRpZDprZXk6ejZNa2lNcUM2eWpVY2dKSzFxZEFSckszREc3M0tnV3NyaTdEbWVGWDR4N0ZQckd5I3o2TWtpTXFDNnlqVWNnSksxcWRBUnJLM0RHNzNLZ1dzcmk3RG1lRlg0eDdGUHJHeSJ9","signature":"tAJ9SMGq5zhOg3ukVgpXWq6Xz5zVgck2aTS2RldwWJbjn0NgjvxhRAv4dk-lRqV8KsL4B6OoxckR8SVlmyQkAA"}],"link":"bafyreieunqdncnb5iqmiws55qfka6h2eoxg6ujkcjykbfm3dchtsydt4la"},"linkedBlock":"o2JpZNgqWCYAAYUBEiB9vTEjzuz/0Xc3sKiQfBteOJ8+1w2l+uijZuEQbDePEWRkYXRhgqNib3BncmVwbGFjZWRwYXRoay9wb3NpdGlvbi95ZXZhbHVl+0Cd0bveGIc5o2JvcGdyZXBsYWNlZHBhdGhrL3Bvc2l0aW9uL3hldmFsdWX7QIz38tCM39BkcHJldtgqWCYAAYUBEiDKImmZOVKJU8wNGcvNZUCF1GtnoxQcJLxR62HOoUU6Qw","cacaoBlock":"o2FooWF0Z2VpcDQzNjFhcKljYXVkeDhkaWQ6a2V5Ono2TWtpTXFDNnlqVWNnSksxcWRBUnJLM0RHNzNLZ1dzcmk3RG1lRlg0eDdGUHJHeWNleHB4GDIwMjMtMDgtMThUMTM6MzE6MjYuNzgzWmNpYXR4GDIwMjMtMDUtMTdUMTM6MzE6MjYuNzgzWmNpc3N4O2RpZDpwa2g6ZWlwMTU1OjE6MHhjYTVmZjRiMzQ0MmZjYWMyN2UxYWY0NDU3ZTAyZWI2MjljNzEyOTgzZW5vbmNlanFnS3c2OWxNZUZmZG9tYWluaTEyNy4wLjAuMWd2ZXJzaW9uYTFpcmVzb3VyY2VzhHhRY2VyYW1pYzovLyo/bW9kZWw9a2p6bDZodmZyYnc2YzVmcjU5cnZoYTBuYml6ZmM1ZXI3dHZpZThhamxrazUyYjIwczF1eW1sdGM4enVxZzNmeFFjZXJhbWljOi8vKj9tb2RlbD1ranpsNmh2ZnJidzZjYjJqbmt4N2Fsb2N2b3Q2cWNsNDM1MWpsNHA5anhvaDR0NzF3eTNqNG04bXg4MmRqNWx4UWNlcmFtaWM6Ly8qP21vZGVsPWtqemw2aHZmcmJ3NmM1Nnd1c200Mmo4ZGoxaGw5Zm1nenpqeWM2M2I3YTAyYXU1ZmxwNnpvcnJzOWk5OXZoMXhRY2VyYW1pYzovLyo/bW9kZWw9a2p6bDZodmZyYnc2Y2FoNjlsbHlibGxibnoweDgyZWJ1NW1pZ2tkeGlhd3FkYThwdjFzZXp0bXp0bGE2c2NoaXN0YXRlbWVudHg8R2l2ZSB0aGlzIGFwcGxpY2F0aW9uIGFjY2VzcyB0byBzb21lIG9mIHlvdXIgZGF0YSBvbiBDZXJhbWljYXOiYXN4hDB4OWYyMzA4YjMwNmIxYmVhNzg1YzAwMDc2YjJmYjNlY2IxMTFmNDRjYjhlMWRjNzRkY2M1MWViMGJjMzgwYjdlMjIyNzJiODU2ODU4YmRiZDhiMzY2ZTMzMGQyODM2NGJlYzkyZmNmOWIxNWZmMWU3ZGQwOWRiNWMyNjQwODA2ODYxYmF0ZmVpcDE5MQ"},"opts":{"anchor":true,"publish":true,"sync":0}}'

And these are the requests when creating a node.

These both work:

curl 'https://node-url/api/v0/streams' \
  -H 'content-type: application/json' \
  --data-raw '{"type":3,"genesis":{"jws":{"payload":"AXESIAjiHYelLyZP0GY89cF4cqEK-a5r1-HQmj4X0y2k4O7e","signatures":[{"protected":"eyJhbGciOiJFZERTQSIsImNhcCI6ImlwZnM6Ly9iYWZ5cmVpY3J1ZnIzNDJmeTVmaWlpcjYyZDVwdGFuNW9icTJmeW9mdnI0c2ZrdjZ5M21odDd6bnVrZSIsImtpZCI6ImRpZDprZXk6ejZNa2lNcUM2eWpVY2dKSzFxZEFSckszREc3M0tnV3NyaTdEbWVGWDR4N0ZQckd5I3o2TWtpTXFDNnlqVWNnSksxcWRBUnJLM0RHNzNLZ1dzcmk3RG1lRlg0eDdGUHJHeSJ9","signature":"_F_I0BAT6o_be_9l1-evoDxzbFpao7uoRdgdEoDEIjZpOeWSDl2TxqvfhDPlw8RWE8vqxl8kOBLV7rr4XDa8DQ"}],"link":"bafyreiai4ioypjjpezh5azr46xaxq4vbbl42426x4hijupqx2mw2jyho3y"},"linkedBlock":"omRkYXRhpmRkYXRhoWVsYWJlbGhOZXcgbm9kZWR0eXBlaE5lZWROb2RlZ2NyZWF0ZWR4GDIwMjMtMDUtMjJUMDk6NTQ6MjYuMTc0Wmhwb3NpdGlvbqJhePtAhuTmqVUkMmF5+0CWCffc/mnwaWxhdGVyYWxJRHgkMTI1NWY3M2YtNWI2NC00MDkxLTg5ZjgtMWU0MTAxZDUyNWE3aXByb2plY3RJRHg/a2p6bDZrY3ltN3c4eTZ5ZjZoOW03bHB1YjM1dGh6MTVybm02d2xseGFsaDZrenppcXB6N2lpaHBvNHN1NjkzZmhlYWRlcqRjc2VwZW1vZGVsZW1vZGVsWCjOAQIBhQESIPMIJr8pLtYk63spBqoPQLg/gxcRjVq+m8jMo63u7JQ5ZnVuaXF1ZUwoEHLiGgPnjmHsqSNrY29udHJvbGxlcnOBeDtkaWQ6cGtoOmVpcDE1NToxOjB4Y2E1ZmY0YjM0NDJmY2FjMjdlMWFmNDQ1N2UwMmViNjI5YzcxMjk4Mw","cacaoBlock":"o2FooWF0Z2VpcDQzNjFhcKljYXVkeDhkaWQ6a2V5Ono2TWtpTXFDNnlqVWNnSksxcWRBUnJLM0RHNzNLZ1dzcmk3RG1lRlg0eDdGUHJHeWNleHB4GDIwMjMtMDgtMThUMTM6MzE6MjYuNzgzWmNpYXR4GDIwMjMtMDUtMTdUMTM6MzE6MjYuNzgzWmNpc3N4O2RpZDpwa2g6ZWlwMTU1OjE6MHhjYTVmZjRiMzQ0MmZjYWMyN2UxYWY0NDU3ZTAyZWI2MjljNzEyOTgzZW5vbmNlanFnS3c2OWxNZUZmZG9tYWluaTEyNy4wLjAuMWd2ZXJzaW9uYTFpcmVzb3VyY2VzhHhRY2VyYW1pYzovLyo/bW9kZWw9a2p6bDZodmZyYnc2YzVmcjU5cnZoYTBuYml6ZmM1ZXI3dHZpZThhamxrazUyYjIwczF1eW1sdGM4enVxZzNmeFFjZXJhbWljOi8vKj9tb2RlbD1ranpsNmh2ZnJidzZjYjJqbmt4N2Fsb2N2b3Q2cWNsNDM1MWpsNHA5anhvaDR0NzF3eTNqNG04bXg4MmRqNWx4UWNlcmFtaWM6Ly8qP21vZGVsPWtqemw2aHZmcmJ3NmM1Nnd1c200Mmo4ZGoxaGw5Zm1nenpqeWM2M2I3YTAyYXU1ZmxwNnpvcnJzOWk5OXZoMXhRY2VyYW1pYzovLyo/bW9kZWw9a2p6bDZodmZyYnc2Y2FoNjlsbHlibGxibnoweDgyZWJ1NW1pZ2tkeGlhd3FkYThwdjFzZXp0bXp0bGE2c2NoaXN0YXRlbWVudHg8R2l2ZSB0aGlzIGFwcGxpY2F0aW9uIGFjY2VzcyB0byBzb21lIG9mIHlvdXIgZGF0YSBvbiBDZXJhbWljYXOiYXN4hDB4OWYyMzA4YjMwNmIxYmVhNzg1YzAwMDc2YjJmYjNlY2IxMTFmNDRjYjhlMWRjNzRkY2M1MWViMGJjMzgwYjdlMjIyNzJiODU2ODU4YmRiZDhiMzY2ZTMzMGQyODM2NGJlYzkyZmNmOWIxNWZmMWU3ZGQwOWRiNWMyNjQwODA2ODYxYmF0ZmVpcDE5MQ"},"opts":{"anchor":true,"publish":true,"sync":2,"syncTimeoutSeconds":0}}'

curl 'https://node-url/api/v0/multiqueries' \
  -H 'content-type: application/json' \
  --data-raw '{"queries":[{"streamId":"kjzl6kcym7w8y6yf6h9m7lpub35thz15rnm6wllxalh6kzziqpz7iihpo4su693"}]}'

nax · May 22, 2023, 10:06am

Weirdly when I update another field using the same query it works. This is another request that works:

curl 'https://node-url/api/v0/commits' \
  -H 'content-type: application/json' \
  --data-raw '{"streamId":"kjzl6kcym7w8y9zv59nv555ydw57kk0wqbva8duzdfneme3okim468vtmld6kxl","commit":{"jws":{"payload":"AXESID2KDoBYW6rm9Rqv0bsJzbD1P_p4qeH1On1oI8rAod-B","signatures":[{"protected":"eyJhbGciOiJFZERTQSIsImNhcCI6ImlwZnM6Ly9iYWZ5cmVpY3J1ZnIzNDJmeTVmaWlpcjYyZDVwdGFuNW9icTJmeW9mdnI0c2ZrdjZ5M21odDd6bnVrZSIsImtpZCI6ImRpZDprZXk6ejZNa2lNcUM2eWpVY2dKSzFxZEFSckszREc3M0tnV3NyaTdEbWVGWDR4N0ZQckd5I3o2TWtpTXFDNnlqVWNnSksxcWRBUnJLM0RHNzNLZ1dzcmk3RG1lRlg0eDdGUHJHeSJ9","signature":"6ubiD8hNmybfOnzYcnhdMAZCCRNc6HkRtP3QGvJk_VdbiYlVThxHa-IcB3dqJLwmRVwOJOX1l64aFOBas41jBg"}],"link":"bafyreib5rihiawc3vltpkgvp2g5qttnq6u77u6fj4h2tu7liepfmbio7qe"},"linkedBlock":"o2JpZNgqWCYAAYUBEiDNKOuPmHPflj7LyzQNVoS6wLEXiMFALqqowLumWfjweWRkYXRhgaNib3BncmVwbGFjZWRwYXRoay9kYXRhL2xhYmVsZXZhbHVlZ3Rlc3RpbmdkcHJldtgqWCYAAYUBEiDC/Tons9+tovz9B3xA/JAR7hT2/ga5l/j0pRH8nLx2wg","cacaoBlock":"o2FooWF0Z2VpcDQzNjFhcKljYXVkeDhkaWQ6a2V5Ono2TWtpTXFDNnlqVWNnSksxcWRBUnJLM0RHNzNLZ1dzcmk3RG1lRlg0eDdGUHJHeWNleHB4GDIwMjMtMDgtMThUMTM6MzE6MjYuNzgzWmNpYXR4GDIwMjMtMDUtMTdUMTM6MzE6MjYuNzgzWmNpc3N4O2RpZDpwa2g6ZWlwMTU1OjE6MHhjYTVmZjRiMzQ0MmZjYWMyN2UxYWY0NDU3ZTAyZWI2MjljNzEyOTgzZW5vbmNlanFnS3c2OWxNZUZmZG9tYWluaTEyNy4wLjAuMWd2ZXJzaW9uYTFpcmVzb3VyY2VzhHhRY2VyYW1pYzovLyo/bW9kZWw9a2p6bDZodmZyYnc2YzVmcjU5cnZoYTBuYml6ZmM1ZXI3dHZpZThhamxrazUyYjIwczF1eW1sdGM4enVxZzNmeFFjZXJhbWljOi8vKj9tb2RlbD1ranpsNmh2ZnJidzZjYjJqbmt4N2Fsb2N2b3Q2cWNsNDM1MWpsNHA5anhvaDR0NzF3eTNqNG04bXg4MmRqNWx4UWNlcmFtaWM6Ly8qP21vZGVsPWtqemw2aHZmcmJ3NmM1Nnd1c200Mmo4ZGoxaGw5Zm1nenpqeWM2M2I3YTAyYXU1ZmxwNnpvcnJzOWk5OXZoMXhRY2VyYW1pYzovLyo/bW9kZWw9a2p6bDZodmZyYnc2Y2FoNjlsbHlibGxibnoweDgyZWJ1NW1pZ2tkeGlhd3FkYThwdjFzZXp0bXp0bGE2c2NoaXN0YXRlbWVudHg8R2l2ZSB0aGlzIGFwcGxpY2F0aW9uIGFjY2VzcyB0byBzb21lIG9mIHlvdXIgZGF0YSBvbiBDZXJhbWljYXOiYXN4hDB4OWYyMzA4YjMwNmIxYmVhNzg1YzAwMDc2YjJmYjNlY2IxMTFmNDRjYjhlMWRjNzRkY2M1MWViMGJjMzgwYjdlMjIyNzJiODU2ODU4YmRiZDhiMzY2ZTMzMGQyODM2NGJlYzkyZmNmOWIxNWZmMWU3ZGQwOWRiNWMyNjQwODA2ODYxYmF0ZmVpcDE5MQ"},"opts":{"anchor":true,"publish":true,"sync":0}}'

It’s updating a field on a document. This is the query:

mutation UpdateNode($input: UpdateGraphNodeInput!) {
  updateGraphNode(input: $input) {
    document {
      id
    }
  }
}

This one hangs:

await updateNodeMutation.mutateAsync({
  input: {
    id: node.ceramicID,
    content: { position: { x: node.position.x, y: node.position.y } },
  },
});

Whereas this one worked:

await updateNodeMutation.mutateAsync({
  input: {
    id: node?.ceramicID,
    content: {
      type: node.type,
      data: pickBy(
        pick(node.data, ["childrenHidden", "label", "url"]),
        identity
      ),
      meta: node?.meta ?? undefined,
    },
  },
});

Not sure if this helps but hopefully it will provide some clue to what the problem might be.