Server Request Interrupted Error on Heroku after a while

[ebitogu]

Thanks for this amazing library.

I however have a weird issue going on. I am going to paste my code exactly as it is in production just so I can get as much help as possible to resolving my problem.

The problem I am having is this:

When I uploaded a file of about 26MB more than 4 times using Busboy it worked flawlessly.
Now after a while I keep getting this error in my heroku application logs that states:
sock=backend at=error code=H18 desc="Server Request Interrupted" method=PUT
I did some research and found out that it has something to do with handling chunked file upload according to their documentation
https://help.heroku.com/18NDWDW0/debugging-h18-server-request-interrupted-errors-in-nodejs-applications

I can't seem to figure out what is going on but the above Server Request Interrupted error message has kept me stalled pretty badly as users are complaining that file uploads are no longer going through after a while.

Please I need all the help I can get at resolving this.

Here is the code that handles the large file uploads

static async createNewPost(req, res) {
    const busboy = new Busboy({
        headers: req.headers,
        highWaterMark: 2 * 1024 * 1024,
        limits: {
            fileSize: 1e+9,
        }
    });
    let accessKey = req.header('access_key');
    let badRequestError = Preconditions.checkNotNull({ accessKey });
    if (badRequestError) {
        return ResponseHandler.sendErrorResponse(res, StatusCodes.BAD_REQUEST, badRequestError);
    }
    let user = await AccountService.findByAccessKey(accessKey);
    if (!user) {
        return ResponseHandler.sendErrorResponse(res, StatusCodes.NOT_FOUND, "Invalid Access Key Provided");
    }
    let uploadPath = path.join(__dirname, '..');
    uploadPath = path.join(uploadPath, 'uploads/');
    fs.ensureDir(uploadPath);
    let filePaths = [];
    let fileNames = [];
    let requestBody = {};
    let uploadedFileUrls = [];
    busboy.on('file', function (fieldname, file, filename, encoding, mimetype) {
        let newFileName = `${Math.random() * 100000000000}${filename}`;
        let fileExtension = filename.split('.')[filename.split('.').length - 1];
        newFileName = SHA256(newFileName);
        newFileName = `${newFileName}.${fileExtension}`;
        let filePath = path.join(uploadPath, newFileName);
        if (!filePaths.includes(filePath)) {
            filePaths.push(filePath);
            fileNames.push(newFileName);
        }
        file.pipe(fs.createWriteStream(filePath));
    });
    busboy.on('field', function (fieldname, val, fieldnameTruncated, valTruncated, encoding, mimetype) {
        let data = JSON.parse(val);
        requestBody['data'] = data;
    });
    busboy.on('finish', async function () {
        let { data } = requestBody;
        let { targets, body, time_to_post, ...others } = data;
        if (filePaths.length > 0) {
            for (let i = 0; i < filePaths.length; i++) {
                let uploadableFilePath = filePaths[i];
                let fileName = fileNames[i];
                try {
                    let uuid = uuidv4();
                    let bucket = firebase.storage().bucket();
                    await bucket.upload(uploadableFilePath, {
                        resumable: false,
                        gzip: true,
                        metadata: {
                            cacheControl: 'public, max-age=31536000',
                            firebaseStorageDownloadTokens: uuid,
                        }
                    });
                    const uploadedFileUrl = `https://firebasestorage.googleapis.com/v0/b/${bucket.name}/o/${fileName}?alt=media&token=${uuid}`;
                    if (!uploadedFileUrls.includes(uploadedFileUrl)) {
                        uploadedFileUrls.push(uploadedFileUrl);
                    }
                    //Delete the file immediately after upload to firebase
                    module.exports.unLinkFile(uploadableFilePath);
                } catch (e) {
                    console.log(e);
                }
            }
            //Finally publish post here
        } else {
            //Finally publish post here
        }
        res.writeHead(303, { Connection: 'close', Location: '/' });
        res.end();
    });
    req.pipe(busboy);
}

I know the code is quite exhausting to understand easily but kindly look through and see if I am missing anything that is causing the dreaded Server Request Interrupted Error after a while.

Thank you

[mscdex]

The only thing I see wrong at first glance is that you're not waiting for uploaded files to be completely flushed to disk (the 'finish' event from each fs.createWriteStream() stream) before trying to upload them to firebase and delete them from disk.

While the 'finish' event on busboy does indicate the entire form has been read/processed, if you do anything async inside the 'file' event handler, you may need to wait appropriately if you need to immediately do something with those files. In your particular case it's possible for node to still have some data buffered in memory that hasn't been written to disk yet. The node file stream's 'finish' event will tell you when all data has been flushed to disk and the file descriptor has been closed. That is when you know it will be safe to upload that file and delete it.

[ebitogu]

@mscdex Thank you for the swift response. However, I am not doing any heavy work while the files are been streamed to disk. If you noticed my flow, I have support for uploading multiple files. So, what I did was after each file upload to disk I basically added the path of that file to a filePaths array, that is without sending it to firebase yet.

It is when all the files have been uploaded to disk and the busboy.on('finish') event is called that I took all the paths of the uploaded files and send to firebase one after the other and delete it from disk.

Now, the major issue here is that Server Request Interrupted means something somewhere is interrupting the requests at that point where req.pipe(busboy); is called.

Plus, I followed the examples exactly as given in the busboy documentation and only did final processing within the callback of busboy.on('finish')

Also this line file.pipe(fs.createWriteStream(filePath)); I didn't see any example in the documentation that shows how to close the stream after each file upload. Mind sharing?

But according to what you said, can you recommend a way for me to know if there are hanging files in node memory that I can clear up before busboy.on('file'); is called on each file?

Thanks in anticipation of your response.

[mscdex]

It is when all the files have been uploaded to disk and the busboy.on('finish') event is called that I took all the paths of the uploaded files and send to firebase one after the other and delete it from disk.

Like I said, busboy's 'finish' event is emitted when the entire form has been completely parsed, it doesn't mean all of your files have necessarily been completely written to disk yet due to how node streams work. To be safe, you should be waiting until each fs.createWriteStream() stream you create has emitted 'finish' before calling bucket.upload() for that particular file.

Now, the major issue here is that Server Request Interrupted means something somewhere is interrupting the requests at that point where req.pipe(busboy); is called.

I'm not familiar with how Heroku works or what debugging/troubleshooting facilities they provide. Is it possible there is an 'error' event or other exception being thrown, causing your application to die before sending a response? Otherwise I see nothing that would prevent a response from being sent from this particular code path. I would suggest start mocking out different parts of this code to narrow down the cause (e.g. uploading to firebase, form parsing with busboy, etc.).

Also this line file.pipe(fs.createWriteStream(filePath)); I didn't see any example in the documentation that shows how to close the stream after each file upload. Mind sharing?

Which stream? pipe() automatically closes the writable stream you pass to it by default when the readable stream you're piping from ends.

[ebitogu]

@mscdex Thank you once again for your elaborate response. As you've suggested, henceforth I will surely try to wait for the writeStream of each file to fire finish before pushing to firebase.

Now, unto the main issue which is sock=backend at=error code=H18 desc="Server Request Interrupted" method=PUT I did further research and bumped on this stack overflow question here (https://stackoverflow.com/questions/42748698/rust-http-server-on-heroku-generates-error-h18-server-request-interrupted) which was directed at Rust and not NodeJS but still helpful because the issue is the same. And they said this and I quote

As discussed in the comments, the problem was that the code was using \n as the delimiter in the HTTP response whereas the standard says it should be \r\n

Do you have any idea what that means? Is it possible that res.end() should be using res.end('\r\n'), I am not too sure what they meant by that because I feel nodejs was responsible for sending back a valid response.

Kindly review and see if you can understand what they meant here.

Thanks once again for your anticipated response.

[mscdex]

The part you quoted is referring to a lower level part of HTTP. Node already takes care of those sorts of details. As long as you're calling res.end() either implicitly or explicitly, a response should be sent.

[ebitogu]

Damn! So I'm stucked in this as I have no idea on what next to do to prevent this Server Request Interrupted error 😢 .

[ebitogu]

Or is it possible it has something to do with the Free version of Heroku? Because I successfully uploaded files of about 30MB with the above code up to 5 times and then on the 6th time I started getting the dreaded Server Request Interrupted error.

[ebitogu]

@mscdex Is it possible that this issue nodejs/node#12339 is likely responsible to my case?

My node version is this "node": ">=14.0",

[ebitogu]

I strongly believe Heroku is throwing the Server Request Interrupted error after a while the moment req.pipe(busboy); is called. So none of the events like busboy.on('file'), busboy.on('field'), busboy.on('finish') ever got the opportunity to fire at all.

So it's likely that there is an interruption going on when req.pipe(busboy); is called.

But I don't know how to find out where exactly it is happening.

[Uzlopak]

Try to set autoDestroy of busboy to false.

[ebitogu]

@Uzlopak Oh really? Please where can I set that? Thank you

[Uzlopak]

here pseudocode:

const bb = new busboy();
bb._writableState.autoDestroy = false

[ebitogu]

@Uzlopak It worked!!!!!! You have no idea how u just saved me my Job. I'm so greatly thankful to you. If you believe in the concept of God, then I'll say may God bless you 👍 ... I truly truly truly appreciate. Thanks a trillion times.

[Uzlopak]

@hashweather
Great to hear that.

Maybe I can make you interested in our busboy fork? https://github.com/fastify/busboy .It has autoDestroy set to false by default. So with our fork you would have never had this issue in the first place. Check what else we have done in our fork. :) More performance and more safety (fixed security issues) are waiting for you.

[ebitogu]

@Uzlopak Wow! Fantastic.. Thank you very much. I'll migrate asap.

[mscdex]

Closing this as this should no longer be an issue with v1.x. If you find that it is, let me know and we can re-open this.