Error: write CONNECTION_CLOSED localhost:2323

[jonasgheer]

I trying to generate a test data set. To do so I am inserting around around 4000 items at a time in a loop:

await sql`insert into testevents ${sql(eventsList)}`

But after running the script for around 7 minutes I get this error:

node:internal/process/esm_loader:40
      internalBinding('errors').triggerUncaughtException(
                                ^

Error: write CONNECTION_CLOSED localhost:2323
    at Socket.closed (file:///Users/jonasgheer/eventlogdump/node_modules/postgres/src/connection.js:440:57)
    at Socket.emit (node:events:514:28)
    at TCP.<anonymous> (node:net:337:12)
    at cachedError (file:///Users/jonasgheer/eventlogdump/node_modules/postgres/src/query.js:170:23)
    at new Query (file:///Users/jonasgheer/eventlogdump/node_modules/postgres/src/query.js:36:24)
    at sql (file:///Users/jonasgheer/eventlogdump/node_modules/postgres/src/index.js:112:11)
    at file:///Users/jonasgheer/eventlogdump/create_test_data.js:45:18 {
  code: 'CONNECTION_CLOSED',
  errno: 'CONNECTION_CLOSED',
  address: 'localhost',
  port: 2323
}

Node.js v20.8.0
node create_test_data.js  160.55s user 9.53s system 36% cpu 7:40.69 total

I started out with default settings:

const sql = postgres({
    database: "events",
    host: "localhost",
    username: "foo",
    password: "bar",
    port: 2323
})

But the last one I tried one was:

const sql = postgres({
    database: "events",
    host: "localhost",
    username: "foo",
    password: "bar",
    port: 2323,
    idle_timeout: 30,
    connect_timeout: 60,
    connection: {
        statement_timeout: 20 * 1000 // PostgreSQL expects milliseconds
    }
})

It does not seem to make much of a difference for me. Is it just a matter of tweaking the settings, or is there something else going on? The database is running in a docker container.

[porsager]

What does you PostgreSQL logs say?

[jonasgheer]

Ah, probably should have thought of that first 🤦‍♂️

2023-10-28 20:06:30.244 UTC [59] LOG:  invalid record length at 5/948D7A08: wanted 24, got 0
2023-10-28 20:06:30.244 UTC [59] LOG:  redo done at 5/948D79D0 system usage: CPU: user: 1.11 s, system: 0.81 s, elapsed: 2.14 s
2023-10-28 20:06:30.787 UTC [1] LOG:  database system is ready to accept connections
2023-10-28 20:16:34.157 UTC [1] LOG:  server process (PID 70) was terminated by signal 9: Killed
2023-10-28 20:16:34.157 UTC [1] DETAIL:  Failed process was running: insert into testevents ("a","b","c","d","e","f","g","h","i")values($1,$2,$3,$4,$5,$6,$7,$8,$9),($10,$11,$12,$13,$14,$15,$16,$17,$18),($19,$20,$21,$22,$23,$24,$25,$26,$27),($28,$29,$30,$31,$32,$33,$34,$35,$36),($37,$38,$39,$40,$41,$42,$43,$44,$45),($46,$47,$48,$49,$50,$51,$52,$53,$54),($55,$56,$57,$58,$59,$60,$61,$62,$63),($64,$65,$66,$67,$68,$69,$70,$71,$72),($73,$74,$75,$76,$77,$78,$79,$80,$81),($82,$83,$84,$85,$86,$87,$88,$89,$90),($91,$92,$93,$94,$95,$96,$97,$98,$99),($100,$101,$102,$103,$104,$105,$106,$107,$108),($109,$110,$111,$112,$113,$114,$115,$116,$117),($118,$119,$120,$121,$122,$123,$124,$125,$126),($127,$128,$129,$130,$131,$132,$133,$134,$135),($136,$137,$138,$139,$140,$141,$142,$143,$144),($145,$146,$147,$148,$149,$150,$151,$152,$153),($154,$155,$156,$157,$158,$159,$160,$161,$162),($163,$164,$165,$166,$167,$168,$169,$170,$171),($172,$173,$174,$175,$176,$177,$178,$179,$180),($181,$182,$183,$184,$185,$186,$187
2023-10-28 20:16:34.158 UTC [1] LOG:  terminating any other active server processes
2023-10-28 20:16:34.166 UTC [1] LOG:  all server processes terminated; reinitializing
2023-10-28 20:16:34.220 UTC [82] LOG:  database system was interrupted; last known up at 2023-10-28 20:15:51 UTC
2023-10-28 20:16:34.374 UTC [82] LOG:  database system was not properly shut down; automatic recovery in progress
2023-10-28 20:16:34.377 UTC [82] LOG:  redo starts at 6/DE0AE9B0
2023-10-28 20:16:36.800 UTC [82] LOG:  invalid record length at 7/15C36370: wanted 24, got 0
2023-10-28 20:16:36.800 UTC [82] LOG:  redo done at 7/15C36348 system usage: CPU: user: 1.15 s, system: 0.83 s, elapsed: 2.42 s
2023-10-28 20:16:37.303 UTC [1] LOG:  database system is ready to accept connections
2023-10-28 20:25:28.159 UTC [1] LOG:  server process (PID 93) was terminated by signal 9: Killed

After some googling it seems I am running into some OOM issues unrelated to the client library. Thanks for the quick reply! Closing the ticket.