fetch error seldomly causes deno panic....

[eseiker]

[2023-08-18 13:02:05 WARN][observer] Emit lock expired, re-publishing to emit queue, blockNumber: 17935509  logIndex: 173
[2023-08-18 13:02:05 WARN][observer] Emit lock expired, re-publishing to emit queue, blockNumber: 17935554  logIndex: 171
[2023-08-18 13:02:05 WARN][observer] Emit lock expired, re-publishing to emit queue, blockNumber: 17935571  logIndex: 99
[2023-08-18 13:02:05 DBUG][emitter] Received event message, blockNumber: 17935509  logIndex: 173  delivery tag: 0.
[2023-08-18 13:02:05 DBUG][emitter] Received event message, blockNumber: 17935554  logIndex: 171  delivery tag: 0.
[2023-08-18 13:02:05 DBUG][emitter] Received event message, blockNumber: 17935571  logIndex: 99  delivery tag: 0.
[2023-08-18 13:02:05 INFO][emitter] Queueing event for emit, blockNumber: 17935554  logIndex: 171.
[2023-08-18 13:02:05 DBUG][emitter] Acknowledging AMQP message for event, blockNumber: 17935554  logIndex: 171  delivery tag: 0.
[2023-08-18 13:02:05 INFO][emitter] Posting event destination: http://localhost:4000  blockNumber: 17935554  logIndex: 171.
[2023-08-18 13:02:05 EROR][emitter] Event emit POST request failed with an exception, blockNumber: 17935554  logIndex: 171  url: http://localhost:4000: TypeError: error sending request for url (http://localhost:4000/): error trying to connect: tcp connect error: Connection refused (os error 61)
    at async mainFetch (ext:deno_fetch/26_fetch.js:276:12)
    at async fetch (ext:deno_fetch/26_fetch.js:500:7)
    at async file:///Users/mizuki/Projects/Corvette/emitter.ts:290:34
    at async Promise.all (index 0)
    at async file:///Users/mizuki/Projects/Corvette/emitter.ts:283:36
    at async Promise.all (index 0)
    at async file:///Users/mizuki/Projects/Corvette/emitter.ts:265:22
    at async doMutex (file:///Users/mizuki/Projects/Corvette/concurrencyUtils.ts:19:16)
    at async emitEvents (file:///Users/mizuki/Projects/Corvette/emitter.ts:262:7)
[2023-08-18 13:02:05 INFO][emitter] Event post failed for some webhook URLs, will retry on next event observed or after 60s, blockNumber: 17935554  logIndex: 171  destinations: http://localhost:4000.
[2023-08-18 13:02:05 INFO][emitter] Queueing event for emit, blockNumber: 17935509  logIndex: 173.
[2023-08-18 13:02:05 INFO][emitter] Queueing event for emit, blockNumber: 17935571  logIndex: 99.
[2023-08-18 13:02:05 DBUG][emitter] Acknowledging AMQP message for event, blockNumber: 17935509  logIndex: 173  delivery tag: 0.
[2023-08-18 13:02:05 DBUG][emitter] Acknowledging AMQP message for event, blockNumber: 17935571  logIndex: 99  delivery tag: 0.
[2023-08-18 13:02:05 INFO][emitter] Retry posting event destination: http://localhost:4000  blockNumber: 17935554  logIndex: 171.
[2023-08-18 13:02:05 EROR][emitter] Event emit POST request failed with an exception, blockNumber: 17935554  logIndex: 171  url: http://localhost:4000: TypeError: error sending request for url (http://localhost:4000/): error trying to connect: tcp connect error: Connection refused (os error 61)
    at async mainFetch (ext:deno_fetch/26_fetch.js:276:12)
    at async fetch (ext:deno_fetch/26_fetch.js:500:7)
    at async file:///Users/mizuki/Projects/Corvette/emitter.ts:290:34
    at async Promise.all (index 0)
    at async file:///Users/mizuki/Projects/Corvette/emitter.ts:283:36
    at async Promise.all (index 0)
    at async file:///Users/mizuki/Projects/Corvette/emitter.ts:265:22
    at async doMutex (file:///Users/mizuki/Projects/Corvette/concurrencyUtils.ts:19:16)
    at async emitEvents (file:///Users/mizuki/Projects/Corvette/emitter.ts:262:7)

============================================================
Deno has panicked. This is a bug in Deno. Please report this
at https://github.com/denoland/deno/issues/new.
If you can reliably reproduce this panic, include the
reproduction steps and re-run with the RUST_BACKTRACE=1 env
var set and include the backtrace in your report.

Platform: macos aarch64
Version: 1.36.1
Args: ["deno", "run", "--allow-read", "--allow-write", "--allow-env", "--allow-run", "--allow-net", "--allow-ffi", "/Users/mizuki/Projects/Corvette/app.ts", "--main"]

thread '<unnamed>' panicked at 'called `Result::unwrap()` on an `Err` value: TrySendError { kind: Disconnected }', cli/napi/threadsafe_functions.rs:113:40
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

• This may not directly related but some other exceptions kind seldomly occurs

[2023-08-18 13:07:14 WARN][observer] Emit lock expired, re-publishing to emit queue, blockNumber: 17935509  logIndex: 173
[2023-08-18 13:07:14 WARN][observer] Emit lock expired, re-publishing to emit queue, blockNumber: 17935554  logIndex: 171
[2023-08-18 13:07:14 WARN][observer] Emit lock expired, re-publishing to emit queue, blockNumber: 17935571  logIndex: 99
[2023-08-18 13:07:14 DBUG][emitter] Received event message, blockNumber: 17935509  logIndex: 173  delivery tag: 0.
[2023-08-18 13:07:14 DBUG][emitter] Received event message, blockNumber: 17935554  logIndex: 171  delivery tag: 0.
[2023-08-18 13:07:14 DBUG][emitter] Received event message, blockNumber: 17935571  logIndex: 99  delivery tag: 0.
[2023-08-18 13:07:14 INFO][emitter] Queueing event for emit, blockNumber: 17935509  logIndex: 173.
[2023-08-18 13:07:14 DBUG][emitter] Acknowledging AMQP message for event, blockNumber: 17935509  logIndex: 173  delivery tag: 0.
[2023-08-18 13:07:14 INFO][emitter] Posting event destination: http://localhost:4000  blockNumber: 17935509  logIndex: 173.
[2023-08-18 13:07:14 INFO][emitter] Event post success for all webhook URLs, blockNumber: 17935509  logIndex: 173.
[2023-08-18 13:07:14 INFO][emitter] Queueing event for emit, blockNumber: 17935554  logIndex: 171.
[2023-08-18 13:07:14 INFO][emitter] Queueing event for emit, blockNumber: 17935571  logIndex: 99.
[2023-08-18 13:07:14 DBUG][emitter] Acknowledging AMQP message for event, blockNumber: 17935554  logIndex: 171  delivery tag: 0.
[2023-08-18 13:07:14 DBUG][emitter] Acknowledging AMQP message for event, blockNumber: 17935571  logIndex: 99  delivery tag: 0.
[2023-08-18 13:07:14 INFO][emitter] Posting event destination: http://localhost:4000  blockNumber: 17935554  logIndex: 171.
error: Uncaught PrismaClientUnknownRequestError: 
Invalid `prisma.failedUrl.deleteMany()` invocation:


Error occurred during query execution:
ConnectorError(ConnectorError { user_facing_error: None, kind: ConnectionError(Timed out during query execution.), transient: false })
    at Rn.handleRequestError (file:///Users/mizuki/Projects/Corvette/generated/client/runtime/library.js:174:7499)
    at Rn.handleAndLogRequestError (file:///Users/mizuki/Projects/Corvette/generated/client/runtime/library.js:174:6754)
    at Rn.request (file:///Users/mizuki/Projects/Corvette/generated/client/runtime/library.js:174:6344)
    at async file:///Users/mizuki/Projects/Corvette/emitter.ts:310:13
    at async Promise.all (index 0)
    at async file:///Users/mizuki/Projects/Corvette/emitter.ts:265:22
    at async doMutex (file:///Users/mizuki/Projects/Corvette/concurrencyUtils.ts:19:16)
    at async emitEvents (file:///Users/mizuki/Projects/Corvette/emitter.ts:262:7)

[Akamig]

So I scanned other code bases reporting similar issue,

First I can safely conclude two of each bugs are seperated issue.

About the first one, "thread '<unnamed>' panicked at 'called Result::unwrap()on anErr value: TrySendError { kind: Disconnected }',

In this instance, if we look at that line of threadsafe_functions.rs, that line is ominously commented as "this call should not fail", which actually failed in our case.

There was a long babble about what unbound_send() even means, but simply put it's the process of inter-thread communication, and as it try to 'unwrap' the 'unbounded_send(call)',

As far as I deduct, it expects "Err" and unwrap the actual error, but because of unsafe call_js_cb, which calls callback as it's name, possibly callback function being async function, and since await is not used before unwrap that thing, so it panics while try to unwrap some asynchronous function call instead of bubbling up it's error.

On contrary, since this caused while handling result of unbound_send(), which is inter-thread operation, so call stack couldn't be properly given because of, y'know, multi-threaded execution flow thingy.

In short, it seems bug in Deno as that log says.
Damn.

[Akamig]

Possibly Relevant Issues:
denoland/deno#5334
paritytech/jsonrpsee#284
microsoft/demikernel#246

As the error message states, the unbound_send always fails because the receiver is disconnected. So we always panic here. As you can see the receiver is immediately dropped. So I don't see how this code is every supposed to not fail. Or what is the point of it since it doesn't seem to do anything?

And I personally think this is very crucial observation. It even also commented in threadsafe_functions.rs this reciever might have already dropped. So I guess this panic happends when reciever dropped before unbound_send able to do anything.

denoland/deno#19177

[Akamig]

Anyway, sadly this is barely comprehensible for me, I have no single idea to mitigate this issue.

At least we know it happens when we tries to unwrap the content of fetch error, can we just ignore error temporarily and prevent that thing from getting executed?