search

surrealdb / surrealdb.js

SurrealDB SDK for JavaScript
https://surrealdb.com
Apache License 2.0
272 stars 45 forks source link

Bug: CBORError: Remaining bytes #248

Closed rvdende closed 2 months ago

rvdende commented 2 months ago

Describe the bug

Not sure if this is a bug on the surrealdb.js implementation, or in cbor-redux, but this is the error. It seems to happen after a while, not sure if its to do with authentication getting stale, or some other memory issue after a while.

The database connection becomes unusable and only restarting the server seems to get things back to working. So I'd consider this a critical bug that breaks usability for deployments.

I've opened an issue here aswell https://github.com/aaronhuggins/cbor-redux/issues/36

 ⨯ unhandledRejection: Error: CBORError: Remaining bytes
    at decode (file:///node_modules/.pnpm/cbor-redux@1.0.0/node_modules/cbor-redux/esm/src/decode.js:271:19)
    at decodeCbor (file:///node_modules/.pnpm/surrealdb.js@1.0.0-beta.5/node_modules/surrealdb.js/esm/library/cbor/index.js:76:12)
    at HttpEngine.rpc (file:///node_modules/.pnpm/surrealdb.js@1.0.0-beta.5/node_modules/surrealdb.js/esm/library/engine.js:262:26)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async Surreal.ping (file:///node_modules/.pnpm/surrealdb.js@1.0.0-beta.5/node_modules/surrealdb.js/esm/surreal.js:130:27)

Any idea what might be causing this?

Steps to reproduce

I used https://create.t3.gg/ to setup a base t3 template.

Then I use this to retain a db connection through hot module reloading: 

import { Surreal } from "surrealdb.js";
import { env } from "~/env";

let client;
let dbPromise: Surreal;

if (process.env.NODE_ENV === "development") {
  // In development mode, use a global variable so that the value
  // is preserved across module reloads caused by HMR (Hot Module Replacement).
  console.log("development mode using global var for reload support");
  const globalWithSurreal = global as typeof globalThis & {
    _dbPromise?: Surreal;
  };

  if (!globalWithSurreal._dbPromise) {
    client = new Surreal();

    await client.connect(`${env.SURREALDB_HOST}/rpc`, {
      namespace: env.SURREALDB_NS,
      database: env.SURREALDB_DB,
      auth: {
        username: env.SURREALDB_USER,
        password: env.SURREALDB_PASS,
        namespace: env.SURREALDB_NS,
        database: env.SURREALDB_DB,
      }
    });

    await client.use({
      namespace: env.SURREALDB_NS,
      database: env.SURREALDB_DB,
    });
    console.log("connected!!!")
    globalWithSurreal._dbPromise = client;
  }

  console.log("using existing connection...");
  dbPromise = globalWithSurreal._dbPromise;
} else {
  console.log("prod mode, no global var");
  client = new Surreal();
  await client.connect(`${env.SURREALDB_HOST}/rpc`, {
    namespace: env.SURREALDB_NS,
    database: env.SURREALDB_DB,
    auth: {
      username: env.SURREALDB_USER,
      password: env.SURREALDB_PASS,
      namespace: env.SURREALDB_NS,
      database: env.SURREALDB_DB,
    }
  });

  await client.use({
    namespace: env.SURREALDB_NS,
    database: env.SURREALDB_DB,
  });
  console.log("connected!!!")
  dbPromise = client;
}

export const db = dbPromise;

Expected behaviour

Perhaps a better error description of what went wrong would be helpful.

SurrealDB version

1.4.2 for linux on x86_64

SurrealDB.js version

1.0.0-beta.5

Contact Details

rouan@8bo.org

Is there an existing issue for this?

Code of Conduct

alan-strickland-red commented 2 months ago

I am getting the same error. I started running surrealdb in Docker Desktop on Friday and left it running over the weekend

I also left a debugger on and have the server running with trace logging so I have a bit more information.

[api] {
[api]   message: 'CBORError: Remaining bytes',
[api]   name: 'Error',
[api]   stack: 'Error: CBORError: Remaining bytes\n' +
[api]     '    at decode (file:///D:/git-hub/red-technology/tripla/node_modules/cbor-redux/esm/src/decode.js:271:19)\n' +
[api]     '    at decodeCbor (file:///D:/git-hub/red-technology/tripla/node_modules/surrealdb.js/src/library/cbor/index.ts:101:9)\n' +
[api]     '    at HttpEngine.rpc (file:///D:/git-hub/red-technology/tripla/node_modules/surrealdb.js/src/library/engine.ts:333:33)\n' +
[api]     '    at processTicksAndRejections (node:internal/process/task_queues:95:5)\n' +
[api]     '    at async Surreal.ping (file:///D:/git-hub/red-technology/tripla/node_modules/surrealdb.js/src/surreal.ts:160:21)',
[api]   code: undefined,
[api]   signal: undefined
[api] }

image

image

image

2024-04-29T08:27:12.354041Z DEBUG request: surreal::net::tracer: started processing request otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="fa5a555e-7ef8-42e3-ac3c-ed2ec32cf239" client.address="172.17.0.1"
2024-04-29T08:27:12.354075Z TRACE request: surrealdb_core::iam::verify: Attempting token authentication otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="fa5a555e-7ef8-42e3-ac3c-ed2ec32cf239" client.address="172.17.0.1"
2024-04-29T08:27:12.354105Z TRACE request: surrealdb_core::iam::verify: The 'exp' field in the authentication token was invalid otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="fa5a555e-7ef8-42e3-ac3c-ed2ec32cf239" client.address="172.17.0.1"
2024-04-29T08:27:12.354118Z DEBUG request: surreal::net::tracer: finished processing request otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="fa5a555e-7ef8-42e3-ac3c-ed2ec32cf239" client.address="172.17.0.1" http.response.status_code=401 http.latency.ms=0
2024-04-29T08:27:12.354600Z DEBUG request: surreal::net::tracer: started processing request otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="6ba28e0d-27af-4838-9833-311972c64237" client.address="172.17.0.1"
2024-04-29T08:27:12.354674Z TRACE request: surrealdb_core::iam::verify: Attempting token authentication otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="6ba28e0d-27af-4838-9833-311972c64237" client.address="172.17.0.1"
2024-04-29T08:27:12.354705Z TRACE request: surrealdb_core::iam::verify: The 'exp' field in the authentication token was invalid otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="6ba28e0d-27af-4838-9833-311972c64237" client.address="172.17.0.1"
2024-04-29T08:27:12.354722Z DEBUG request: surreal::net::tracer: finished processing request otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="6ba28e0d-27af-4838-9833-311972c64237" client.address="172.17.0.1" http.response.status_code=401 http.latency.ms=0
2024-04-29T08:27:12.355095Z DEBUG request: surreal::net::tracer: started processing request otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="4e2ba64f-872f-4671-8430-d55c83531c40" client.address="172.17.0.1"
2024-04-29T08:27:12.355139Z TRACE request: surrealdb_core::iam::verify: Attempting token authentication otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="4e2ba64f-872f-4671-8430-d55c83531c40" client.address="172.17.0.1"
2024-04-29T08:27:12.355170Z TRACE request: surrealdb_core::iam::verify: The 'exp' field in the authentication token was invalid otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="4e2ba64f-872f-4671-8430-d55c83531c40" client.address="172.17.0.1"
2024-04-29T08:27:12.355206Z DEBUG request: surreal::net::tracer: finished processing request otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="4e2ba64f-872f-4671-8430-d55c83531c40" client.address="172.17.0.1" http.response.status_code=401 http.latency.ms=0
2024-04-29T08:27:12.355799Z DEBUG request: surreal::net::tracer: started processing request otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="ff944920-5636-495c-ad91-8cb4600afea9" client.address="172.17.0.1"
2024-04-29T08:27:12.355842Z TRACE request: surrealdb_core::iam::verify: Attempting token authentication otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="ff944920-5636-495c-ad91-8cb4600afea9" client.address="172.17.0.1"
2024-04-29T08:27:12.355862Z TRACE request: surrealdb_core::iam::verify: The 'exp' field in the authentication token was invalid otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="ff944920-5636-495c-ad91-8cb4600afea9" client.address="172.17.0.1"
2024-04-29T08:27:12.355872Z DEBUG request: surreal::net::tracer: finished processing request otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="ff944920-5636-495c-ad91-8cb4600afea9" client.address="172.17.0.1" http.response.status_code=401 http.latency.ms=0
2024-04-29T08:27:12.356787Z DEBUG request: surreal::net::tracer: started processing request otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="eb916c5c-351a-4a62-9b6d-280decf78f9c" client.address="172.17.0.1"
2024-04-29T08:27:12.356839Z TRACE request: surrealdb_core::iam::verify: Attempting token authentication otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="eb916c5c-351a-4a62-9b6d-280decf78f9c" client.address="172.17.0.1"
2024-04-29T08:27:12.356862Z TRACE request: surrealdb_core::iam::verify: The 'exp' field in the authentication token was invalid otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="eb916c5c-351a-4a62-9b6d-280decf78f9c" client.address="172.17.0.1"
2024-04-29T08:27:12.356875Z DEBUG request: surreal::net::tracer: finished processing request otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="eb916c5c-351a-4a62-9b6d-280decf78f9c" client.address="172.17.0.1" http.response.status_code=401 http.latency.ms=0
2024-04-29T08:27:12.358974Z DEBUG request: surreal::net::tracer: started processing request otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="b0ad3567-8ad6-4bc2-93fd-342a455d6f99" client.address="172.17.0.1"
2024-04-29T08:27:12.359013Z TRACE request: surrealdb_core::iam::verify: Attempting token authentication otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="b0ad3567-8ad6-4bc2-93fd-342a455d6f99" client.address="172.17.0.1"
2024-04-29T08:27:12.359034Z TRACE request: surrealdb_core::iam::verify: The 'exp' field in the authentication token was invalid otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="b0ad3567-8ad6-4bc2-93fd-342a455d6f99" client.address="172.17.0.1"
2024-04-29T08:27:12.359044Z DEBUG request: surreal::net::tracer: finished processing request otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="b0ad3567-8ad6-4bc2-93fd-342a455d6f99" client.address="172.17.0.1" http.response.status_code=401 http.latency.ms=0
2024-04-29T08:27:12.359215Z DEBUG request: surreal::net::tracer: started processing request otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="9eba4900-e4a3-49e2-88bf-ce4f562cda26" client.address="172.17.0.1"
2024-04-29T08:27:12.359271Z TRACE request: surrealdb_core::iam::verify: Attempting token authentication otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="9eba4900-e4a3-49e2-88bf-ce4f562cda26" client.address="172.17.0.1"
2024-04-29T08:27:12.359284Z TRACE request: surrealdb_core::iam::verify: The 'exp' field in the authentication token was invalid otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="9eba4900-e4a3-49e2-88bf-ce4f562cda26" client.address="172.17.0.1"
2024-04-29T08:27:12.359297Z DEBUG request: surreal::net::tracer: finished processing request otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="9eba4900-e4a3-49e2-88bf-ce4f562cda26" client.address="172.17.0.1" http.response.status_code=401 http.latency.ms=0
2024-04-29T08:27:12.359536Z DEBUG request: surreal::net::tracer: started processing request otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="1482db39-fa3c-4b8c-991d-8e809a9a56d8" client.address="172.17.0.1"
2024-04-29T08:27:12.359613Z TRACE request: surrealdb_core::iam::verify: Attempting token authentication otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="1482db39-fa3c-4b8c-991d-8e809a9a56d8" client.address="172.17.0.1"
2024-04-29T08:27:12.359628Z TRACE request: surrealdb_core::iam::verify: The 'exp' field in the authentication token was invalid otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="1482db39-fa3c-4b8c-991d-8e809a9a56d8" client.address="172.17.0.1"
2024-04-29T08:27:12.359637Z DEBUG request: surreal::net::tracer: finished processing request otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="1482db39-fa3c-4b8c-991d-8e809a9a56d8" client.address="172.17.0.1" http.response.status_code=401 http.latency.ms=0
2024-04-29T08:27:12.360584Z DEBUG request: surreal::net::tracer: started processing request otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="414e7667-a36e-4860-af3a-f828ec5a4d04" client.address="172.17.0.1"
2024-04-29T08:27:12.360630Z TRACE request: surrealdb_core::iam::verify: Attempting token authentication otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="414e7667-a36e-4860-af3a-f828ec5a4d04" client.address="172.17.0.1"
2024-04-29T08:27:12.360649Z TRACE request: surrealdb_core::iam::verify: The 'exp' field in the authentication token was invalid otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="414e7667-a36e-4860-af3a-f828ec5a4d04" client.address="172.17.0.1"
2024-04-29T08:27:12.360661Z DEBUG request: surreal::net::tracer: finished processing request otel.kind="server" http.request.method="POST" url.path="/rpc" network.protocol.name="http" network.protocol.version="1.1" http.request.body.size="31" user_agent.original="undici" otel.name="POST /rpc" http.route="/rpc" http.request.id="414e7667-a36e-4860-af3a-f828ec5a4d04" client.address="172.17.0.1" http.response.status_code=401 http.latency.ms=0
rvdende commented 2 months ago

From the logs it seems like this gets triggered by Surreal.ping. Perhaps the ping packets are not being handled correctly?

rvdende commented 2 months ago

@alan-strickland-red thanks for seconding this bug, I thought its maybe just me. I also tried rolling back surrealdb.js to beta 4 or beta 1 and same issue.

rvdende commented 2 months ago

@kearfy just want to make sure you see this. Looks like a bug introduced from https://github.com/surrealdb/surrealdb.js/pull/227

oskar-gmerek commented 2 months ago

@alan-strickland-red What happens if you change the session duration to e.g. 1 minute, will the same error occur after that minute?

alan-strickland-red commented 2 months ago

@oskar-gmerek How do you set the session duration when authenticating with the root user?

I started using surrealdb for a project on Friday so I am very much new to the surrealdb platform, but I think when I read about authentication is said something along the lines of system user sessions never expire.

oskar-gmerek commented 2 months ago

@alan-strickland-red never mind, I was think that come from scope user auth.

Yes, I also seen the message on discord that system users sessions currently never expire, but I understand this is on the DB side. Anyway, the exp field on system level users are set for 1 hour. I guess that error may happen after inactivity longer than 1 hour, I guessing that you do not check the exp field before trying to authenticate what lead to unexpected behavior. But is just guessing from my side, I can't even find a part of code throwing that error, as well as I do not know, how you actually authenticate that user.

kearfy commented 2 months ago

Hey all! With #249, these errors should now be nicely returned in the form of a HttpConnectionError. Ideally the RPC layer on SurrealDB's side would handle authentication errors and give back the same result as with WebSockets, but this is the best we can handle it on JS's side at the moment.

If you cannot figure out how to solve the actual authentication issue, feel free to ping on or @gguillemas on Discord so we can figure out there what's going wrong.

Thank you! 🙏

gguillemas commented 2 months ago

We have updated our documentation to explain how expiration works in SurrealDB: https://surrealdb.com/docs/surrealdb/security/authentication#expiration-since-130

rvdende commented 2 months ago

@kearfy thank you for the change, its a lot better now.

unhandledRejection: HttpConnectionError: There was a problem with authentication
...
  status: 401,
  statusText: 'Unauthorized',

Wouldnt it be better to have the client side library automatically call authenticate again before the session expires? It should know how long before it expires and be able to refresh the connection session automatically. This will save many long running processes from having to implement this themselves? Any reason not to?