start-odk.sh and cron jobs do not complete when Sentry is blocked

[yanokwa]

The scripts (both start-odk.sh and the nightly cron jobs) hang when the service container can't reach the ODK Sentry instance on the internet. It would be great if this could be handled gracefully with an error or with a log message.

https://forum.getodk.org/t/memory-use-issue-using-docker-compose-stack-odkcentral-service-container/56473

[lognaturel]

Some good thoughts from @jniles at https://forum.getodk.org/t/memory-use-issue-using-docker-compose-stack-odkcentral-service-container/56473/12?u=ln with an offer to help with some guidance

[yanokwa]

I've added documentation at https://github.com/getodk/docs/pull/2022/files. We'll be working on a hot fix to ensure Central can start even with Sentry is disabled or down.

[jniles]

You guys are outstanding; thank you for the quick work on this!

[alxndrsn]

Reproduction

Unclear what the exact failure seen by users is, but this seems to produce a similar situation:

Setup

/etc/hosts

Add:

0.0.0.0 o1.ingest.sentry.io
0.0.0.0 ingest.sentry.io

lib/external/sentry.js

patch lib/external/sentry.js <<'EOF'
--- a/lib/external/sentry.js
+++ b/lib/external/sentry.js
@@ -185,6 +185,8 @@ const _init = (config) => { // eslint-disable-line no-shadow
   ];
 
   Sentry.init({
+    debug: true,
+    enableLogs: true,
     dsn: `https://${config.key}@${config.orgSubdomain}.ingest.sentry.io/${config.project}`,
     environment: process.env.SENTRY_ENVIRONMENT || 'production',
     integrations: defaults => [
EOF

command

In odk-central-backend repo:

NODE_CONFIG='{"default":{"external":{"sentry":{"key":"bbbbeeeeeeeeeeeeeffffffffffff","project":"123","orgSubdomain":"o1"}}}}' \
node lib/bin/run-analytics.js

Example logs

Sentry Logger [log]: @opentelemetry_sentry-patched/instrumentation-http outgoingRequest on request close()
Sentry Logger [log]: Flushing outcomes...
Sentry Logger [log]: Sending outcomes: [ { reason: 'network_error', category: 'internal', quantity: 1 } ]
Sentry Logger [log]: Instrumentation suppressed, returning Noop Span
Sentry Logger [log]: [Tracing] Not injecting trace data for url because tracing is suppressed.
Sentry Logger [log]: @opentelemetry_sentry-patched/instrumentation-http https instrumentation outgoingRequest
Sentry Logger [log]: @opentelemetry_sentry-patched/instrumentation-http http.ClientRequest return request
Sentry Logger [log]: @sentry/instrumentation-http Handling finished outgoing request
Sentry Logger [log]: @opentelemetry_sentry-patched/instrumentation-http outgoingRequest on request error() Error: connect ECONNREFUSED 0.0.0.0:443
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1637:16)
    at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:130:17) {
  errno: -111,
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '0.0.0.0',
  port: 443
}
Sentry Logger [log]: Recording outcome: "network_error:internal"
Sentry Logger [error]: Encountered error running transport request: Error: connect ECONNREFUSED 0.0.0.0:443
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1637:16)
    at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:130:17) {
  errno: -111,
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '0.0.0.0',
  port: 443
}
Sentry Logger [error]: Error while sending envelope: Error: connect ECONNREFUSED 0.0.0.0:443
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1637:16)
    at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:130:17) {
  errno: -111,
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '0.0.0.0',
  port: 443
}
Sentry Logger [log]: @opentelemetry_sentry-patched/instrumentation-http outgoingRequest on request close()
Sentry Logger [log]: Flushing outcomes...
Sentry Logger [log]: Sending outcomes: [ { reason: 'network_error', category: 'internal', quantity: 1 } ]
Sentry Logger [log]: Instrumentation suppressed, returning Noop Span
Sentry Logger [log]: [Tracing] Not injecting trace data for url because tracing is suppressed.
Sentry Logger [log]: @opentelemetry_sentry-patched/instrumentation-http https instrumentation outgoingRequest
Sentry Logger [log]: @opentelemetry_sentry-patched/instrumentation-http http.ClientRequest return request
Sentry Logger [log]: @sentry/instrumentation-http Handling finished outgoing request
Sentry Logger [log]: @opentelemetry_sentry-patched/instrumentation-http outgoingRequest on request error() Error: connect ECONNREFUSED 0.0.0.0:443
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1637:16)
    at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:130:17) {
  errno: -111,
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '0.0.0.0',
  port: 443
}
Sentry Logger [log]: Recording outcome: "network_error:internal"
Sentry Logger [error]: Encountered error running transport request: Error: connect ECONNREFUSED 0.0.0.0:443
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1637:16)
    at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:130:17) {
  errno: -111,
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '0.0.0.0',
  port: 443
}
Sentry Logger [error]: Error while sending envelope: Error: connect ECONNREFUSED 0.0.0.0:443
    at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1637:16)
    at TCPConnectWrap.callbackTrampoline (node:internal/async_hooks:130:17) {
  errno: -111,
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '0.0.0.0',
  port: 443
}

[johannestoger]

Great, looking forward to use this on our next upgrade.

[alxndrsn]

Possible Fixes

1. Sentry.close()

Calling Sentry.close() seems to prevent the endless error loop from establishing itself.

It's not made explicit in the docs that calling Sentry.close() is required: https://docs.sentry.io/platforms/javascript/guides/node/configuration/apis/#close

2. Sentry.init({ sendClientReports:false })

Another fix seems to be to disable sendClientReports in Sentry.init(): https://docs.sentry.io/platforms/javascript/guides/node/configuration/options/#sendClientReports

I don't think the documentation is very explicit about what a "client report" actually is, or what is lost by disabling it:

Client reports are a protocol feature that let clients send status reports about themselves to Sentry. They are currently mainly used to emit outcomes for events that were never sent.

Recommendation

Code changes

The immediate safe approach looks to be disabling sendClientReports.

Longer-term, it might be good to:

1. re-enable sendClientReports, at least in odk cloud instances, and
2. understand why Sentry does not automatically clean up after itself. If the current behaviour is expected, ensure that corresponding Sentry.close() or other recommended cleanup is done in every situation where Sentry.init() is called.

Tests

It seems like testing this issue will require a full e2e test including modifications to /etc/hosts - attempts to recreate the issue by overriding NodeJS's dns.lookup() function did not trigger the same behaviour.

[alxndrsn]

Filed upstream at getsentry/sentry-javascript#18802