All Requests Receive Timeout Error

[jgaull]

Environment Setup

• Server: parse-server 2.2.10 (also tested on 2.2.9) , node 5.11.1, heroku
• Database: mLab mongoDB 3.0.9

Steps to reproduce

I'm sorry this sucks, but we have not been able to narrow down the steps any more than this:

1. Upload build to server
2. Wait 5-15 minutes

Result: All requests begin timing out.

Code

Please note, this code does not appear to cause the problem as timeouts have begun without this ever running. However, I've been using this function when troubleshooting.

    console.log('running create!');
    //configure parameters
    var user = request.user;

    var title = request.params.title; //required
    var imageData = request.params.imageData; //required
    var videoData = request.params.videoData; //optional
    var content = request.params.content; //optional
    var attachment = request.params.attachment; //optional always URL

    //create a new story
    var newStory = new Story();
    //set the default parameters
    newStory.set("user", user);
    newStory.set("inspireCount", 0);
    newStory.set("commentCount", 0);
    newStory.set("viewCount", 0);
    newStory.set("notificationsOptOut", []);
    newStory.set("archived", false);
    newStory.set("toAllUsers", true);
    //add params that have been passed in
    newStory.set("title", title);
    newStory.set("content", content);
    newStory.set("attachment", attachment);
    //get the user's name and set it to the story
    var creatorName = user.get("name");
    newStory.set("creatorName", creatorName);

    //set the ACL
    newStory.setACL(createACLForStory(newStory));

    //this will be used to store promises when saving files
    var mediaFileSavePromises = [];
    //create image
    var image = new Parse.File("Image.jpg", imageData, "image/jpg");
    //save the image and push the promise into an array of promises
    mediaFileSavePromises.push(image.save());
    newStory.set("imageFile", image);

    //if there is a video
    if (videoData) {
        //create a file
        var video = new Parse.File("Video.mp4", videoData, "video/mp4");
        //save the file and push the promise onto the array
        mediaFileSavePromises.push(video.save());
        newStory.set("videoFile", video);
    }

    Parse.Promise.when(mediaFileSavePromises).then(function (mediaFiles) {
        //save the story
        console.log("media saved");
        return newStory.save();

    })
//more stuff. But never runs after timeouts start

Logs/Trace

Once timeouts begin I'm seeing this with VERBOSE enabled:

2016-05-20T20:18:26.942301+00:00 app[web.1]: verbose: GET /parse/classes/ClinkComment { host: '****.herokuapp.com',
2016-05-20T20:18:26.942311+00:00 app[web.1]:   connection: 'close',
2016-05-20T20:18:26.942313+00:00 app[web.1]:   'user-agent': 'node-XMLHttpRequest, Parse/js1.8.5 (NodeJS 5.11.1)',
2016-05-20T20:18:26.942313+00:00 app[web.1]:   accept: '*/*',
2016-05-20T20:18:26.942314+00:00 app[web.1]:   'content-type': 'text/plain',
2016-05-20T20:18:26.942317+00:00 app[web.1]:   'x-request-id': '9a7593e2-87c6-4e48-bc56-d1f9d05a0177',
2016-05-20T20:18:26.942318+00:00 app[web.1]:   'x-forwarded-for': '54.242.116.62',
2016-05-20T20:18:26.942319+00:00 app[web.1]:   'x-forwarded-proto': 'https',
2016-05-20T20:18:26.942319+00:00 app[web.1]:   'x-forwarded-port': '443',
2016-05-20T20:18:26.942320+00:00 app[web.1]:   via: '1.1 vegur',
2016-05-20T20:18:26.942320+00:00 app[web.1]:   'connect-time': '2',
2016-05-20T20:18:26.942321+00:00 app[web.1]:   'x-request-start': '1463775506929',
2016-05-20T20:18:26.942322+00:00 app[web.1]:   'total-route-time': '0',
2016-05-20T20:18:26.942322+00:00 app[web.1]:   'content-length': '349' } {
2016-05-20T20:18:26.942323+00:00 app[web.1]:   "where": {
2016-05-20T20:18:26.942324+00:00 app[web.1]:     "clink": {
2016-05-20T20:18:26.942324+00:00 app[web.1]:       "__type": "Pointer",
2016-05-20T20:18:26.942325+00:00 app[web.1]:       "className": "Clink",
2016-05-20T20:18:26.942325+00:00 app[web.1]:       "objectId": "B1vNrvL9sC"
2016-05-20T20:18:26.942326+00:00 app[web.1]:     }
2016-05-20T20:18:26.942327+00:00 app[web.1]:   },
2016-05-20T20:18:26.942327+00:00 app[web.1]:   "include": "user",
2016-05-20T20:18:26.942328+00:00 app[web.1]:   "limit": 25,
2016-05-20T20:18:26.942328+00:00 app[web.1]:   "order": "-createdAt"
2016-05-20T20:18:26.942329+00:00 app[web.1]: }
2016-05-20T20:18:26.696219+00:00 heroku[router]: at=error code=H12 desc="Request timeout" method=POST path="/parse/classes/ClinkComment" host=***.herokuapp.com request_id=dcac6a25-54f5-42b0-b15e-dd43556a7a4a fwd="54.242.116.62" dyno=web.1 connect=1ms service=30000ms status=503 bytes=0
2016-05-20T20:18:31.243011+00:00 heroku[router]: at=error code=H12 desc="Request timeout" method=POST path="/parse/functions/fetchStories" host=***.herokuapp.com request_id=3d6c2b02-57f4-430c-b836-54563d5ace3f fwd="108.212.64.230" dyno=web.1 connect=1ms service=30000ms status=503 bytes=0
2016-05-20T20:18:31.260092+00:00 heroku[router]: at=error code=H12 desc="Request timeout" method=POST path="/parse/classes/Clink" host=***.herokuapp.com request_id=0fbf25bd-2def-43a3-81c3-c0e875950825 fwd="54.242.116.62" dyno=web.1 connect=1ms service=30000ms status=503 bytes=0

If I wait around long enough I see this error:

2016-05-20T19:19:53.738611+00:00 app[web.1]: error! Received an error with invalid JSON from Parse: <!DOCTYPE html>
2016-05-20T19:19:53.738637+00:00 app[web.1]:     <html>
2016-05-20T19:19:53.738638+00:00 app[web.1]:     <head>
2016-05-20T19:19:53.738639+00:00 app[web.1]:       <meta name="viewport" content="width=device-width, initial-scale=1">
2016-05-20T19:19:53.738640+00:00 app[web.1]:       <style type="text/css">
2016-05-20T19:19:53.738641+00:00 app[web.1]:         html, body, iframe { margin: 0; padding: 0; height: 100%; }
2016-05-20T19:19:53.738643+00:00 app[web.1]:         iframe { display: block; width: 100%; border: none; }
2016-05-20T19:19:53.738643+00:00 app[web.1]:       </style>
2016-05-20T19:19:53.738645+00:00 app[web.1]:     <title>Application Error</title>
2016-05-20T19:19:53.738645+00:00 app[web.1]:     </head>
2016-05-20T19:19:53.738646+00:00 app[web.1]:     <body>
2016-05-20T19:19:53.738647+00:00 app[web.1]:       <iframe src="//s3.amazonaws.com/heroku_pages/error.html">
2016-05-20T19:19:53.738647+00:00 app[web.1]:         <p>Application Error</p>
2016-05-20T19:19:53.738648+00:00 app[web.1]:       </iframe>
2016-05-20T19:19:53.738648+00:00 app[web.1]:     </body>
2016-05-20T19:19:53.738649+00:00 app[web.1]:     </html>

Tested These Things

• Spun up a new server instance. Still saw issue.
• Waited until issue started and visited https://my-app.herokuapp.com/ and saw "I dream of being a website"
• Added console.log statements in cloud code (above). Cloud functions get called even when requests are timing out. PFFiles are successfully saved. Nothing happens after newStory.save().
• Enabled "log-runtime-metrics". Memory usage was stable.
• Restarted server. This solves the issue temporarily.
• Rolled back to a previous deploy. This solved the issue. Diffed code between releases and saw only trivial changes. A few console.logs.

I'm very much at a loss for how to continue troubleshooting this problem. Thanks so much for your help!

[drew-gross]

You are receiving an AWS error, which seems to indicate an issue with your AWS config. If you run the server locally, do you get the same issue?

[jgaull]

Thanks @drew-gross! I'm not set up to run the server locally. I can work on this.

Is it possible that this AWS error is related to S3Adapter? As far as I know that's the only AWS we integrate with.

[drew-gross]

That is possible, yes. Possibly if you have an extremely large file are are trying to proxy it through a very small heroku instance or something.

[jgaull]

@drew-gross largest file in S3 is 7.7mb. Should be fine. It looks like #1854 describes exactly what our team is experiencing.

[jadsonlourenco]

I have no sure about the problem, but before upgrade to 2.2.10 all works fine, local and remote (same server), and I'm using Google Cloud Storage to files, so I don't think that it is an issue because of server load or proxy, before upgrade everything works fine including fetch files... But I don't know.

The MongoDb I don't think too, because I can access data normally on the parse-server database, using MongoChef.

Also after restart the Docker container of parse-server it back to normal, but then down again. It's mean is something related with parse-server.

I'm waiting the log here, soon I paste here after the parser-serve go to down.

[jadsonlourenco]

Ok, after few minutes the server not respond anymore, but show nothing on the logs (VERBOSE). Can be related with database, I'm installing the database locally now to see the logs too.
Just to share ☺️

[drew-gross]

@jgaull If your ClinkComment class is large and there is no index on createdAt then mongo may be forced to do a full table scan which takes too long. This is why my suggestion was to check the mongo logs for long running queries.

[dcdspace]

@drew-gross do you have any ideas on why this happened only after updating, and can be temporarily fixed for under 15 minutes by resetting the dyno?

[davide-scalzo]

I'm experiencing the same issue, however I deploy on EB. Here's the Nginx error log after I switched to a single instance:

-------------------------------------
/var/log/nginx/error.log
-------------------------------------
2016/05/21 02:13:57 [warn] 3409#0: duplicate MIME type "text/html" in /etc/nginx/conf.d/00_elastic_beanstalk_proxy.conf:42
2016/05/21 02:25:14 [error] 3432#0: *6 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 75.165.113.35, server: , request: "POST /api/classes/Brand HTTP/1.1", upstream: "http://127.0.0.1:8081/api/classes/Brand", host: "www.example.com"
2016/05/21 02:25:14 [error] 3432#0: *7 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 75.165.113.35, server: , request: "POST /api/classes/Review HTTP/1.1", upstream: "http://127.0.0.1:8081/api/classes/Review", host: "www.example.com"
2016/05/21 02:25:14 [error] 3432#0: *5 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 75.165.113.35, server: , request: "POST /api/classes/Location HTTP/1.1", upstream: "http://127.0.0.1:8081/api/classes/Location", host: "www.example.com"
2016/05/21 02:25:14 [error] 3432#0: *8 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 75.165.113.35, server: , request: "POST /api/classes/Review HTTP/1.1", upstream: "http://127.0.0.1:8081/api/classes/Review", host: "www.example.com"

Otherwise with auto-scaling there is a 111 error:

failed (111: Connection refused) while connecting to upstream

[jgaull]

@drew-gross There are only 232 records in the table. I can double check that there's an index tomorrow.

[drew-gross]

No, I don't have any ideas unfortunately, hence why I'm looking for logs. There weren't actually very many changes in the recent versions of Parse Server, and looking at them I don't see anything that seems relevant.

[drew-gross]

@jgaull 232 records wouldn't be enough to cause issues even if a tablescan is going on. Checking the mongo logs for slow queries would still be useful though.

[johndrewing]

@drew-groos I'm still can seeing data is showing on parse.com dashboard. (I was already migrated data) but it not showing from my server.

[davide-scalzo]

@jadsonlourenco @jgaull are the three of us all on mongoLab sandbox plan?