REST request times out when restoring etherpad revisions

[mrvisser]

I tried to restore a revision of an etherpad document in staging on 1.4.0: c:gatch:-yo1Bzglb

The restore request gave me a 504 gateway timeout (that's a 5s failure time to node it tried). Afterward, there were a bunch of new revisions that were created at the same time. There are a few issues here:

• [x] Nginx, after a 5s time out to one app server retried each other one. The request that was made actually did result in creating a new revision, however possibly threw an exception and never wound up responding to the web request. Nginx shouldn't retry non-idempotent requests: #3836
• [x] I think an exception was thrown that triggered the timeout, please validate that. However, our Express.js error handler should have caught that and then replied with a 500 code rather quickly on the response. If an exception caused this, why didn't our error handler catch it with its domain handler?

• [x] This exception was thrown, that may have resulted in the timeout:

  [2014-07-30T15:30:22.685Z] ERROR: oae/23127 on app0: An uncaught exception was raised to the application.
    TypeError: Cannot read property 'parent' of undefined
        at exports.update (/opt/oae/node_modules/cheerio/lib/parse.js:62:25)
        at module.exports (/opt/oae/node_modules/cheerio/lib/parse.js:24:3)
        at Function.exports.load (/opt/oae/node_modules/cheerio/lib/static.js:19:14)
        at _isHtmlDocument (/opt/oae/node_modules/oae-content/lib/internal/etherpad.js:352:21)
        at _ensureHtmlDocument (/opt/oae/node_modules/oae-content/lib/internal/etherpad.js:337:9)
        at Object.module.exports.setHTML (/opt/oae/node_modules/oae-content/lib/internal/etherpad.js:150:59)
        at /opt/oae/node_modules/oae-content/lib/api.js:2204:34
        at /opt/oae/node_modules/oae-content/lib/internal/dao.content.js:222:17
        at _doCallback (/opt/oae/node_modules/oae-content/lib/internal/dao.content.js:436:20)
        at /opt/oae/node_modules/oae-content/lib/internal/dao.content.js:459:24

  Before throwing a try/catch at it, we should try and find out why it threw in the first place, it should have been valid HTML

• [x] Why did the request timeout? :)
• [ ] Fix null-revision (or allow restoring an empty pad)
• [ ] Wrap cheerio.load in try/catch

[simong]

Some database data

cqlsh:oae> select * From "RevisionByContent" WHERE "contentId" = 'c:gatech:-yo1Bzglb';

 contentId          | created       | revisionId
--------------------+---------------+-----------------------
 c:gatech:-yo1Bzglb | 1406734037867 | rev:gatech:bkgsyHGlx-
 c:gatech:-yo1Bzglb | 1406734067045 |  rev:gatech:ZykzUMxxb
 c:gatech:-yo1Bzglb | 1406734076830 |  rev:gatech:-1bd8MegW
 c:gatech:-yo1Bzglb | 1406734081850 |  rev:gatech:Z17s8GggZ
 c:gatech:-yo1Bzglb | 1406734086845 |  rev:gatech:-kB0IzleW
 c:gatech:-yo1Bzglb | 1406734091848 |  rev:gatech:-kP-PzleW
 c:gatech:-yo1Bzglb | 1406734098525 |  rev:gatech:W15rDfxeb
 c:gatech:-yo1Bzglb | 1406734103532 |  rev:gatech:Wy3dPMxl-
 c:gatech:-yo1Bzglb | 1406734108540 |  rev:gatech:bkCivfxlb
 c:gatech:-yo1Bzglb | 1406734113548 |  rev:gatech:WyeyOzeeb
 c:gatech:-yo1Bzglb | 1406734175031 |  rev:gatech:Z1PB9fee-
 c:gatech:-yo1Bzglb | 1406734180039 |  rev:gatech:-JYdqfgg-
 c:gatech:-yo1Bzglb | 1406734185038 |  rev:gatech:-ksjcMgx-
 c:gatech:-yo1Bzglb | 1406734190037 |  rev:gatech:bk605MgxZ
 c:gatech:-yo1Bzglb | 1406734210377 |  rev:gatech:bkYojMgg-
 c:gatech:-yo1Bzglb | 1406734222642 |  rev:gatech:bJmX2Gxxb
 c:gatech:-yo1Bzglb | 1406734227640 |  rev:gatech:b1HU2fggb
 c:gatech:-yo1Bzglb | 1406734232633 |  rev:gatech:WJDF2zxlW
 c:gatech:-yo1Bzglb | 1406734237632 |  rev:gatech:ZyK3nflgZ
 c:gatech:-yo1Bzglb | 1406734273525 |  rev:gatech:b1lQRMggZ

cqlsh:oae> select * from "Revisions" WHERE "revisionId" IN ('rev:gatech:b1lQRMggZ', 'rev:gatech:ZyK3nflgZ', 'rev:gatech:WJDF2zxlW', 'rev:gatech:b1HU2fggb', 'rev:gatech:bJmX2Gxxb', 'rev:gatech:bkYojMgg-', 'rev:gatech:bk605MgxZ', 'rev:gatech:-ksjcMgx-', 'rev:gatech:-JYdqfgg-', 'rev:gatech:Z1PB9fee-', 'rev:gatech:WyeyOzeeb', 'rev:gatech:bkCivfxlb', 'rev:gatech:Wy3dPMxl-', 'rev:gatech:W15rDfxeb', 'rev:gatech:-kP-PzleW', 'rev:gatech:-kB0IzleW', 'rev:gatech:Z17s8GggZ', 'rev:gatech:-1bd8MegW', 'rev:gatech:ZykzUMxxb', 'rev:gatech:bkgsyHGlx-')
       ... ;

 revisionId            | contentId          | created       | createdBy         | etherpadHtml                                                                                         | filename | largeUri | mediumUri | mime | previews                                                                                                                                                                                                              | previewsId            | size | smallUri | status  | thumbnailUri                                                                     | uri  | wideUri
-----------------------+--------------------+---------------+-------------------+------------------------------------------------------------------------------------------------------+----------+----------+-----------+------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------+------+----------+---------+----------------------------------------------------------------------------------+------+-----------------------------------------------------------------------------
  rev:gatech:b1lQRMggZ | c:gatech:-yo1Bzglb | 1406734273525 | u:gatech:gk1wOXop | <!DOCTYPE HTML><html><body>This is nice...<br><br>Another line of the text LOL<br><br></body></html> |     null |     null |      null | null | {"wideUri":"local:c/gatech/-y/o1/Bz/gl/-yo1Bzglb/previews/rev-gatech-b1lQRMggZ/wide.png","status":"done","total":2,"thumbnailUri":"local:c/gatech/-y/o1/Bz/gl/-yo1Bzglb/previews/rev-gatech-b1lQRMggZ/thumbnail.png"} |  rev:gatech:b1lQRMggZ | null |     null |    done | local:c/gatech/-y/o1/Bz/gl/-yo1Bzglb/previews/rev-gatech-b1lQRMggZ/thumbnail.png | null | local:c/gatech/-y/o1/Bz/gl/-yo1Bzglb/previews/rev-gatech-b1lQRMggZ/wide.png
  rev:gatech:ZyK3nflgZ | c:gatech:-yo1Bzglb | 1406734237632 | u:gatech:gk1wOXop |                                                                                                 null |     null |     null |      null | null |                                                                                                                                                                                        {"status":"ignored","total":0} | rev:gatech:bkgsyHGlx- | null |     null | ignored |                                                                             null | null |                                                                        null
  rev:gatech:WJDF2zxlW | c:gatech:-yo1Bzglb | 1406734232633 | u:gatech:gk1wOXop |                                                                                                 null |     null |     null |      null | null |                                                                                                                                                                                        {"status":"ignored","total":0} | rev:gatech:bkgsyHGlx- | null |     null | ignored |                                                                             null | null |                                                                        null
  rev:gatech:b1HU2fggb | c:gatech:-yo1Bzglb | 1406734227640 | u:gatech:gk1wOXop |                                                                                                 null |     null |     null |      null | null |                                                                                                                                                                                        {"status":"ignored","total":0} | rev:gatech:bkgsyHGlx- | null |     null | ignored |                                                                             null | null |                                                                        null
  rev:gatech:bJmX2Gxxb | c:gatech:-yo1Bzglb | 1406734222642 | u:gatech:gk1wOXop |                                                                                                 null |     null |     null |      null | null |                                                                                                                                                                                        {"status":"ignored","total":0} | rev:gatech:bkgsyHGlx- | null |     null | ignored |                                                                             null | null |                                                                        null
  rev:gatech:bkYojMgg- | c:gatech:-yo1Bzglb | 1406734210377 | u:gatech:gk1wOXop | <!DOCTYPE HTML><html><body>This is nice...<br><br>Another line of the text LOL<br><br></body></html> |     null |     null |      null | null | {"wideUri":"local:c/gatech/-y/o1/Bz/gl/-yo1Bzglb/previews/rev-gatech-bkYojMgg-/wide.png","status":"done","total":2,"thumbnailUri":"local:c/gatech/-y/o1/Bz/gl/-yo1Bzglb/previews/rev-gatech-bkYojMgg-/thumbnail.png"} |  rev:gatech:bkYojMgg- | null |     null |    done | local:c/gatech/-y/o1/Bz/gl/-yo1Bzglb/previews/rev-gatech-bkYojMgg-/thumbnail.png | null | local:c/gatech/-y/o1/Bz/gl/-yo1Bzglb/previews/rev-gatech-bkYojMgg-/wide.png
  rev:gatech:bk605MgxZ | c:gatech:-yo1Bzglb | 1406734190037 | u:gatech:gk1wOXop |                                                                                                 null |     null |     null |      null | null |                                                                                                                                                                                        {"status":"ignored","total":0} | rev:gatech:bkgsyHGlx- | null |     null | ignored |                                                                             null | null |                                                                        null
  rev:gatech:-ksjcMgx- | c:gatech:-yo1Bzglb | 1406734185038 | u:gatech:gk1wOXop |                                                                                                 null |     null |     null |      null | null |                                                                                                                                                                                        {"status":"ignored","total":0} | rev:gatech:bkgsyHGlx- | null |     null | ignored |                                                                             null | null |                                                                        null
  rev:gatech:-JYdqfgg- | c:gatech:-yo1Bzglb | 1406734180039 | u:gatech:gk1wOXop |                                                                                                 null |     null |     null |      null | null |                                                                                                                                                                                        {"status":"ignored","total":0} | rev:gatech:bkgsyHGlx- | null |     null | ignored |                                                                             null | null |                                                                        null
  rev:gatech:Z1PB9fee- | c:gatech:-yo1Bzglb | 1406734175031 | u:gatech:gk1wOXop |                                                                                                 null |     null |     null |      null | null |                                                                                                                                                                                        {"status":"ignored","total":0} | rev:gatech:bkgsyHGlx- | null |     null | ignored |                                                                             null | null |                                                                        null
  rev:gatech:WyeyOzeeb | c:gatech:-yo1Bzglb | 1406734113548 | u:gatech:gk1wOXop |                                                                                                 null |     null |     null |      null | null |                                                                                                                                                                                        {"status":"ignored","total":0} | rev:gatech:bkgsyHGlx- | null |     null | ignored |                                                                             null | null |                                                                        null
  rev:gatech:bkCivfxlb | c:gatech:-yo1Bzglb | 1406734108540 | u:gatech:gk1wOXop |                                                                                                 null |     null |     null |      null | null |                                                                                                                                                                                        {"status":"ignored","total":0} | rev:gatech:bkgsyHGlx- | null |     null | ignored |                                                                             null | null |                                                                        null
  rev:gatech:Wy3dPMxl- | c:gatech:-yo1Bzglb | 1406734103532 | u:gatech:gk1wOXop |                                                                                                 null |     null |     null |      null | null |                                                                                                                                                                                        {"status":"ignored","total":0} | rev:gatech:bkgsyHGlx- | null |     null | ignored |                                                                             null | null |                                                                        null
  rev:gatech:W15rDfxeb | c:gatech:-yo1Bzglb | 1406734098525 | u:gatech:gk1wOXop |                                                                                                 null |     null |     null |      null | null |                                                                                                                                                                                        {"status":"ignored","total":0} | rev:gatech:bkgsyHGlx- | null |     null | ignored |                                                                             null | null |                                                                        null
  rev:gatech:-kP-PzleW | c:gatech:-yo1Bzglb | 1406734091848 | u:gatech:gk1wOXop |                                                                                                 null |     null |     null |      null | null |                                                                                                                                                                                        {"status":"ignored","total":0} | rev:gatech:bkgsyHGlx- | null |     null | ignored |                                                                             null | null |                                                                        null
  rev:gatech:-kB0IzleW | c:gatech:-yo1Bzglb | 1406734086845 | u:gatech:gk1wOXop |                                                                                                 null |     null |     null |      null | null |                                                                                                                                                                                        {"status":"ignored","total":0} | rev:gatech:bkgsyHGlx- | null |     null | ignored |                                                                             null | null |                                                                        null
  rev:gatech:Z17s8GggZ | c:gatech:-yo1Bzglb | 1406734081850 | u:gatech:gk1wOXop |                                                                                                 null |     null |     null |      null | null |                                                                                                                                                                                        {"status":"ignored","total":0} | rev:gatech:bkgsyHGlx- | null |     null | ignored |                                                                             null | null |                                                                        null
  rev:gatech:-1bd8MegW | c:gatech:-yo1Bzglb | 1406734076830 | u:gatech:gk1wOXop |                                                                                                 null |     null |     null |      null | null |                                                                                                                                                                                        {"status":"ignored","total":0} | rev:gatech:bkgsyHGlx- | null |     null | ignored |                                                                             null | null |                                                                        null
  rev:gatech:ZykzUMxxb | c:gatech:-yo1Bzglb | 1406734067045 | u:gatech:gk1wOXop |                                     <!DOCTYPE HTML><html><body>This is nice...<br><br></body></html> |     null |     null |      null | null | {"wideUri":"local:c/gatech/-y/o1/Bz/gl/-yo1Bzglb/previews/rev-gatech-ZykzUMxxb/wide.png","status":"done","total":2,"thumbnailUri":"local:c/gatech/-y/o1/Bz/gl/-yo1Bzglb/previews/rev-gatech-ZykzUMxxb/thumbnail.png"} |  rev:gatech:ZykzUMxxb | null |     null |    done | local:c/gatech/-y/o1/Bz/gl/-yo1Bzglb/previews/rev-gatech-ZykzUMxxb/thumbnail.png | null | local:c/gatech/-y/o1/Bz/gl/-yo1Bzglb/previews/rev-gatech-ZykzUMxxb/wide.png
 rev:gatech:bkgsyHGlx- | c:gatech:-yo1Bzglb | 1406734037867 | u:gatech:gk1wOXop |                                                                                                 null |     null |     null |      null | null |                                                                                                                                                                                        {"status":"ignored","total":0} | rev:gatech:bkgsyHGlx- | null |     null | ignored |                                                                             null | null |                                                                        null

[mrvisser]

Document HTML was:

<!DOCTYPE HTML><html><body>This is nice...<br><br></body></html>

Not too complicated. My steps were:

1. Create an empty pad
2. Refreshed, and ensured it didn't create a new revision
3. Added: This is nice...<br>
4. Refreshed, and ensured it created a new revision
5. Tried to restore the initial (empty) revision
6. Got a timeout
7. Added <br>Another line of the text LOL
8. Refreshed, ensuring a new revision is created
9. Tried to restore the second (non-empty) revision
10. Got a timeout

I did an indeterministic number of attempts afterward (0-3 attempts maybe). But not as many times as we have blank revisions, that's almost certainly a result of the Nginx retries.

[nicolaasmatthijs]

Assigning to @simong for investigation

[nicolaasmatthijs]

@simong : Also, can you update the README instructions for the Etherpad installation as part of this PR?

[simong]

I think an exception was thrown that triggered the timeout, please validate that. However, our Express.js error handler should have caught that and then replied with a 500 code rather quickly on the response. If an exception caused this, why didn't our error handler catch it with its domain handler?

I don't think that's entirely right. Express error handler only catches errors that are thrown in the same tick as the route handler. For example, this will get caught:

app.get('/test', function(req, res) {
    throw new Error('error in same tick as route handler, should get caught');
});

This however, will not:

app.get('/test', function(req, res) {
    process.nextTick(function() {
        throw new Error('error in another tick as route handler, does NOT get caught');
    });
});

The error does get caught by the global node catch-all error handler (process.on('uncaughtException', ..)

[simong]

My steps were:

1. Create an empty pad
2. Refreshed, and ensured it didn't create a new revision

This would've created a revision with a null value for the etherpadHtml key.

1. Added: This is nice...
   
2. Refreshed, and ensured it created a new revision
3. Tried to restore the initial (empty) revision

This would try to restore the null html. When we call Etherpad.setHtml and eventually perform the cheerio.load(content) call, content will be null and cause cheerio to blow up.

I suppose we either need to either not generate revisions for empty pads or allow you to restore an empty pad to fix this. The cheerio.load call should still be wrapped in a try/catch.

This exception was thrown, that may have resulted in the timeout It certainly would've resulted in a timeout as the express error handler wouldn't've been able to catch it. Restoring the etherpad HTML happens after quite a few async calls.

Why did the request timeout? :) Same as above

[mrvisser]

I don't think that's entirely right. Express error handler only catches errors that are thrown in the same tick as the route handler.

This is correct, and makes the error handler entirely useless :( I thought it used domains..

The attempts to restore a non-null revisions did fail as well, but maybe after first trying the null revision it broke some state on the content item.

[simong]

PR submitted @ https://github.com/oaeproject/Hilary/pull/989

[simong]

As the hilary PR has been merged, this can now be closed