Search code examples
herokuredisshopify-appshopify-api

Heroku Redis closing socket unexpectedly within shopify app

I am new to shopify api, what I have done is create node app with the following details:
shopify api V5.0.1
using redis as SessionStorage
deployed to heroku
shopify cli V2.22
Heroku Data for Redis

and here is the log from heroku using this command heroku logs -t --app<app_name_in_heroku>`

See log 
2022-08-22T02:53:05.000000+00:00 app[heroku-redis]: source=REDIS addon=redis-closed-31837 sample#active-connections=2 sample#load-avg-1m=0.395 sample#load-avg-5m=0.29 sample#load-avg-15m=0.235 sample#read-iops=0 sample#write-iops=0 sample#memory-total=16085852kB sample#memory-free=10200488kB sample#memory-cached=2958216kB sample#memory-redis=355704bytes sample#hit-rate=1 sample#evicted-keys=0
2022-08-22T02:57:43.000000+00:00 app[heroku-redis]: source=REDIS addon=redis-closed-31837 sample#active-connections=2 sample#load-avg-1m=0.315 sample#load-avg-5m=0.375 sample#load-avg-15m=0.28 sample#read-iops=0 sample#write-iops=0 sample#memory-total=16085852kB sample#memory-free=10199724kB sample#memory-cached=2958228kB sample#memory-redis=355704bytes sample#hit-rate=1 sample#evicted-keys=0
2022-08-22T02:57:43.000000+00:00 app[heroku-redis]: source=REDIS addon=redis-closed-31837 sample#active-connections=2 sample#load-avg-1m=0.155 sample#load-avg-5m=0.285 sample#load-avg-15m=0.26 sample#read-iops=0 sample#write-iops=0 sample#memory-total=16085852kB sample#memory-free=10200236kB sample#memory-cached=2958236kB sample#memory-redis=355672bytes sample#hit-rate=1 sample#evicted-keys=0
2022-08-22T02:58:36.080444+00:00 app[web.1]: node:events:491
2022-08-22T02:58:36.080453+00:00 app[web.1]: throw er; // Unhandled 'error' event
2022-08-22T02:58:36.080454+00:00 app[web.1]: ^
2022-08-22T02:58:36.080454+00:00 app[web.1]:
2022-08-22T02:58:36.080455+00:00 app[web.1]: SocketClosedUnexpectedlyError: Socket closed unexpectedly
2022-08-22T02:58:36.080456+00:00 app[web.1]: at Socket.<anonymous> (/app/node_modules/@redis/client/dist/lib/client/socket.js:156:118)
2022-08-22T02:58:36.080456+00:00 app[web.1]: at Object.onceWrapper (node:events:628:26)
2022-08-22T02:58:36.080457+00:00 app[web.1]: at Socket.emit (node:events:513:28)
2022-08-22T02:58:36.080457+00:00 app[web.1]: at TCP.<anonymous> (node:net:757:14)
2022-08-22T02:58:36.080457+00:00 app[web.1]: Emitted 'error' event on Commander instance at:
2022-08-22T02:58:36.080458+00:00 app[web.1]: at RedisSocket.<anonymous> (/app/node_modules/@redis/client/dist/lib/client/index.js:344:14)
2022-08-22T02:58:36.080458+00:00 app[web.1]: at RedisSocket.emit (node:events:513:28)
2022-08-22T02:58:36.080459+00:00 app[web.1]: at RedisSocket._RedisSocket_onSocketError (/app/node_modules/@redis/client/dist/lib/client/socket.js:179:10)
2022-08-22T02:58:36.080460+00:00 app[web.1]: at Socket.<anonymous> (/app/node_modules/@redis/client/dist/lib/client/socket.js:156:107)
2022-08-22T02:58:36.080460+00:00 app[web.1]: at Object.onceWrapper (node:events:628:26)
2022-08-22T02:58:36.080460+00:00 app[web.1]: at Socket.emit (node:events:513:28)
2022-08-22T02:58:36.080461+00:00 app[web.1]: at TCP.<anonymous> (node:net:757:14)
2022-08-22T02:58:36.080466+00:00 app[web.1]:
2022-08-22T02:58:36.080467+00:00 app[web.1]: Node.js v18.7.0
2022-08-22T02:58:36.223443+00:00 heroku[web.1]: Process exited with status 1
2022-08-22T02:58:36.431160+00:00 heroku[web.1]: State changed from up to crashed
2022-08-22T02:58:36.434346+00:00 heroku[web.1]: State changed from crashed to starting
2022-08-22T02:58:40.417402+00:00 heroku[web.1]: Starting process with command `npm start`
2022-08-22T02:58:42.045346+00:00 app[web.1]:
2022-08-22T02:58:42.045359+00:00 app[web.1]: > start
2022-08-22T02:58:42.045359+00:00 app[web.1]: > npm run serve
2022-08-22T02:58:42.045360+00:00 app[web.1]:
2022-08-22T02:58:42.360327+00:00 app[web.1]:
2022-08-22T02:58:42.360333+00:00 app[web.1]: > preserve
2022-08-22T02:58:42.360333+00:00 app[web.1]: > npm run build
2022-08-22T02:58:42.360334+00:00 app[web.1]:
2022-08-22T02:58:42.663352+00:00 app[web.1]:
2022-08-22T02:58:42.663364+00:00 app[web.1]: > build
2022-08-22T02:58:42.663366+00:00 app[web.1]: > npm run build:client
2022-08-22T02:58:42.663366+00:00 app[web.1]:
2022-08-22T02:58:42.969492+00:00 app[web.1]:
2022-08-22T02:58:42.969499+00:00 app[web.1]: > build:client
2022-08-22T02:58:42.969500+00:00 app[web.1]: > vite build --outDir dist/client
2022-08-22T02:58:42.969500+00:00 app[web.1]:
2022-08-22T02:58:43.361517+00:00 app[web.1]: vite v2.9.8 building for production...
2022-08-22T02:58:43.418520+00:00 app[web.1]: transforming...
2022-08-22T02:58:51.309037+00:00 app[web.1]: ✓ 1478 modules transformed.
2022-08-22T02:58:52.060605+00:00 app[web.1]: rendering chunks...
2022-08-22T02:58:52.068929+00:00 app[web.1]: dist/client/assets/eromman_logo.6b39893a.png   8.82 KiB
2022-08-22T02:58:52.071195+00:00 app[web.1]: dist/client/index.html                         0.29 KiB
2022-08-22T02:58:52.079983+00:00 app[web.1]: dist/client/assets/index.9ac88508.css          330.02 KiB / gzip: 38.73 KiB
2022-08-22T02:58:52.102140+00:00 app[web.1]: dist/client/assets/index.f69ec157.js           522.69 KiB / gzip: 144.56 KiB
2022-08-22T02:58:52.102350+00:00 app[web.1]:
2022-08-22T02:58:52.102350+00:00 app[web.1]: (!) Some chunks are larger than 500 KiB after minification. Consider:
2022-08-22T02:58:52.102351+00:00 app[web.1]: - Using dynamic import() to code-split the application
2022-08-22T02:58:52.102353+00:00 app[web.1]: - Use build.rollupOptions.output.manualChunks to improve chunking: https://rollupjs.org/guide/en/#outputmanualchunks
2022-08-22T02:58:52.102353+00:00 app[web.1]: - Adjust chunk size limit for this warning via build.chunkSizeWarningLimit.
2022-08-22T02:58:52.145873+00:00 app[web.1]:
2022-08-22T02:58:52.145874+00:00 app[web.1]: > serve
2022-08-22T02:58:52.145875+00:00 app[web.1]: > cross-env NODE_ENV=production node server/index.js
2022-08-22T02:58:52.145876+00:00 app[web.1]:
2022-08-22T02:58:53.208466+00:00 heroku[web.1]: State changed from starting to up
2022-08-22T03:02:17.000000+00:00 app[heroku-redis]: source=REDIS addon=redis-closed-31837 sample#active-connections=2 sample#load-avg-1m=0.155 sample#load-avg-5m=0.26 sample#load-avg-15m=0.255 sample#read-iops=0 sample#write-iops=0 sample#memory-total=16085852kB sample#memory-free=10198040kB sample#memory-cached=2958376kB sample#memory-redis=355672bytes sample#hit-rate=1 sample#evicted-keys=0
2022-08-22T03:02:17.000000+00:00 app[heroku-redis]: source=REDIS addon=redis-closed-31837 sample#active-connections=2 sample#load-avg-1m=0.31 sample#load-avg-5m=0.29 sample#load-avg-15m=0.27 sample#read-iops=0 sample#write-iops=0 sample#memory-total=16085852kB sample#memory-free=10199328kB sample#memory-cached=2958376kB sample#memory-redis=355672bytes sample#hit-rate=1 sample#evicted-keys=0
2022-08-22T03:07:14.000000+00:00 app[heroku-redis]: source=REDIS addon=redis-closed-31837 sample#active-connections=2 sample#load-avg-1m=0.175 sample#load-avg-5m=0.25 sample#load-avg-15m=0.26 sample#read-iops=0 sample#write-iops=0 sample#memory-total=16085852kB sample#memory-free=10200780kB sample#memory-cached=2958388kB sample#memory-redis=355672bytes sample#hit-rate=1 sample#evicted-keys=0
2022-08-22T03:07:14.000000+00:00 app[heroku-redis]: source=REDIS addon=redis-closed-31837 sample#active-connections=2 sample#load-avg-1m=0.1 sample#load-avg-5m=0.185 sample#load-avg-15m=0.23 sample#read-iops=0 sample#write-iops=0 sample#memory-total=16085852kB sample#memory-free=10199220kB sample#memory-cached=2958524kB sample#memory-redis=355672bytes sample#hit-rate=1 sample#evicted-keys=0
2022-08-22T03:11:57.000000+00:00 app[heroku-redis]: source=REDIS addon=redis-closed-31837 sample#active-connections=2 sample#load-avg-1m=0.085 sample#load-avg-5m=0.15 sample#load-avg-15m=0.21 sample#read-iops=0 sample#write-iops=0 sample#memory-total=16085852kB sample#memory-free=10199936kB sample#memory-cached=2958536kB sample#memory-redis=355672bytes sample#hit-rate=1 sample#evicted-keys=0
2022-08-22T03:13:53.045639+00:00 app[web.1]: node:events:491
2022-08-22T03:13:53.045648+00:00 app[web.1]: throw er; // Unhandled 'error' event
2022-08-22T03:13:53.045648+00:00 app[web.1]: ^
2022-08-22T03:13:53.045648+00:00 app[web.1]:
2022-08-22T03:13:53.045649+00:00 app[web.1]: SocketClosedUnexpectedlyError: Socket closed unexpectedly
2022-08-22T03:13:53.045650+00:00 app[web.1]: at Socket.<anonymous> (/app/node_modules/@redis/client/dist/lib/client/socket.js:156:118)
2022-08-22T03:13:53.045650+00:00 app[web.1]: at Object.onceWrapper (node:events:628:26)
2022-08-22T03:13:53.045651+00:00 app[web.1]: at Socket.emit (node:events:513:28)
2022-08-22T03:13:53.045651+00:00 app[web.1]: at TCP.<anonymous> (node:net:757:14)
2022-08-22T03:13:53.045651+00:00 app[web.1]: Emitted 'error' event on Commander instance at:
2022-08-22T03:13:53.045652+00:00 app[web.1]: at RedisSocket.<anonymous> (/app/node_modules/@redis/client/dist/lib/client/index.js:344:14)
2022-08-22T03:13:53.045652+00:00 app[web.1]: at RedisSocket.emit (node:events:513:28)
2022-08-22T03:13:53.045653+00:00 app[web.1]: at RedisSocket._RedisSocket_onSocketError (/app/node_modules/@redis/client/dist/lib/client/socket.js:179:10)
2022-08-22T03:13:53.045653+00:00 app[web.1]: at Socket.<anonymous> (/app/node_modules/@redis/client/dist/lib/client/socket.js:156:107)
2022-08-22T03:13:53.045653+00:00 app[web.1]: at Object.onceWrapper (node:events:628:26)
2022-08-22T03:13:53.045654+00:00 app[web.1]: at Socket.emit (node:events:513:28)
2022-08-22T03:13:53.045654+00:00 app[web.1]: at TCP.<anonymous> (node:net:757:14)
2022-08-22T03:13:53.045659+00:00 app[web.1]:
2022-08-22T03:13:53.045659+00:00 app[web.1]: Node.js v18.7.0
2022-08-22T03:13:53.674235+00:00 heroku[web.1]: State changed from up to crashed
2022-08-22T03:13:53.677381+00:00 heroku[web.1]: State changed from crashed to starting
2022-08-22T03:13:53.486062+00:00 heroku[web.1]: Process exited with status 1
2022-08-22T03:13:59.017503+00:00 heroku[web.1]: Starting process with command `npm start`
2022-08-22T03:14:00.918467+00:00 app[web.1]:
2022-08-22T03:14:00.918479+00:00 app[web.1]: > start
2022-08-22T03:14:00.918479+00:00 app[web.1]: > npm run serve
2022-08-22T03:14:00.918479+00:00 app[web.1]:
2022-08-22T03:14:02.061437+00:00 app[web.1]:
2022-08-22T03:14:02.061449+00:00 app[web.1]: > build:client
2022-08-22T03:14:02.061450+00:00 app[web.1]: > vite build --outDir dist/client

As you can see the error is
node:events:491
throw er; // Unhandled 'error' event
SocketClosedUnexpectedlyError: Socket closed unexpectedly

and the weired thing is heroku immediatly rebuild the app?!!! I think it should only restart. am i right?

My question is how to know the cause of this error??

how to resolve this error? Because my app got rejected in final review because of this error since shopify app send me below screenshot while the are reviewing my app

Yes heroku is displaying this error but after a while(after rebuild) the app again because accessible and works fine and after successfull installation by 1 min the error occur and heroku rebuild the app again.

Any help is appreciated and thanks in advance

Solution

  • I have found the cause of this issue:

    1. my node version in package.json was >=16.13.0 after making it 16.13.0 and deploy to heroku the app crash and rebuild after 15 minutes of the first deploy and then crash then rebuild and again after 15 minutes apps crash again. After it was crashing within the 1st minute.

    2. Again to resolve the new issue explained above I have similar issue in redis node repo, saying that i have to extend client-output-buffer-limit and maxmemory while in heroku free plan for redis you can't access redis CONFIG command at all. So, I have found another alternative which is using free plan of RedisLabs and the issue of crashing is resolved and my app is working fine now.