Cht-core: Getting 502s after submitting task; Tasks not cleared until refresh

[abbyad]

Testing in 2.10.0-alpha.4810, completing a task gives errors and the task is not cleared.

In the log you see the new report being saved followed by some 502s:

inbox.js:53 POST https://standard.app.medicmobile.org/medic/_changes?style=all_docs&feed=longpoll&heartbeat=10000&filter=_doc_ids&since=12689&limit=99 502 (Bad Gateway)
inbox.js:53 GET https://standard.app.medicmobile.org/medic/_design/medic/_rewrite 502 (Bad Gateway)
inbox.js:53 GET https://standard.app.medicmobile.org/medic/_local/VOTmYoGCCvv21sOHfbh08g%3D%3D? 502 (Bad Gateway)

The task-rules in question are here and the task generation should be immutable. This avoids a usual cause of tasks not clearing until refresh, but I may be mistaken in determining that in this case. Either way, the 502s seem problematic.

This is spawned from #3001 since it seems to be a different issue.

[garethbowen]

@abbyad 502 indicates a server error - it would be really useful to grab the api logs.

[abbyad]

I don't see any any errors in api logs (and can't export them all), but this is reproducible so can guide someone through steps to take a look.

[garethbowen]

This is really strange so it's worth looking into. Scheduling.

[garethbowen]

I'm not getting 502s but the task isn't being cleared.

[garethbowen]

Given that I can't reproduce the 502s and tasks clear for other configurations I'm reasonably sure this is a configuration issue.

@abbyad If you see the 502s again grab the API log, the nginx logs (access and error), the couchdb log, and anything else you can think of - there must be _something_ in one of them.

[abbyad]

I see reference to the 502s in the nginx access.log, but don't see anything else that I can make sense of in the other logs. I'll follow up over dm.

[abbyad]

Testing with a patient report (immunization_visit), it seems as though the 502s occur only when the default_responses transition is enabled. It leaves a trace in "transitions" but no other changes. I cannot get the 502 if that transition is disabled, yet can reproduce 100% of the time when that transition is enabled, both when the auto reply is set and removed for that form in app_settings.

[garethbowen]

There are some Document Update Conflicts in the medic-sentinel log (probably due to marking the report as read while transitions are running) but these shouldn't cause 502s. Unfortunately I can't see quite where these are coming from.

[garethbowen]

I can't find any evidence of the 502 in the access, couchdb, or api logs.

@abbyad When you reproduce this I need you to grab all the logs you can and include them here (or DM them if confidential). The access log will give me the timestamp to look for in the api, sentinel, and couch logs. You can also turn timestamps on in Chrome dev tools console.

[garethbowen]

We have logs!

nginx:

70.30.64.17 - - [21/Feb/2017:19:49:00 +0000] "POST /medic/_changes?style=all_docs&feed=longpoll&heartbeat=10000&filter=_doc_ids&since=55880&limit=99 HTTP/1.1" 502 575 "https://standard.app.medicmobile.org/medic/_design/medic/_rewrite/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36"
70.30.64.17 - - [21/Feb/2017:19:49:00 +0000] "GET /medic/_changes?include_docs=true&feed=longpoll&heartbeat=10000&since=55882&limit=25 HTTP/1.1" 502 575 "https://standard.app.medicmobile.org/medic/_design/medic/_rewrite/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36"
70.30.64.17 - - [21/Feb/2017:19:49:01 +0000] "GET / HTTP/1.1" 302 161 "https://standard.app.medicmobile.org/medic/_design/medic/_rewrite/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36"
70.30.64.17 - - [21/Feb/2017:19:49:01 +0000] "GET /medic/_design/medic/_rewrite HTTP/1.1" 502 575 "https://standard.app.medicmobile.org/medic/_design/medic/_rewrite/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36"
70.30.64.17 - - [21/Feb/2017:19:49:01 +0000] "GET /medic/_local/lHeFgXytyHd39R9dTCPz4A%3D%3D? HTTP/1.1" 502 575 "https://standard.app.medicmobile.org/medic/_design/medic/_rewrite/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36"

medic-api:

2017-02-21T19:48:59.746Z - info: 127.0.0.1 - - [21/Feb/2017:19:48:59 +0000] "GET /medic/_changes?include_docs=true&feed=longpoll&heartbeat=10000&since=55882&limit=25 HTTP/1.0" - - "https://standard.app.medicmobile.org/medic/_design/medic/_rewrite/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36"

2017-02-21T19:49:00.401Z - error: UNCAUGHT EXCEPTION!

2017-02-21T19:49:00.405Z - error: Server error:
 { [Error: write after end]
  domainEmitter: 
   { domain: 
      { domain: null,
        _events: [Object],
        _maxListeners: undefined,
        members: [] },
     _events: { prefinish: [Function: resOnFinish] },
     _maxListeners: undefined,
     output: [],
     outputEncodings: [],
     outputCallbacks: [],
     writable: true,
     _last: true,
     chunkedEncoding: false,
     shouldKeepAlive: false,
     useChunkedEncodingByDefault: false,
     sendDate: true,
     _removedHeader: {},
     _hasBody: true,
     _trailer: '',
     finished: true,
     _hangupClose: false,
     _headerSent: true,
     socket: null,
     connection: null,
     _header: 'HTTP/1.1 200 OK\r\nX-Powered-By: Express\r\nX-Accel-Buffering: no\r\nContent-Type: application/json\r\nDate: Tue, 21 Feb 2017 19:46:40 GMT\r\nConnection: close\r\n\r\n',
     _headers: 
      { 'x-powered-by': 'Express',
        'x-accel-buffering': 'no',
        'content-type': 'application/json' },
     _headerNames: 
      { 'x-powered-by': 'X-Powered-By',
        'x-accel-buffering': 'X-Accel-Buffering',
        'content-type': 'Content-Type' },
     req: 
      { _readableState: [Object],
        readable: false,
        domain: [Object],
        _events: [Object],
        _maxListeners: undefined,
        socket: [Object],
        connection: [Object],
        httpVersionMajor: 1,
        httpVersionMinor: 0,
        httpVersion: '1.0',
        complete: true,
        headers: [Object],
        rawHeaders: [Object],
        trailers: {},
        rawTrailers: [],
        _pendings: [],
        _pendingIndex: 0,
        upgrade: false,
        url: '/medic/_changes?style=all_docs&feed=longpoll&heartbeat=10000&filter=_doc_ids&since=55878&limit=100',
        method: 'POST',
        statusCode: null,
        statusMessage: null,
        client: [Object],
        _consuming: true,
        _dumped: false,
        next: [Function: next],
        baseUrl: '',
        originalUrl: '/medic/_changes?style=all_docs&feed=longpoll&heartbeat=10000&filter=_doc_ids&since=55878&limit=100',
        _parsedUrl: [Object],
        params: {},
        query: [Object],
        res: [Circular],
        _startAt: [Object],
        _startTime: Tue Feb 21 2017 19:46:29 GMT+0000 (UTC),
        _remoteAddress: '127.0.0.1',
        route: [Object],
        body: [Object],
        _body: true,
        length: undefined,
        read: [Function] },
     locals: {},
     _startAt: undefined,
     _startTime: undefined,
     statusMessage: 'OK',
     statusCode: 200 },
  domain: 
   { domain: null,
     _events: { error: [Function] },
     _maxListeners: undefined,
     members: [] },
  domainThrown: false }

2017-02-21T19:49:00.406Z - error: UNCAUGHT EXCEPTION!

2017-02-21T19:49:00.407Z - error: Server error:
 { [Error: Can't set headers after they are sent.]
  domain: 
   { domain: null,
     _events: { error: [Function] },
     _maxListeners: undefined,
     members: [] },
  domainThrown: true }

2017-02-21T19:49:00.407Z - error: UNCAUGHT EXCEPTION!

2017-02-21T19:49:00.407Z - error: Server error:
 { [Error: Can't set headers after they are sent.]
  domain: 
   { domain: null,
     _events: { error: [Function] },
     _maxListeners: undefined,
     members: [] },
  domainThrown: true }

2017-02-21T19:49:00.409Z - error: _http_outgoing.js:335
    throw new Error('Can\'t set headers after they are sent.');
          ^
Error: Can't set headers after they are sent.
    at ServerResponse.OutgoingMessage.setHeader (_http_outgoing.js:335:11)
    at ServerResponse.header (/srv/storage/gardener/data/working_dir/aHR0cDovL2xvY2FsaG9zdDo1OTg0L21lZGljL19kZXNpZ24vbWVkaWMvbWVkaWMtYXBp/node_modules/medic-api/node_modules/express/lib/response.js:719:10)
    at ServerResponse.send (/srv/storage/gardener/data/working_dir/aHR0cDovL2xvY2FsaG9zdDo1OTg0L21lZGljL19kZXNpZ24vbWVkaWMvbWVkaWMtYXBp/node_modules/medic-api/node_modules/express/lib/response.js:164:12)
    at ServerResponse.json (/srv/storage/gardener/data/working_dir/aHR0cDovL2xvY2FsaG9zdDo1OTg0L21lZGljL19kZXNpZ24vbWVkaWMvbWVkaWMtYXBp/node_modules/medic-api/node_modules/express/lib/response.js:250:15)
    at writeJSON (/srv/storage/gardener/data/working_dir/aHR0cDovL2xvY2FsaG9zdDo1OTg0L21lZGljL19kZXNpZ24vbWVkaWMvbWVkaWMtYXBp/node_modules/medic-api/server-utils.js:12:7)
    at respond (/srv/storage/gardener/data/working_dir/aHR0cDovL2xvY2FsaG9zdDo1OTg0L21lZGljL19kZXNpZ24vbWVkaWMvbWVkaWMtYXBp/node_modules/medic-api/server-utils.js:21:12)
    at Object.module.exports.serverError (/srv/storage/gardener/data/working_dir/aHR0cDovL2xvY2FsaG9zdDo1OTg0L21lZGljL19kZXNpZ24vbWVkaWMvbWVkaWMtYXBp/node_modules/medic-api/server-utils.js:83:5)
    at Domain.<anonymous> (/srv/storage/gardener/data/working_dir/aHR0cDovL2xvY2FsaG9zdDo1OTg0L21lZGljL19kZXNpZ24vbWVkaWMvbWVkaWMtYXBp/node_modules/medic-api/server.js:66:17)
    at Domain.emit (events.js:107:17)
    at ServerResponse.emit (events.js:83:19)

2017-02-21T19:49:04.207Z - info: DDoc extraction completed successfully

medic-sentinel:

70.30.64.17 - - [21/Feb/2017:19:49:00 +0000] "POST /medic/_changes?style=all_docs&feed=longpoll&heartbeat=10000&filter=_doc_ids&since=55880&limit=99 HTTP/1.1" 502 575 "https://standard.app.medicmobile.org/medic/_design/medic/_rewrite/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36"
70.30.64.17 - - [21/Feb/2017:19:49:00 +0000] "GET /medic/_changes?include_docs=true&feed=longpoll&heartbeat=10000&since=55882&limit=25 HTTP/1.1" 502 575 "https://standard.app.medicmobile.org/medic/_design/medic/_rewrite/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36"
70.30.64.17 - - [21/Feb/2017:19:49:01 +0000] "GET / HTTP/1.1" 302 161 "https://standard.app.medicmobile.org/medic/_design/medic/_rewrite/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36"
70.30.64.17 - - [21/Feb/2017:19:49:01 +0000] "GET /medic/_design/medic/_rewrite HTTP/1.1" 502 575 "https://standard.app.medicmobile.org/medic/_design/medic/_rewrite/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36"
70.30.64.17 - - [21/Feb/2017:19:49:01 +0000] "GET /medic/_local/lHeFgXytyHd39R9dTCPz4A%3D%3D? HTTP/1.1" 502 575 "https://standard.app.medicmobile.org/medic/_design/medic/_rewrite/" "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36"

[garethbowen]

Alrightie - I think this is some sort of race condition. In the changes handler we have a listener waiting for couchdb changes and writing them back to the client. In this case, if you have this transition enabled, the changes listener fires twice in quick succession. Then the handler tries to write the second change to a response that's already ended. Adding a check for res.finished before trying to write solves the 502s. Unfortunately the tasks still don't update so it looks like they're separate issues. I'll have a look at the tasks not disappearing next...

[garethbowen]

CR please @estellecomment : https://github.com/medic/medic-api/pull/123 and https://github.com/medic/medic-webapp/pull/3147

[abbyad]

Works like a charm, no 502s and tasks disappear. Moving to Ready.