Bug: Occasional EPIPE exception when using idle database connection

[kernwig]

I'm periodically receiving this exception in my Nodejs 10 Lambdas under light load. It always happens after the Lambda has been idle for around ten minutes. A later run in the same instance obtains a new connection and everything is fine once again.

Obviously I can catch and retry this on my own, but I expected dropped connections to be normal behavior handled by this library, since it is actively killing connections. Should I be pursuing a serverless-mysql library fix or handling it in my code?

Here's one entire CloudWatch log for an instance (just removing a little bit of noise via ):

START RequestId: 0e5e749e-5d68-4a7c-a4a2-5edae446077d Version: 66
2020-01-23T16:26:24.238Z    0e5e749e-5d68-4a7c-a4a2-5edae446077d    INFO    aws-https: Status: 200
2020-01-23T16:26:24.288Z    0e5e749e-5d68-4a7c-a4a2-5edae446077d    INFO    events-get-overview: runSearch: 
{
    "sql": "SELECT eventId as id, <snip>",
    "values": [
        "open"
    ],
    "timeout": 30000
}

2020-01-23T16:26:24.827Z    0e5e749e-5d68-4a7c-a4a2-5edae446077d    INFO    DB: Opened a new connection
END RequestId: 0e5e749e-5d68-4a7c-a4a2-5edae446077d
REPORT RequestId: 0e5e749e-5d68-4a7c-a4a2-5edae446077d  Duration: 5115.86 ms    Billed Duration: 5200 ms    Memory Size: 256 MB Max Memory Used: 127 MB Init Duration: 491.56 ms    
START RequestId: 5c6117cf-a1bc-415f-a8a4-7795997cfbd2 Version: 66
2020-01-23T16:37:18.030Z    5c6117cf-a1bc-415f-a8a4-7795997cfbd2    INFO    events-get-overview: runSearch: 
{
    "sql": "SELECT eventId as id, <snip>",
    "values": [
        "open"
    ],
    "timeout": 30000
}

2020-01-23T16:37:18.070Z    5c6117cf-a1bc-415f-a8a4-7795997cfbd2    ERROR   lambda-utils: Unhandled exception: { Error: write EPIPE
    at WriteWrap.afterWrite (net.js:789:14)
    --------------------
    at Protocol._enqueue (/var/task/node_modules/mysql/lib/protocol/Protocol.js:144:48)
    at Connection.query (/var/task/node_modules/mysql/lib/Connection.js:198:25)
    at PromiseLibrary (/var/task/node_modules/serverless-mysql/index.js:189:25)
    at new Promise (<anonymous>)
    at Object.query (/var/task/node_modules/serverless-mysql/index.js:185:12) errno: 'EPIPE', code: 'EPIPE', syscall: 'write', fatal: true }
2020-01-23T16:37:18.070Z    5c6117cf-a1bc-415f-a8a4-7795997cfbd2    INFO    lambda-utils: Response to API Gateway: 
{
    "statusCode": 500,
    "body": "Error: write EPIPE"
}

2020-01-23T16:37:18.071Z    5c6117cf-a1bc-415f-a8a4-7795997cfbd2    INFO    DB: Closed a connection
END RequestId: 5c6117cf-a1bc-415f-a8a4-7795997cfbd2
REPORT RequestId: 5c6117cf-a1bc-415f-a8a4-7795997cfbd2  Duration: 82.99 ms  Billed Duration: 100 ms Memory Size: 256 MB Max Memory Used: 128 MB 
START RequestId: 1cabb7bc-5a20-4afe-abcf-4f6ffe07856b Version: 66
2020-01-23T16:37:19.187Z    1cabb7bc-5a20-4afe-abcf-4f6ffe07856b    INFO    events-get-overview: runSearch: 
{
    "sql": "SELECT eventId as id, <snip>",
    "values": [
        "open"
    ],
    "timeout": 30000
}

2020-01-23T16:37:19.308Z    1cabb7bc-5a20-4afe-abcf-4f6ffe07856b    INFO    DB: Opened a new connection
END RequestId: 1cabb7bc-5a20-4afe-abcf-4f6ffe07856b
REPORT RequestId: 1cabb7bc-5a20-4afe-abcf-4f6ffe07856b  Duration: 144.38 ms Billed Duration: 200 ms Memory Size: 256 MB Max Memory Used: 129 MB 
START RequestId: f733dcf7-d665-4a05-9f2c-5011b579104a Version: 66
2020-01-23T16:40:31.914Z    f733dcf7-d665-4a05-9f2c-5011b579104a    INFO    events-get-overview: runSearch: 
{
    "sql": "SELECT eventId as id, <snip>",
    "values": [
        "open"
    ],
    "timeout": 30000
}

END RequestId: f733dcf7-d665-4a05-9f2c-5011b579104a
REPORT RequestId: f733dcf7-d665-4a05-9f2c-5011b579104a  Duration: 37.08 ms  Billed Duration: 100 ms Memory Size: 256 MB Max Memory Used: 129 MB ```

[kernwig]

Can I submit an PR to just add 'EPIPE' to tooManyConnsErrors? @jeremydaly

[kernwig]

Per here, may want to include 'ECONNRESET' as well. Most bug reports about EPIPE are people trying very large queries, so maybe that's why you didn't include it. (That scenario would fail every time.) But it also can happen when the connection is dropped by the server - due to idle or restart.

[jeremydaly]

Yes, please submit a PR.

[kernwig]

Very good. I'm testing the change in my app right now - so I'll make the PR after it proves out.

[kernwig]

PR submitted. I had an console.log on the retry when testing this so that I could see it work.

START RequestId: e3360cc5-0dd6-45b5-a764-92f5351eeb1c Version: 92
2020-02-28T17:45:45.803Z    e3360cc5-0dd6-45b5-a764-92f5351eeb1c    INFO    do query...
2020-02-28T17:45:46.100Z    e3360cc5-0dd6-45b5-a764-92f5351eeb1c    INFO    Resetting DB client due to err: EPIPE
2020-02-28T17:45:46.320Z    e3360cc5-0dd6-45b5-a764-92f5351eeb1c    INFO    DB: Opened a new connection
END RequestId: e3360cc5-0dd6-45b5-a764-92f5351eeb1c
REPORT RequestId: e3360cc5-0dd6-45b5-a764-92f5351eeb1c  Duration: 543.96 ms Billed Duration: 600 ms Memory Size: 256 MB Max Memory Used: 106 MB 

[kernwig]

PR #71 is waiting for some loving attention, @jeremydaly .

[iRoachie]

Hey, @jeremydaly are you willing to accept a PR for the ECONNRESET case?

[jeremydaly]

Of course!

[iRoachie]

@jeremydaly Opened https://github.com/jeremydaly/serverless-mysql/pull/123