bnusunny
commented
10 months ago I haven't seen such an issue. Do you have the logs around that error? Does it happen at cold start or after it already served some requests?
Closed akadori closed 10 months ago
bnusunny
commented
10 months ago I haven't seen such an issue. Do you have the logs around that error? Does it happen at cold start or after it already served some requests?
akadori
commented
10 months ago The CloudWatch logs during the error occurrence look something like this. From what I can see, the log stream appears to begin with the error. Also, when an INIT_REPORT is output, there are messages that indicate that INITIALIZE has started again.
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| timestamp | message |
|---------------|---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
| 1702763408597 | Error: listen EADDRINUSE: address already in use 0.0.0.0:58000 |
| 1702763408597 | at __node_internal_captureLargerStackTrace (node:internal/errors:490:5) |
| 1702763408597 | at __node_internal_uvExceptionWithHostPort (node:internal/errors:589:12) |
| 1702763408597 | at Server.setupListenHandle [as _listen2] (node:net:1740:16) |
| 1702763408597 | at listenInCluster (node:net:1788:12) |
| 1702763408597 | at Server.listen (node:net:1876:7) |
| 1702763408597 | at Function.listen (/node_modules/express/lib/application.js:635:24) |
| 1702763408597 | at <anonymous> (/var/src/index.ts:9:22) |
| 1702763408597 | at process.processTicksAndRejections (node:internal/process/task_queues:95:5) |
| 1702763408647 | EXTENSION Name: cloudwatch_lambda_agent State: Ready Events: [INVOKE, SHUTDOWN] |
| 1702763408647 | EXTENSION Name: lambda-adapter State: Ready Events: [] |
| 1702763408647 | INIT_REPORT Init Duration: 5038.94 ms Phase: init Status: error Error Type: Runtime.ExitError |
| 1702763473309 | LOGS Name: cloudwatch_lambda_agent State: Already subscribed Types: [Platform] |
| 1702763476546 | initializing... |
| 1702763476824 | Configuration Info: Enable error tracking with Sentry |Regarding whether it happens at cold start or after it has already served some requests, the error seems to occur during a cold start since an INIT FAIL is recorded.
bnusunny
commented
10 months ago Are there more logs before this error in the same log stream? Lambda might restart the runtime if it times out or crashes, and you can see init logs as well.
akadori
commented
10 months ago Oh, I apologize, when I said earlier that all the log streams with errors started with an error message, I was mistaken.
Below, I am pasting the log streams where the errors occurred (this is different from the one I pasted before):
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| timestamp |
|---------------|-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
| 1702842946156 | LOGS Name: cloudwatch_lambda_agent State: Subscribed Types: [Platform]
| 1702842948576 | initializing...
| 1702842948720 | Configuration Info: Enable error tracking with Sentry
| 1702842948723 | initialized. setSettingsTime: 1.0258450000546873ms, setDbUrlTime: 143.00228100002278ms
| 1702842950256 | 2023-12-17T19:55:50.256Z backend:launch Configuration Info: Enable error tracking with Sentry
| 1702842950257 | 2023-12-17T19:55:50.257Z backend:launch app creating...
| 1702842950257 | 2023-12-17T19:55:50.257Z backend:launch Configuration Info: DB connecting...
| 1702842950265 | 2023-12-17T19:55:50.257Z backend:launch Connection has NOT established and try to connect
| 1702842950316 | query: SELECT * FROM current_schema()
| 1702842950337 | query: CREATE EXTENSION IF NOT EXISTS "uuid-ossp"
| 1702842950344 | query: SELECT version();
| 1702842950352 | 2023-12-17T19:55:50.352Z backend:launch Configuration Info: DB connected.
| 1702842950473 | Sun, 17 Dec 2023 19:55:50 GMT express:application set "x-powered-by" to true
| 1702842950473 | Sun, 17 Dec 2023 19:55:50 GMT express:application set "etag" to 'weak'
| 1702842950474 | Sun, 17 Dec 2023 19:55:50 GMT express:application set "etag fn" to [Function: generateETag]
| 1702842950474 | Sun, 17 Dec 2023 19:55:50 GMT express:application set "env" to 'production'
| 1702842950474 | Sun, 17 Dec 2023 19:55:50 GMT express:application set "query parser" to 'extended'
| 1702842950475 | Sun, 17 Dec 2023 19:55:50 GMT express:application set "query parser fn" to [Function: parseExtendedQueryString]
| 1702842950475 | Sun, 17 Dec 2023 19:55:50 GMT express:application set "subdomain offset" to 2
| 1702842950475 | Sun, 17 Dec 2023 19:55:50 GMT express:application set "trust proxy" to false
| 1702842950475 | Sun, 17 Dec 2023 19:55:50 GMT express:application set "trust proxy fn" to [Function: trustNone]
| 1702842950475 | Sun, 17 Dec 2023 19:55:50 GMT express:application booting in production mode
| 1702842950475 | Sun, 17 Dec 2023 19:55:50 GMT express:application set "view" to [Function: View]
| 1702842950475 | Sun, 17 Dec 2023 19:55:50 GMT express:application set "views" to '/var/task/views'
| 1702842950475 | Sun, 17 Dec 2023 19:55:50 GMT express:application set "jsonp callback name" to 'callback'
| 1702842950475 | Sun, 17 Dec 2023 19:55:50 GMT express:application set "view cache" to true
| 1702842950475 | Sun, 17 Dec 2023 19:55:50 GMT express:application set "x-powerd-by" to false
| 1702842950475 | Sun, 17 Dec 2023 19:55:50 GMT express:application set "trust proxy" to true
| 1702842950476 | Sun, 17 Dec 2023 19:55:50 GMT express:application set "trust proxy fn" to [Function (anonymous)]
| 1702842950476 | Sun, 17 Dec 2023 19:55:50 GMT express:router use '/' query2
| 1702842950476 | Sun, 17 Dec 2023 19:55:50 GMT express:router:layer new '/'
| 1702842950477 | Sun, 17 Dec 2023 19:55:50 GMT express:router use '/' expressInit
| 1702842950477 | Sun, 17 Dec 2023 19:55:50 GMT express:router:layer new '/'
| 1702842950477 | Sun, 17 Dec 2023 19:55:50 GMT express:router use '/' <anonymous>
| 1702842950477 | Sun, 17 Dec 2023 19:55:50 GMT express:router:layer new '/'
| 1702842950478 | Sun, 17 Dec 2023 19:55:50 GMT express:router use '/.well-known/apollo/server-health' <anonymous>
| 1702842950478 | Sun, 17 Dec 2023 19:55:50 GMT express:router:layer new '/.well-known/apollo/server-health'
| 1702842950478 | Sun, 17 Dec 2023 19:55:50 GMT express:router use '/graphql' corsMiddleware
| 1702842950478 | Sun, 17 Dec 2023 19:55:50 GMT express:router:layer new '/graphql'
| 1702842950479 | Sun, 17 Dec 2023 19:55:50 GMT express:router use '/graphql' jsonParser
| 1702842950479 | Sun, 17 Dec 2023 19:55:50 GMT express:router:layer new '/graphql'
| 1702842950479 | Sun, 17 Dec 2023 19:55:50 GMT express:router use '/graphql' <anonymous>
| 1702842950479 | Sun, 17 Dec 2023 19:55:50 GMT express:router:layer new '/graphql'
| 1702842950479 | Sun, 17 Dec 2023 19:55:50 GMT express:router use '/graphql' <anonymous>
| 1702842950479 | Sun, 17 Dec 2023 19:55:50 GMT express:router:layer new '/graphql'
| 1702842950479 | Sun, 17 Dec 2023 19:55:50 GMT express:router use '/' router
| 1702842950479 | Sun, 17 Dec 2023 19:55:50 GMT express:router:layer new '/'
| 1702842950480 | Sun, 17 Dec 2023 19:55:50 GMT express:router:route new '/health'
| 1702842950480 | Sun, 17 Dec 2023 19:55:50 GMT express:router:layer new '/health'
| 1702842950480 | Sun, 17 Dec 2023 19:55:50 GMT express:router:route get '/health'
| 1702842950480 | Sun, 17 Dec 2023 19:55:50 GMT express:router:layer new '/'
| 1702842950480 | 2023-12-17T19:55:50.480Z backend:launch app created
| 1702842950482 | 2023-12-17T19:55:50.482Z backend:launch Configuration Info: Server listening on 58000
| 1702842951194 | Error: listen EADDRINUSE: address already in use 0.0.0.0:58000
| 1702842951194 | at __node_internal_captureLargerStackTrace (node:internal/errors:490:5)
| 1702842951194 | at __node_internal_uvExceptionWithHostPort (node:internal/errors:589:12)
| 1702842951194 | at Server.setupListenHandle [as _listen2] (node:net:1740:16)
| 1702842951194 | at listenInCluster (node:net:1788:12)
| 1702842951194 | at Server.listen (node:net:1876:7)
| 1702842951194 | at Function.listen (/node_modules/express/lib/application.js:635:24)
| 1702842951194 | at <anonymous> (/var/src/index.ts:9:22)
| 1702842951194 | at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
| 1702842951238 | EXTENSION Name: cloudwatch_lambda_agent State: Ready Events: [INVOKE, SHUTDOWN]
| 1702842951238 | EXTENSION Name: lambda-adapter State: Ready Events: []
| 1702842951238 | INIT_REPORT Init Duration: 5123.87 ms Phase: init Status: error Error Type: Runtime.ExitError
| 1702843008312 | LOGS Name: cloudwatch_lambda_agent State: Already subscribed Types: [Platform]
| 1702843011680 | initializing...
| 1702843011869 | Configuration Info: Enable error tracking with Sentry
| 1702843011872 | initialized. setSettingsTime: 0.9989269999787211ms, setDbUrlTime: 188.39021199999843ms
| 1702843014515 | 2023-12-17T19:56:54.515Z backend:launch Configuration Info: Enable error tracking with Sentry
| 1702843014517 | 2023-12-17T19:56:54.517Z backend:launch app creating...
| 1702843014518 | 2023-12-17T19:56:54.517Z backend:launch Configuration Info: DB connecting...
| 1702843014518 | 2023-12-17T19:56:54.518Z backend:launch Connection has NOT established and try to connect
| 1702843014633 | query: SELECT * FROM current_schema()
| 1702843014713 | query: CREATE EXTENSION IF NOT EXISTS "uuid-ossp"
| 1702843014723 | query: SELECT version();
| 1702843014729 | 2023-12-17T19:56:54.729Z backend:launch Configuration Info: DB connected.
| 1702843014833 | Sun, 17 Dec 2023 19:56:54 GMT express:application set "x-powered-by" to true
| 1702843014833 | Sun, 17 Dec 2023 19:56:54 GMT express:application set "etag" to 'weak'
| 1702843014834 | Sun, 17 Dec 2023 19:56:54 GMT express:application set "etag fn" to [Function: generateETag]
| 1702843014834 | Sun, 17 Dec 2023 19:56:54 GMT express:application set "env" to 'production'
| 1702843014834 | Sun, 17 Dec 2023 19:56:54 GMT express:application set "query parser" to 'extended'
| 1702843014834 | Sun, 17 Dec 2023 19:56:54 GMT express:application set "query parser fn" to [Function: parseExtendedQueryString]
| 1702843014835 | Sun, 17 Dec 2023 19:56:54 GMT express:application set "subdomain offset" to 2
| 1702843014835 | Sun, 17 Dec 2023 19:56:54 GMT express:application set "trust proxy" to false
| 1702843014835 | Sun, 17 Dec 2023 19:56:54 GMT express:application set "trust proxy fn" to [Function: trustNone]
| 1702843014835 | Sun, 17 Dec 2023 19:56:54 GMT express:application booting in production mode
| 1702843014835 | Sun, 17 Dec 2023 19:56:54 GMT express:application set "view" to [Function: View]
| 1702843014835 | Sun, 17 Dec 2023 19:56:54 GMT express:application set "views" to '/var/task/views'
| 1702843014835 | Sun, 17 Dec 2023 19:56:54 GMT express:application set "jsonp callback name" to 'callback'
| 1702843014835 | Sun, 17 Dec 2023 19:56:54 GMT express:application set "view cache" to true
| 1702843014835 | Sun, 17 Dec 2023 19:56:54 GMT express:application set "x-powerd-by" to false
| 1702843014835 | Sun, 17 Dec 2023 19:56:54 GMT express:application set "trust proxy" to true
| 1702843014835 | Sun, 17 Dec 2023 19:56:54 GMT express:application set "trust proxy fn" to [Function (anonymous)]
| 1702843014836 | Sun, 17 Dec 2023 19:56:54 GMT express:router use '/' query2
| 1702843014836 | Sun, 17 Dec 2023 19:56:54 GMT express:router:layer new '/'
| 1702843014836 | Sun, 17 Dec 2023 19:56:54 GMT express:router use '/' expressInit
| 1702843014836 | Sun, 17 Dec 2023 19:56:54 GMT express:router:layer new '/'
| 1702843014837 | Sun, 17 Dec 2023 19:56:54 GMT express:router use '/' <anonymous>
| 1702843014837 | Sun, 17 Dec 2023 19:56:54 GMT express:router:layer new '/'
| 1702843014837 | Sun, 17 Dec 2023 19:56:54 GMT express:router use '/.well-known/apollo/server-health' <anonymous>
| 1702843014837 | Sun, 17 Dec 2023 19:56:54 GMT express:router:layer new '/.well-known/apollo/server-health'
| 1702843014838 | Sun, 17 Dec 2023 19:56:54 GMT express:router use '/graphql' corsMiddleware
| 1702843014838 | Sun, 17 Dec 2023 19:56:54 GMT express:router:layer new '/graphql'
| 1702843014851 | Sun, 17 Dec 2023 19:56:54 GMT express:router use '/graphql' jsonParser
| 1702843014851 | Sun, 17 Dec 2023 19:56:54 GMT express:router:layer new '/graphql'
| 1702843014851 | Sun, 17 Dec 2023 19:56:54 GMT express:router use '/graphql' <anonymous>
| 1702843014851 | Sun, 17 Dec 2023 19:56:54 GMT express:router:layer new '/graphql'
| 1702843014851 | Sun, 17 Dec 2023 19:56:54 GMT express:router use '/graphql' <anonymous>
| 1702843014851 | Sun, 17 Dec 2023 19:56:54 GMT express:router:layer new '/graphql'
| 1702843014851 | Sun, 17 Dec 2023 19:56:54 GMT express:router use '/' router
| 1702843014851 | Sun, 17 Dec 2023 19:56:54 GMT express:router:layer new '/'
| 1702843014852 | Sun, 17 Dec 2023 19:56:54 GMT express:router:route new '/health'
| 1702843014852 | Sun, 17 Dec 2023 19:56:54 GMT express:router:layer new '/health'
| 1702843014852 | Sun, 17 Dec 2023 19:56:54 GMT express:router:route get '/health'
| 1702843014852 | Sun, 17 Dec 2023 19:56:54 GMT express:router:layer new '/'
| 1702843014852 | 2023-12-17T19:56:54.852Z backend:launch app created
| 1702843014854 | 2023-12-17T19:56:54.854Z backend:launch Configuration Info: Server listening on 58000
| 1702843014874 | Sun, 17 Dec 2023 19:56:54 GMT express:router dispatching GET /
| 1702843014874 | Sun, 17 Dec 2023 19:56:54 GMT express:router query2 : /
| 1702843014875 | Sun, 17 Dec 2023 19:56:54 GMT express:router expressInit : /
| 1702843014875 | Sun, 17 Dec 2023 19:56:54 GMT express:router <anonymous> : /
| 1702843014876 | 2023-12-17T19:56:54.876Z backend:verbose:request {
The message at 1702842948723 indicates that the retrieval of values from Secrets Manager has completed. From 1702842950257 to 1702842950352, a connection with the database is being established (via RDS Proxy). Starting at 1702843011680, the server is attempting to retry initialization. At 1702843014854, the server successfully started up, and since then, it has been handling requests.
sladg
commented
10 months ago @akadori could you try more widely used port such as 3000 or 8080 to run your express app? Would it throw same error?
PS. I was facing problem with INIT timeouts as app wasn't found even tho it was returning data correctly. So I forked it to more bare-bone version, might come handy.
bnusunny
commented
10 months ago @akadori From these two lines of logs, it seems the server was already listening on 58000 at 1702842950482, and it tried to re-binding to port 58000 again at 1702842951194. Could you enable debug level logging to see what happens between these two logs?
| 1702842950482 | 2023-12-17T19:55:50.482Z backend:launch Configuration Info: Server listening on 58000
| 1702842951194 | Error: listen EADDRINUSE: address already in use 0.0.0.0:58000@bnusunny I'm sorry, but the logs from that time are not available. The reason why you might have sensed something odd in the sequence here is that the code contained an error like the one shown below.
getServer()
.then((app) => app.listen(PORT))
.then(() => {
launchLogger(`Configuration Info: Server listening on ${PORT}`);
}) // app.listen does not return a promise
.catch(async (e) => {
await fatalLogger(e);
process.exit(1);
});I have corrected this. However, since the issue originally occurred only occasionally, I have not been able to verify whether this correction has resolved it. Also, it does not seem to me that this was the cause of the issue.
Since it seems difficult to pinpoint the cause, I am considering using either server-express or Fargate. Thank you for your cooperation.
bnusunny
commented
10 months ago No problem. Thanks for testing out LWA.
I am using AWS Lambda Web Adapter and Express.js, with Express configured to listen on port 58000. It generally operates correctly, but sometimes it encounters an error saying "listen EADDRINUSE: address already in use 0.0.0.0:58000".
It seems that this issue might be related to an instance where another server process is attempting to bind to the same port that is already in use. What could be the scenarios leading to this conflict?