Timeout appending / reading larger files

[Steve-Mcl]

Current Behavior

Large appends to large files can result in the error "failed to append to file: Error: Timeout awaiting 'request' for 3000ms"

Reading back large files can also timeout

Expected Behavior

So long as the append is within the fastify POST limits and the resulting file store size is < quota limit, the timeout should not occur.

Consideration should be made to the length of time the s3 storage takes. For example, we could simply max out the request timeout but users would start experiencing long delays between file operations and the flow continuing.

One possible interim (containement) option might be to add an explicit "timeout" setting on the FF NR File-node config that permits the user to see (and adjust) this if they encounter timeouts. Not ideal, but the presence of the timeout option would go some way (implicitly) to explain what can be done about any incurred timeouts

Other far reaching possibilities include:

• employing something other than the s3 backend - is it just too slow for purpose? is it our code?
• add performance logging in the areas of code to determine where the bottle necks are?
• use alternative transport?

Steps To Reproduce

1. Add the (below) flow to a cloud instance
2. Operate the 5MB button and wait for the debug message
3. Repeat step 2 8 times until the file is 40MB
   1. Note how with each operation the time to perform the 5MB append increases.
4. Wait 1 minute
5. Operate the Read inject
   1. Should get a timeout, if not, try adding some more 5MB parts (step 2)

[{"id":"9a693308.7ebaf","type":"subflow","name":"flow-timer","info":"","category":"","in":[{"x":80,"y":100,"wires":[{"id":"7fc82258.93e36c"}]}],"out":[{"x":580,"y":80,"wires":[{"id":"cebf40311504c8e9","port":0}]}],"env":[{"name":"name","type":"str","value":"measure","ui":{"icon":"font-awesome/fa-tag","label":{"en-US":"Timer Name"},"type":"input","opts":{"types":["str","env"]}}},{"name":"operation","type":"str","value":"start","ui":{"icon":"font-awesome/fa-cog","label":{"en-US":"Operation"},"type":"select","opts":{"opts":[{"l":{"en-US":"start"},"v":"start"},{"l":{"en-US":"stop"},"v":"stop"},{"l":{"en-US":"msg.topic"},"v":"msg.topic"},{"l":{"en-US":"msg.operation"},"v":"msg.operation"},{"l":{"en-US":"msg.payload"},"v":"msg.payload"}]}}},{"name":"delay","type":"num","value":"500","ui":{"icon":"font-awesome/fa-clock-o","label":{"en-US":"Delay (ms)"},"type":"input","opts":{"types":["num","env"]}}}],"meta":{"module":"node-red-contrib-flow-performance","type":"flow-performance","version":"1.0.2","author":"Steve-Mcl","desc":"Inline flow performance measure node","keywords":"node-red performance","license":"MIT"},"color":"#DAEAAA","icon":"node-red/timer.svg","status":{"x":580,"y":160,"wires":[{"id":"7fc82258.93e36c","port":1}]}},{"id":"7fc82258.93e36c","type":"function","z":"9a693308.7ebaf","name":"do operation","func":"var name = msg.perfName || env.get(\"name\");\nvar operation = msg.perfOperation || env.get(\"operation\");\nvar delay = env.get(\"delay\") || 500;\nvar measures = global.get(\"flow_timers\") || {};\nvar measure = measures[name] || { count: 0, stopNode: null, startNode: null};\n\nfunction doOp(measure, op){\n    if(op === \"start\"){\n        measure.start = Date.now();//change to process.hrtime\n        measure.stop = null;\n        measure.durationMs = null;\n        measure.stopNode && measure.stopNode.send([null, { payload: {text: 'waiting...'} }]);\n    } else if(op === \"stop\") {\n        if (typeof measure.count !== 'number' || isNaN(measure.count) || measure.count < 0) {\n            measure.count = 0\n        }\n        measure.startNode && measure.startNode.send([null, { payload: { text: '' } }]);\n        measure.count++\n        measure.stop = Date.now();//change to process.hrtime\n        measure.durationMs = measure.start ? measure.stop - measure.start : null;\n        msg._performance = measure;\n    }\n}\n\n\nif(operation === \"start\"){\n    measure.startNode = node\n    const opt = {\n        hour: \"2-digit\",\n        minute: \"2-digit\",\n        second: \"2-digit\",\n        fractionalSecondDigits: 3,\n        hour12: false\n    }\n    const tn = (new Date()).toLocaleTimeString('en-GB', opt)\n    node.send([null, { payload: { text: `Started '${name}' @ ${tn}` } }]);\n    doOp(measure, operation);\n} else if(operation === \"stop\") {\n    measure.stopNode = node\n    doOp(measure, operation);\n    node.send([null, { payload: { text: name + \": \" + measure.durationMs + \"ms (count:\" + measure.count + \")\" }}]);\n} else if(operation === \"msg.topic\") {\n    operation = msg.topic;\n    doOp(measure, operation);\n} else if(operation === \"msg.operation\") {\n    operation = msg.operation;\n    doOp(measure, operation);\n} else if(operation === \"msg.payload\") {\n    operation = msg.payload;\n    doOp(measure, operation);\n} else {\n    return [msg, null];\n}\nmeasures[name] = measure;\nglobal.set(\"flow_timers\", measures);\n\nif (typeof delay === 'number' && delay > 0) {\n    setTimeout(function() {\n        measure.start = Date.now();//change to process.hrtime\n        node.send([msg, null])\n    }, delay);\n} else {\n    node.send([msg, null])\n}\n\n","outputs":2,"noerr":0,"initialize":"","finalize":"// Code added here will be run when the\n// node is being stopped or re-deployed.\nvar name = env.get(\"name\");\nvar measures = global.get(\"flow_timers\") || {};\ndelete measures[name]\n","libs":[],"x":250,"y":100,"wires":[["cebf40311504c8e9"],[]]},{"id":"cebf40311504c8e9","type":"delay","z":"9a693308.7ebaf","name":"","pauseType":"delay","timeout":"1","timeoutUnits":"milliseconds","rate":"1","nbRateUnits":"1","rateUnits":"second","randomFirst":"1","randomLast":"5","randomUnits":"seconds","drop":false,"allowrate":false,"outputs":1,"x":450,"y":80,"wires":[[]]},{"id":"15e1f637b990a5a1","type":"inject","z":"fa67325bf79a710f","name":"1MB","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"1","payload":"1 * 1024 * 1024","payloadType":"jsonata","x":1490,"y":200,"wires":[["85a18fa8a1d74d63"]]},{"id":"1b1cde87d26522bf","type":"file","z":"fa67325bf79a710f","name":"append","filename":"test.txt","filenameType":"str","appendNewline":true,"createDir":false,"overwriteFile":"false","encoding":"none","x":1840,"y":340,"wires":[["8b10773458448208"]]},{"id":"85a18fa8a1d74d63","type":"function","z":"fa67325bf79a710f","name":"make big data","func":"const length = msg.payload || (1 * 1024 * 1024)\nconst letter = msg.topic?.substr(0,1) || \"A\"\nconst data = Array(length).join(letter)\nmsg.payload = data\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":1720,"y":260,"wires":[["20c687d953fe54ed"]]},{"id":"e4f8ae2f0f1a3f23","type":"inject","z":"fa67325bf79a710f","name":"2MB","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"2","payload":"2 * 1024 * 1024","payloadType":"jsonata","x":1490,"y":240,"wires":[["85a18fa8a1d74d63"]]},{"id":"c7afed29f8f5aba1","type":"inject","z":"fa67325bf79a710f","name":"5MB","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"5","payload":"5 * 1024 * 1024","payloadType":"jsonata","x":1490,"y":280,"wires":[["85a18fa8a1d74d63"]]},{"id":"c06c923f42248749","type":"inject","z":"fa67325bf79a710f","name":"10MB","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"A","payload":"10 * 1024 * 1024","payloadType":"jsonata","x":1490,"y":400,"wires":[["85a18fa8a1d74d63"]]},{"id":"0265795fffb08502","type":"inject","z":"fa67325bf79a710f","name":"10MB + 1","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"a","payload":"(10 * 1024 * 1024) + 1","payloadType":"jsonata","x":1500,"y":440,"wires":[["85a18fa8a1d74d63"]]},{"id":"5124707ad3f0da7f","type":"file in","z":"fa67325bf79a710f","name":"single string","filename":"test.txt","filenameType":"str","format":"utf8","chunk":false,"sendError":false,"encoding":"none","allProps":false,"x":1850,"y":480,"wires":[["dac3309da8ca4609"]]},{"id":"99339a63cc4988dc","type":"debug","z":"fa67325bf79a710f","name":"payload.length","active":true,"tosidebar":true,"console":false,"tostatus":true,"complete":"payload.length","targetType":"msg","statusVal":"payload.length","statusType":"msg","x":2220,"y":480,"wires":[]},{"id":"0e65bd9ddbd0af18","type":"inject","z":"fa67325bf79a710f","name":"7MB","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"5","payload":"7 * 1024 * 1024","payloadType":"jsonata","x":1490,"y":360,"wires":[["85a18fa8a1d74d63"]]},{"id":"5cb0754041dfdf2c","type":"inject","z":"fa67325bf79a710f","name":"clear","props":[{"p":"payload.length","v":"0","vt":"num"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","x":2190,"y":440,"wires":[["99339a63cc4988dc"]]},{"id":"b451f5fd3456a307","type":"inject","z":"fa67325bf79a710f","name":"6MB","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"6","payload":"6 * 1024 * 1024","payloadType":"jsonata","x":1490,"y":320,"wires":[["85a18fa8a1d74d63"]]},{"id":"2e15b1359f4227e3","type":"inject","z":"fa67325bf79a710f","name":"","props":[{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","x":1965,"y":260,"wires":[["6438798d32ec0a85"]],"l":false},{"id":"6438798d32ec0a85","type":"file","z":"fa67325bf79a710f","name":"delete","filename":"test.txt","filenameType":"str","appendNewline":true,"createDir":false,"overwriteFile":"delete","encoding":"none","x":2050,"y":260,"wires":[[]]},{"id":"20c687d953fe54ed","type":"subflow:9a693308.7ebaf","z":"fa67325bf79a710f","name":"","env":[{"name":"name","value":"write","type":"str"}],"x":1700,"y":340,"wires":[["1b1cde87d26522bf"]]},{"id":"eb6e52e5cbd87b7f","type":"subflow:9a693308.7ebaf","z":"fa67325bf79a710f","name":"","env":[{"name":"name","value":"write","type":"str"},{"name":"operation","value":"stop","type":"str"}],"x":2060,"y":340,"wires":[["eb032cd5acafa0cd"]]},{"id":"eb032cd5acafa0cd","type":"debug","z":"fa67325bf79a710f","name":"","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":2190,"y":340,"wires":[]},{"id":"57b08ba12818234e","type":"subflow:9a693308.7ebaf","z":"fa67325bf79a710f","name":"","env":[{"name":"name","value":"read","type":"str"}],"x":1700,"y":480,"wires":[["5124707ad3f0da7f"]]},{"id":"9859c5dc622c8a22","type":"subflow:9a693308.7ebaf","z":"fa67325bf79a710f","name":"","env":[{"name":"name","value":"read","type":"str"},{"name":"operation","value":"stop","type":"str"}],"x":2060,"y":480,"wires":[["99339a63cc4988dc"]]},{"id":"494814b732d4bd07","type":"inject","z":"fa67325bf79a710f","name":"Read","props":[{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","x":1490,"y":480,"wires":[["57b08ba12818234e"]]},{"id":"8b10773458448208","type":"change","z":"fa67325bf79a710f","name":"","rules":[{"t":"delete","p":"payload","pt":"msg"}],"action":"","property":"","from":"","to":"","reg":false,"x":1935,"y":340,"wires":[["eb6e52e5cbd87b7f"]],"icon":"font-awesome/fa-trash-o","l":false},{"id":"dac3309da8ca4609","type":"change","z":"fa67325bf79a710f","name":"","rules":[{"t":"delete","p":"payload","pt":"msg"}],"action":"","property":"","from":"","to":"","reg":false,"x":1955,"y":480,"wires":[["9859c5dc622c8a22"]],"icon":"font-awesome/fa-trash-o","l":false}]

Environment

• FlowForge version: 1.2