ERR_HTTP_HEADERS_SENT crashes after upgrading to 3.X

[UnlikelySassou]

Issue Description

I was running Parse Server 2.8.4 and I want to upgrade to the latest versions. I wanted to start by upgrading to 3.10.0 first, so I read the migration guide and made the necessary changes. However, I get an error that appears randomly and that I cannot reproduce. The app runs for a while, then the error will appear and generate a Heroku error H28 "Client Connection Idle".

I would appreciate if someone with more experienced could help! Thanks

Environment Setup

• Server

  • parse-server version : 3.10.0
  • Hardware: Standard-1x (512 MB)
  • Localhost or remote server?: Heroku

• Database

  • MongoDB version: 4.2.11
  • Hardware: Atlas M10
  • Localhost or remote server? MongoDB Atlas

Logs

08 Jan 2021 14:17:04.234361 <158>1 2021-01-08T13:17:04.059196+00:00 heroku router - - at=warning code=H28 desc="Client Connection Idle" method=POST path="/parse/classes/Event" host=**********.herokuapp.com request_id=1b5af5f2-58f7-4a21-a78f-f34e01cbbd06 fwd="*******" dyno=web.2 connect=0ms service=55069ms status=499 bytes=0 protocol=https
08 Jan 2021 14:17:04.471147 <190>1 2021-01-08T13:17:04.084714+00:00 app web.2 - - /app/node_modules/parse-server/lib/ParseServer.js:229
08 Jan 2021 14:17:04.471114 <190>1 2021-01-08T13:17:04.084724+00:00 app web.2 - - throw err;
08 Jan 2021 14:17:04.471105 <190>1 2021-01-08T13:17:04.084725+00:00 app web.2 - - ^
08 Jan 2021 14:17:04.47194 <190>1 2021-01-08T13:17:04.084725+00:00 app web.2 - -
08 Jan 2021 14:17:04.471177 <190>1 2021-01-08T13:17:04.084726+00:00 app web.2 - - Error [ERR_HTTP_HEADERS_SENT]: Cannot set headers after they are sent to the client
08 Jan 2021 14:17:04.471152 <190>1 2021-01-08T13:17:04.084726+00:00 app web.2 - - at ServerResponse.setHeader (_http_outgoing.js:526:11)
08 Jan 2021 14:17:04.471160 <190>1 2021-01-08T13:17:04.084727+00:00 app web.2 - - at Array.write (/app/node_modules/finalhandler/index.js:115:9)
08 Jan 2021 14:17:04.471157 <190>1 2021-01-08T13:17:04.084727+00:00 app web.2 - - at listener (/app/node_modules/on-finished/index.js:164:15)
08 Jan 2021 14:17:04.471155 <190>1 2021-01-08T13:17:04.084728+00:00 app web.2 - - at onFinish (/app/node_modules/on-finished/index.js:95:5)
08 Jan 2021 14:17:04.471153 <190>1 2021-01-08T13:17:04.084728+00:00 app web.2 - - at callback (/app/node_modules/ee-first/index.js:33:10)
08 Jan 2021 14:17:04.471158 <190>1 2021-01-08T13:17:04.084728+00:00 app web.2 - - at Socket.onevent (/app/node_modules/ee-first/index.js:66:5)
08 Jan 2021 14:17:04.471131 <190>1 2021-01-08T13:17:04.084729+00:00 app web.2 - - at Socket.emit (events.js:322:22)
08 Jan 2021 14:17:04.471144 <190>1 2021-01-08T13:17:04.084729+00:00 app web.2 - - at Socket.EventEmitter.emit (domain.js:482:12)
08 Jan 2021 14:17:04.471146 <190>1 2021-01-08T13:17:04.08473+00:00 app web.2 - - at emitErrorNT (internal/streams/destroy.js:92:8)
08 Jan 2021 14:17:04.471156 <190>1 2021-01-08T13:17:04.08473+00:00 app web.2 - - at emitErrorAndCloseNT (internal/streams/destroy.js:60:3) {
08 Jan 2021 14:17:04.471125 <190>1 2021-01-08T13:17:04.084731+00:00 app web.2 - - code: 'ERR_HTTP_HEADERS_SENT'
08 Jan 2021 14:17:04.47195 <190>1 2021-01-08T13:17:04.084731+00:00 app web.2 - - }
08 Jan 2021 14:17:04.471118 <190>1 2021-01-08T13:17:04.100588+00:00 app web.2 - - npm ERR! code ELIFECYCLE
08 Jan 2021 14:17:04.471110 <190>1 2021-01-08T13:17:04.100873+00:00 app web.2 - - npm ERR! errno 7
08 Jan 2021 14:17:04.471152 <190>1 2021-01-08T13:17:04.101927+00:00 app web.2 - - npm ERR! parse-server-example@1.4.0 start: `node index.js`
08 Jan 2021 14:17:04.471116 <190>1 2021-01-08T13:17:04.102127+00:00 app web.2 - - npm ERR! Exit status 7
08 Jan 2021 14:17:04.471102 <190>1 2021-01-08T13:17:04.10234+00:00 app web.2 - - npm ERR!
08 Jan 2021 14:17:04.471157 <190>1 2021-01-08T13:17:04.102504+00:00 app web.2 - - npm ERR! Failed at the parse-server-example@1.4.0 start script.
08 Jan 2021 14:17:04.471191 <190>1 2021-01-08T13:17:04.10268+00:00 app web.2 - - npm ERR! This is probably not a problem with npm. There is likely additional logging output above.
08 Jan 2021 14:17:04.953311 <158>1 2021-01-08T13:17:04.785256+00:00 heroku router - - at=info method=POST path="/parse/batch" host=**********.herokuapp.com request_id=75ba5673-2437-4e59-a8a5-17482b43de76 fwd="******" dyno=web.1 connect=1ms service=101ms status=200 bytes=637 protocol=https
08 Jan 2021 14:17:04.99894 <190>1 2021-01-08T13:17:04.790391+00:00 app web.2 - -
08 Jan 2021 14:17:04.998146 <190>1 2021-01-08T13:17:04.790617+00:00 app web.2 - - npm ERR! A complete log of this run can be found in:
08 Jan 2021 14:17:04.998157 <190>1 2021-01-08T13:17:04.790737+00:00 app web.2 - - npm ERR! /app/.npm/_logs/2021-01-08T13_17_04_103Z-debug.log
08 Jan 2021 14:17:05.043324 <158>1 2021-01-08T13:17:04.879917+00:00 heroku router - - at=info method=POST path="/parse/classes/Server" host=**********.herokuapp.com request_id=49af389a-e872-4f1e-85e6-d2e4ca046c45 fwd="******" dyno=web.1 connect=1ms service=209ms status=200 bytes=10755 protocol=https
08 Jan 2021 14:17:05.225125 <134>1 2021-01-08T13:17:04.862121+00:00 heroku web.2 - - Process exited with status 7
08 Jan 2021 14:17:05.249129 <134>1 2021-01-08T13:17:04.911178+00:00 heroku web.2 - - State changed from up to crashed
08 Jan 2021 14:17:05.249134 <134>1 2021-01-08T13:17:04.91474+00:00 heroku web.2 - - State changed from crashed to starting

Inex.js

var express = require('express');
var ParseServer = require('parse-server').ParseServer;
var path = require('path');
var S3Adapter = require('parse-server').S3Adapter;
var timeout = require('connect-timeout');

var databaseUri = process.env.DATABASE_URI || process.env.MONGODB_URI || '';
if (!databaseUri) {
  console.log('DATABASE_URI not specified, falling back to localhost.');
}

let VERBOSE = process.env.VERBOSE;
if(VERBOSE == 1) {
    VERBOSE = true;
} else {
    VERBOSE = false;
}

var api = new ParseServer({
  databaseURI: databaseUri || 'mongodb://localhost:27017/dev',
  databaseOptions: {
    maxTimeMS: 1500,
  },
  cloud: process.env.CLOUD_CODE_MAIN || __dirname + '/cloud/main.js',
  appId: process.env.APP_ID || '',
  masterKey: process.env.MASTER_KEY || '', //Add your master key here. Keep it secret!
  fileKey: process.env.FILE_KEY || '', // For migrated apps, this is necessary to provide access to files
  serverURL: process.env.SERVER_URL || 'http://localhost:1337/parse',  // Don't forget to change to https if needed
  maxUploadSize: process.env.MAX_UPLOAD_SIZE || '20mb',
  verbose:VERBOSE,
  enableSingleSchemaCache: true,
  allowClientClassCreation: false,
  push: {
      ios: {
        pfx: 'certificates/Certificates2020.p12',
        bundleId: '*******',
        production: true
      }
    },
  filesAdapter: new S3Adapter(
    process.env.AWS_ACCESS_KEY_ID || "",
    process.env.AWS_SECRET_ACCESS_KEY || "",
    process.env.BUCKET_NAME || "",
    {bucketPrefix : 'data/', directAccess: true}
  )
});

var app = express();
app.use(timeout('30s'));

// Serve static assets from the /public folder
app.use('/public', express.static(path.join(__dirname, '/public')));

// Serve the Parse API on the /parse URL prefix
var mountPath = process.env.PARSE_MOUNT || '/parse';
app.use(mountPath, api);
app.use(haltOnTimedout);

// Parse Server plays nicely with the rest of your web routes
app.get('/', function(req, res) {
  res.status(200).send('Hello World!');
});

// Top level timeouts
function haltOnTimedout(req, res, next) {
  if (!req.timedout) next();
}

// Server timeouts
var port = process.env.PORT || 1337;
var httpServer = require('http').createServer(app);
httpServer.timeout = 25 * 1000;
httpServer.keepAliveTimeout = 70 * 1000;
httpServer.headersTimeout = 120 * 1000;
httpServer.listen(port, function() {
    console.log('parse-server running on port ' + port + '.');
});

[mtrezza]

It seems that the H28 error is logged after a timeout of 55s. I suggest you take a look at this issue and overall look into your timeout handling, for example any interplay between your nodejs server timeout settings and your haltOnTimedout method.

I'm closing this as it does not seem to be a Parse Server issue.

For help with Parse Server, here are some resources you can try:

• For code-level questions we recommend Stack Overflow using the parse-platform tag.
• For network and server questions we recommend ServerFault using the parse-server tag
• For questions that are not appropriate for the above mentioned sites we recommend our community forum.

Feel free to comment if you have any questions and we can re-open this issue.

[UnlikelySassou]

I upgraded to 3.10.0 this morning and I have a little more logs from Logentries now. I assumed the H28 error and the crash were related because of the logs I had so far, but it doesn't seem to be the case.

The crash happened 3 more times in the last hour and no H28 error or timeout specific error has been raised while it was happening. The logs show that all requests were processing just fine before the crash. Then the app restarts and takes requests as usual.

Do you still think it may be related to the way I'm implementing timeouts? I don't know if it's server related or more a code-level implementation issue at this point.

08 Jan 2021 15:55:50.761322 <158>1 2021-01-08T14:55:50.485385+00:00 heroku router - - at=info method=POST path="/parse/classes/Message" host=*********.herokuapp.com request_id=1799b172-ce11-491c-a95c-2e3c0ed821cd fwd="********" dyno=web.2 connect=0ms service=12ms status=201 bytes=731 protocol=https
08 Jan 2021 15:55:50.864323 <158>1 2021-01-08T14:55:50.706699+00:00 heroku router - - at=info method=POST path="/parse/classes/Message" host=*********.herokuapp.com request_id=c5d52bdb-1874-4b27-8d15-1cd11827d765 fwd="********" dyno=web.1 connect=1ms service=28ms status=200 bytes=7475 protocol=https
08 Jan 2021 15:55:51.192146 <190>1 2021-01-08T14:55:50.90611+00:00 app web.2 - - /app/node_modules/parse-server/lib/ParseServer.js:229
08 Jan 2021 15:55:51.192114 <190>1 2021-01-08T14:55:50.906116+00:00 app web.2 - - throw err;
08 Jan 2021 15:55:51.192105 <190>1 2021-01-08T14:55:50.906117+00:00 app web.2 - - ^
08 Jan 2021 15:55:51.19294 <190>1 2021-01-08T14:55:50.906117+00:00 app web.2 - -
08 Jan 2021 15:55:51.192177 <190>1 2021-01-08T14:55:50.906118+00:00 app web.2 - - Error [ERR_HTTP_HEADERS_SENT]: Cannot set headers after they are sent to the client
08 Jan 2021 15:55:51.192152 <190>1 2021-01-08T14:55:50.906119+00:00 app web.2 - - at ServerResponse.setHeader (_http_outgoing.js:526:11)
08 Jan 2021 15:55:51.192160 <190>1 2021-01-08T14:55:50.906119+00:00 app web.2 - - at Array.write (/app/node_modules/finalhandler/index.js:115:9)
08 Jan 2021 15:55:51.192156 <190>1 2021-01-08T14:55:50.90612+00:00 app web.2 - - at listener (/app/node_modules/on-finished/index.js:164:15)
08 Jan 2021 15:55:51.192154 <190>1 2021-01-08T14:55:50.90612+00:00 app web.2 - - at onFinish (/app/node_modules/on-finished/index.js:95:5)
08 Jan 2021 15:55:51.192152 <190>1 2021-01-08T14:55:50.90612+00:00 app web.2 - - at callback (/app/node_modules/ee-first/index.js:33:10)
08 Jan 2021 15:55:51.192167 <190>1 2021-01-08T14:55:50.906121+00:00 app web.2 - - at IncomingMessage.onevent (/app/node_modules/ee-first/index.js:66:5)
08 Jan 2021 15:55:51.192140 <190>1 2021-01-08T14:55:50.906121+00:00 app web.2 - - at IncomingMessage.emit (events.js:322:22)
08 Jan 2021 15:55:51.192153 <190>1 2021-01-08T14:55:50.906122+00:00 app web.2 - - at IncomingMessage.EventEmitter.emit (domain.js:482:12)
08 Jan 2021 15:55:51.192144 <190>1 2021-01-08T14:55:50.906122+00:00 app web.2 - - at endReadableNT (_stream_readable.js:1187:12)
08 Jan 2021 15:55:51.192168 <190>1 2021-01-08T14:55:50.906123+00:00 app web.2 - - at processTicksAndRejections (internal/process/task_queues.js:84:21) {
08 Jan 2021 15:55:51.192125 <190>1 2021-01-08T14:55:50.906123+00:00 app web.2 - - code: 'ERR_HTTP_HEADERS_SENT'
08 Jan 2021 15:55:51.19295 <190>1 2021-01-08T14:55:50.906123+00:00 app web.2 - - }
08 Jan 2021 15:55:51.192118 <190>1 2021-01-08T14:55:50.934283+00:00 app web.2 - - npm ERR! code ELIFECYCLE
08 Jan 2021 15:55:51.192110 <190>1 2021-01-08T14:55:50.934817+00:00 app web.2 - - npm ERR! errno 7
08 Jan 2021 15:55:51.192152 <190>1 2021-01-08T14:55:50.936631+00:00 app web.2 - - npm ERR! parse-server-example@1.4.0 start: `node index.js`
08 Jan 2021 15:55:51.192116 <190>1 2021-01-08T14:55:50.936938+00:00 app web.2 - - npm ERR! Exit status 7
08 Jan 2021 15:55:51.192103 <190>1 2021-01-08T14:55:50.937273+00:00 app web.2 - - npm ERR!
08 Jan 2021 15:55:51.192157 <190>1 2021-01-08T14:55:50.937522+00:00 app web.2 - - npm ERR! Failed at the parse-server-example@1.4.0 start script.
08 Jan 2021 15:55:51.192191 <190>1 2021-01-08T14:55:50.93776+00:00 app web.2 - - npm ERR! This is probably not a problem with npm. There is likely additional logging output above.
08 Jan 2021 15:55:51.19294 <190>1 2021-01-08T14:55:50.964272+00:00 app web.2 - -
08 Jan 2021 15:55:51.192146 <190>1 2021-01-08T14:55:50.964937+00:00 app web.2 - - npm ERR! A complete log of this run can be found in:
08 Jan 2021 15:55:51.192157 <190>1 2021-01-08T14:55:50.965088+00:00 app web.2 - - npm ERR! /app/.npm/_logs/2021-01-08T14_55_50_951Z-debug.log
08 Jan 2021 15:55:51.198322 <158>1 2021-01-08T14:55:50.89456+00:00 heroku router - - at=info method=POST path="/parse/classes/Message" host=*********.herokuapp.com request_id=719fe9c9-afdb-4948-9330-ea67141535f7 fwd="********" dyno=web.2 connect=1ms service=36813ms status=503 bytes=646 protocol=https
08 Jan 2021 15:55:51.424125 <134>1 2021-01-08T14:55:51.058705+00:00 heroku web.2 - - Process exited with status 7
08 Jan 2021 15:55:51.444129 <134>1 2021-01-08T14:55:51.106609+00:00 heroku web.2 - - State changed from up to crashed
08 Jan 2021 15:55:51.444135 <134>1 2021-01-08T14:55:51.113636+00:00 heroku web.2 - - State changed from crashed to starting

[mtrezza]

You could start with a fresh installation of Parse Server and see if these issues still happen, then gradually add your custom configuration and code to see where the issue lies.

The resources I mentioned above should provide support if needed. If it turns out to be an issue with Parse Server please feel free to post an update here and we can investigate.