Site crashed after sending source files to ftp, when waiting for converted file
Current behaviour
Site crashed when tried to send files to ftp. (through submit), because of temporarily connection issue with the ftp server. In this case the connection is lost when the BCMS is waiting to receive the converted file, after successful source file submission.
Logs
We need to handle this error and prevent server going down. Here are the logs of this :
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: 2023-08-22T07:02:07.071Z - error:
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: {
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: message: 'Client is closed',
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: stack: 'Error: Client is closed\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at /home/node/app/node_modules/basic-ftp/dist/FtpContext.js:227:29\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at new Promise (<anonymous>)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at FTPContext.handle (/home/node/app/node_modules/basic-ftp/dist/FtpContext.js:207:16)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at Object.uploadFrom (/home/node/app/node_modules/basic-ftp/dist/transfer.js:201:23)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at Client._uploadFromStream (/home/node/app/node_modules/basic-ftp/dist/Client.js:392:37)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async NcbiAdapter.send (/home/node/app/server/services/ftp/ftp.js:23:14)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async Object.value (/home/node/app/server/services/ncbiConnectionManager/ncbiService.js:24:16)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async WorkUnit.execute (/home/node/app/server/services/ncbiConnectionManager/WorkUnit.js:27:27)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async WorkUnit.execute (/home/node/app/server/services/ncbiConnectionManager/WorkUnit.js:39:16)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async WorkUnit.execute (/home/node/app/server/services/ncbiConnectionManager/WorkUnit.js:39:16)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async WorkUnit.execute (/home/node/app/server/services/ncbiConnectionManager/WorkUnit.js:39:16)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async NcbiService.send (/home/node/app/server/services/ncbiConnectionManager/ncbiService.js:28:12)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async Function.sendForConversion (/home/node/app/server/services/ncbiConnectionManager/packageCollection.js:58:9)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async IngestToPMC.run (/home/node/app/server/services/CommandService/chapterCommands/commands/ingestToPMC.js:115:15)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async Chapter.executeCommand (/home/node/app/server/services/CommandService/baseCommand.js:30:18)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async /home/node/app/server/services/events/listeners/CreatePreview.js:33:37\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: "Closing reason: Error: User launched a task while another one is still running. Forgot to use 'await' or '.then()'?\n" +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at FTPContext.handle (/home/node/app/node_modules/basic-ftp/dist/FtpContext.js:200:25)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at Object.uploadFrom (/home/node/app/node_modules/basic-ftp/dist/transfer.js:201:23)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at Client._uploadFromStream (/home/node/app/node_modules/basic-ftp/dist/Client.js:392:37)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async NcbiAdapter.send (/home/node/app/server/services/ftp/ftp.js:23:14)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async Object.value (/home/node/app/server/services/ncbiConnectionManager/ncbiService.js:24:16)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async WorkUnit.execute (/home/node/app/server/services/ncbiConnectionManager/WorkUnit.js:27:27)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async WorkUnit.execute (/home/node/app/server/services/ncbiConnectionManager/WorkUnit.js:39:16)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async WorkUnit.execute (/home/node/app/server/services/ncbiConnectionManager/WorkUnit.js:39:16)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async WorkUnit.execute (/home/node/app/server/services/ncbiConnectionManager/WorkUnit.js:39:16)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async NcbiService.send (/home/node/app/server/services/ncbiConnectionManager/ncbiService.js:28:12)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async Function.sendForConversion (/home/node/app/server/services/ncbiConnectionManager/packageCollection.js:58:9)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async IngestToPMC.run (/home/node/app/server/services/CommandService/chapterCommands/commands/ingestToPMC.js:115:15)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async Chapter.executeCommand (/home/node/app/server/services/CommandService/baseCommand.js:30:18)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async /home/node/app/server/services/events/listeners/CreatePreview.js:33:37\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async /home/node/app/server/services/events/listeners/CreatePreview.js:33:37\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: 'Running task launched at: Error\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at /home/node/app/node_modules/basic-ftp/dist/FtpContext.js:208:27\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at new Promise (<anonymous>)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at FTPContext.handle (/home/node/app/node_modules/basic-ftp/dist/FtpContext.js:207:16)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at FTPContext.request (/home/node/app/node_modules/basic-ftp/dist/FtpContext.js:184:21)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at enterPassiveModeIPv6 (/home/node/app/node_modules/basic-ftp/dist/transfer.js:11:27)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at Client.prepareTransfer (/home/node/app/node_modules/basic-ftp/dist/Client.js:690:39)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at Client._uploadFromStream (/home/node/app/node_modules/basic-ftp/dist/Client.js:389:24)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at runMicrotasks (<anonymous>)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at processTicksAndRejections (node:internal/process/task_queues:96:5)',
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: code: '0'
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: }
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: 2023-08-22T07:02:07.073Z - error:
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: {
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: message: 'None of the available transfer modes work.',
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: stack: 'Error: None of the available transfer modes work.\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at Client.<anonymous> (/home/node/app/node_modules/basic-ftp/dist/Client.js:701:19)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async Client._uploadFromStream (/home/node/app/node_modules/basic-ftp/dist/Client.js:389:13)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async NcbiAdapter.send (/home/node/app/server/services/ftp/ftp.js:23:14)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async Object.value (/home/node/app/server/services/ncbiConnectionManager/ncbiService.js:24:16)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async WorkUnit.execute (/home/node/app/server/services/ncbiConnectionManager/WorkUnit.js:27:27)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async WorkUnit.execute (/home/node/app/server/services/ncbiConnectionManager/WorkUnit.js:39:16)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async WorkUnit.execute (/home/node/app/server/services/ncbiConnectionManager/WorkUnit.js:39:16)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async WorkUnit.execute (/home/node/app/server/services/ncbiConnectionManager/WorkUnit.js:39:16)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async NcbiService.send (/home/node/app/server/services/ncbiConnectionManager/ncbiService.js:28:12)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at runMicrotasks (<anonymous>)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at processTicksAndRejections (node:internal/process/task_queues:96:5)',
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: code: '0'
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: }
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: 2023-08-22T07:02:07.073Z - error:
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: {
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: message: 'None of the available transfer modes work.',
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: stack: 'Error: None of the available transfer modes work.\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at Client.<anonymous> (/home/node/app/node_modules/basic-ftp/dist/Client.js:701:19)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async Client._uploadFromStream (/home/node/app/node_modules/basic-ftp/dist/Client.js:389:13)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async NcbiAdapter.send (/home/node/app/server/services/ftp/ftp.js:23:14)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async Object.value (/home/node/app/server/services/ncbiConnectionManager/ncbiService.js:24:16)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async WorkUnit.execute (/home/node/app/server/services/ncbiConnectionManager/WorkUnit.js:27:27)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async WorkUnit.execute (/home/node/app/server/services/ncbiConnectionManager/WorkUnit.js:39:16)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async WorkUnit.execute (/home/node/app/server/services/ncbiConnectionManager/WorkUnit.js:39:16)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async WorkUnit.execute (/home/node/app/server/services/ncbiConnectionManager/WorkUnit.js:39:16)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async NcbiService.send (/home/node/app/server/services/ncbiConnectionManager/ncbiService.js:28:12)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async Function.sendForConversion (/home/node/app/server/services/ncbiConnectionManager/packageCollection.js:58:9)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async IngestToPMC.run (/home/node/app/server/services/CommandService/chapterCommands/commands/ingestToPMC.js:115:15)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async Chapter.executeCommand (/home/node/app/server/services/CommandService/baseCommand.js:30:18)\n' +
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at async /home/node/app/server/services/events/listeners/CreatePreview.js:33:37'
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: }
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: 2023-08-22T07:02:07.074Z - error: There was an error sending files to ncbi : Error: Max connection retries reached : 3 times
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: 2023-08-22T07:02:07.074Z - error:
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: {
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: message: 'There was an error sending files to ncbi : Error: Max connection retries reached : 3 times',
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: name: 'NCBIError'
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: }
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: 2023-08-22T07:02:07.074Z - error: There was an error sending files to ncbi : Error: Max connection retries reached : 3 times
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: 2023-08-22T07:02:07.074Z - error:
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: {
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: message: 'There was an error sending files to ncbi : Error: Max connection retries reached : 3 times',
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: name: 'NCBIError'
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: }
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: 2023-08-22T07:02:07.100Z - error: uncaughtException: Running command: Chapter/Book Ingest To PMC Command Failed. Message:
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: {
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: date: 'Tue Aug 22 2023 07:02:07 GMT+0000 (Coordinated Universal Time)',
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: process: {
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: pid: 1,
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: uid: 1000,
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: gid: 1000,
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: cwd: '/home/node/app',
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: execPath: '/usr/local/bin/node',
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: version: 'v16.14.2',
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: argv: [ '/usr/local/bin/node', '/home/node/app/startServer.js' ],
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: memoryUsage: {
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: rss: 111972352,
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: heapTotal: 73945088,
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: heapUsed: 64523968,
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: external: 1887098,
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: arrayBuffers: 391308
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: }
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: },
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: os: { loadavg: [ 0, 0.02, 0 ], uptime: 52590903.85 },
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: trace: [
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: {
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: column: 15,
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: file: '/home/node/app/server/services/CommandService/baseCommand.js',
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: function: 'Chapter.executeCommand',
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: line: 36,
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: method: 'executeCommand',
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: native: false
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: },
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: {
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: column: 37,
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: file: 'async /home/node/app/server/services/events/listeners/CreatePreview.js',
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: function: null,
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: line: 33,
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: method: null,
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: native: false
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: }
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ],
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: stack: [
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: 'Error: Running command: Chapter/Book Ingest To PMC Command Failed. Message: ',
Aug 22 09:02:07 ncbidev-coko d630ad819d72[1204]: ' at Chapter.executeCommand (/home/node/app/server/services/CommandService/baseCommand.js:36:15)',
Steps to produce:
- User uploads chapter or book source files
- The user sees the files submit and status change to "converting" (BCMS has successfully submitted the files)
- After a while the user experiences site crash because the a connection to the FTP cannot be estabilished. Because many actions could have according between submitting the files and the site crashing, it may not be apparent to the user that these two actions are related.
In order to reproduce this we could change the ftp credentials to something wrong. In that way the ftp send files will fail and will throw an error.
Solution
- On the backend, We will need to handle that error . here :
server/services/events/listeners/CreatePreview.js
at line 33 . You can check the error logs.
- On the frontend, refer to related issue [pending]
Acceptance Criteria
-
The site does not crash according to logs and user experience -
The logs continue to report FTP connection issue events