runes api failed to reconnect to PG

[deantchi]

Runes api failed to re-establish connection to PG after PG failed to gracefully shut down. The Runes API read had to be restarted.

PG logs

2024-11-07 23:47:37.591 GMT [1] LOG:  starting PostgreSQL 15.1 on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2024-11-07 23:47:37.591 GMT [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2024-11-07 23:47:37.591 GMT [1] LOG:  listening on IPv6 address "::", port 5432
2024-11-07 23:47:37.594 GMT [1] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2024-11-07 23:47:37.606 GMT [100] LOG:  database system was interrupted; last known up at 2024-11-07 23:45:24 GMT
2024-11-07 23:47:37.663 GMT [100] LOG:  database system was not properly shut down; automatic recovery in progress
2024-11-07 23:47:37.670 GMT [100] LOG:  redo starts at DE/4A12EB0
2024-11-07 23:47:37.978 GMT [100] LOG:  invalid record length at DE/79A41A8: wanted 24, got 0
2024-11-07 23:47:37.978 GMT [100] LOG:  redo done at DE/79A4170 system usage: CPU: user: 0.06 s, system: 0.12 s, elapsed: 0.30 s
2024-11-07 23:47:37.982 GMT [98] LOG:  checkpoint starting: end-of-recovery immediate wait

Runes-API logs

{"level":"info","time":"2024-11-07T23:47:34.013Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","reqId":"req-5pfe","res":{"statusCode":500},"responseTime":532.3675880432129,"msg":"request completed"}
{"level":"error","time":"2024-11-07T23:47:34.013Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","msg":"Shutting down... received unhandledRejection."}
{"level":"info","time":"2024-11-07T23:47:34.013Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","msg":"Closing API Server..."}
{"level":"error","time":"2024-11-07T23:47:34.015Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","reqId":"req-5pfa","req":{"method":"GET","url":"/runes/v1/blocks/869351/activity?limit=60&offset=10320","hostname":"api.hiro.so","remoteAddress":"45.114.15.131","remotePort":41377},"res":{"statusCode":500},"err":{"type":"Error","message":"write CONNECTION_CLOSED mainnet-runes-api-postgresql-blue.mainnet-runes-api.svc.cluster.local:5432","stack":"Error: write CONNECTION_CLOSED mainnet-runes-api-postgresql-blue.mainnet-runes-api.svc.cluster.local:5432\n    at Socket.closed (/app/node_modules/postgres/cjs/src/connection.js:438:57)\n    at Socket.emit (node:events:519:28)\n    at TCP.<anonymous> (node:net:338:12)\n    at TCP.callbackTrampoline (node:internal/async_hooks:130:17)\n    at cachedError (/app/node_modules/postgres/cjs/src/query.js:170:23)\n    at new Query (/app/node_modules/postgres/cjs/src/query.js:36:24)\n    at PgStore.sql [as _sql] (/app/node_modules/postgres/cjs/src/index.js:112:11)\n    at PgStore.getActivity (/app/dist/src/pg/pg-store.js:104:40)","code":"CONNECTION_CLOSED","errno":"CONNECTION_CLOSED","address":["mainnet-runes-api-postgresql-blue.mainnet-runes-api.svc.cluster.local"],"port":[5432]},"msg":"write CONNECTION_CLOSED mainnet-runes-api-postgresql-blue.mainnet-runes-api.svc.cluster.local:5432"}
{"level":"info","time":"2024-11-07T23:47:34.015Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","reqId":"req-5pfa","res":{"statusCode":500},"responseTime":1325.143569946289,"msg":"request completed"}
{"level":"error","time":"2024-11-07T23:47:34.199Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","reqId":"req-5pfb","req":{"method":"GET","url":"/runes/v1/blocks/869351/activity?limit=60&offset=10380","hostname":"api.hiro.so","remoteAddress":"45.114.12.73","remotePort":59953},"res":{"statusCode":500},"err":{"type":"Error","message":"read ECONNRESET","stack":"Error: read ECONNRESET\n    at TCP.onStreamRead (node:internal/stream_base_commons:218:20)\n    at TCP.callbackTrampoline (node:internal/async_hooks:130:17)\n    at cachedError (/app/node_modules/postgres/cjs/src/query.js:170:23)\n    at new Query (/app/node_modules/postgres/cjs/src/query.js:36:24)\n    at PgStore.sql [as _sql] (/app/node_modules/postgres/cjs/src/index.js:112:11)\n    at PgStore.getChainTipEtag (/app/dist/src/pg/pg-store.js:54:39)","errno":-104,"code":"ECONNRESET","syscall":"read"},"msg":"read ECONNRESET"}
{"level":"info","time":"2024-11-07T23:47:34.200Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","reqId":"req-5pfb","res":{"statusCode":500},"responseTime":1046.593843460083,"msg":"request completed"}
{"level":"info","time":"2024-11-07T23:47:34.460Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","reqId":"req-5pfk","res":{"statusCode":503},"msg":"request aborted - refusing to accept new requests as server is closing"}
{"level":"info","time":"2024-11-07T23:47:34.644Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","reqId":"req-5pfl","res":{"statusCode":503},"msg":"request aborted - refusing to accept new requests as server is closing"}
{"level":"info","time":"2024-11-07T23:47:48.861Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","reqId":"req-4av","req":{"method":"GET","url":"/metrics","hostname":"10.0.19.16:9153","remoteAddress":"127.0.0.6","remotePort":33689},"msg":"incoming request"}
{"level":"info","time":"2024-11-07T23:47:48.923Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","reqId":"req-4av","res":{"statusCode":200},"responseTime":62.02267265319824,"msg":"request completed"}
{"level":"info","time":"2024-11-07T23:48:18.861Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","reqId":"req-4aw","req":{"method":"GET","url":"/metrics","hostname":"10.0.19.16:9153","remoteAddress":"127.0.0.6","remotePort":33689},"msg":"incoming request"}
{"level":"info","time":"2024-11-07T23:48:18.873Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","reqId":"req-4aw","res":{"statusCode":200},"responseTime":11.848004341125488,"msg":"request completed"}
{"level":"info","time":"2024-11-07T23:48:33.800Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","msg":"API Server closed"}
{"level":"info","time":"2024-11-07T23:48:33.800Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","msg":"Closing Prometheus Server..."}
{"level":"info","time":"2024-11-07T23:48:33.800Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","msg":"Prometheus Server closed"}
{"level":"info","time":"2024-11-07T23:48:33.800Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","msg":"Closing DB..."}
{"level":"error","time":"2024-11-07T23:49:33.800Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","msg":"DB is taking longer than expected to shutdown, possibly hanging indefinitely"}
{"level":"error","time":"2024-11-07T23:50:33.801Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","msg":"DB is taking longer than expected to shutdown, possibly hanging indefinitely"}
{"level":"error","time":"2024-11-07T23:51:33.801Z","pid":1,"hostname":"runes-api-blue-reader-f7cd89545-mlfql","name":"runes-api","msg":"DB is taking longer than expected to shutdown, possibly hanging indefinitely"}