A very unique problem faced when calling an endpoint in a Node project running a hapijs server. When the endpoint is hit directly, there aren't any problems.
But when we hit it from a gohaqd instance, we get:
170809/044343.745, [log,connection,client,error] message: write EPIPE, stack: Error: write EPIPE at exports._errnoException (util.js:1018:11) at WriteWrap.afterWrite (net.js:800:14)
and more often
170809/040643.248, [log,connection,client,error] message: read ECONNRESET, stack: Error: read ECONNRESET at exports._errnoException (util.js:1018:11) at TCP.onread (net.js:568:26)
I know the error codes mean that somewhere, the app is trying to write to a closed connection. But for the life of me I can't figure out where. The logs themselves are from hapijs, this line if I'm not wrong, but couldn't figure out why node was trying to write to a closed connection, anyway.
Mind, there's no side-effect from this. The app runs fine :|
We turned on NODE_DEBUG=http, net and got the following results. The only thing that stuck out when reading these is that in the second the write ret = true line appears twice, if that means anything. Can someone help me understand what it means?
The first one is when hitting the endpoint directly:
NET 422: onconnection
NET 422: _read
NET 422: Socket._read readStart
HTTP 422: SERVER new http connection
HTTP 422: SERVER socketOnParserExecute 333
NET 422: onread 775
NET 422: got data
NET 422: _read
HTTP 422: call onSocket 0 0
HTTP 422: createConnection api.mixpanel.com:80: { servername: 'api.mixpanel.com',
path: null,
headers: {},
port: 80,
host: 'api.mixpanel.com',
_agentKey: 'api.mixpanel.com:80:' }
NET 422: createConnection [ { servername: 'api.mixpanel.com',
path: null,
headers: {},
port: 80,
host: 'api.mixpanel.com',
_agentKey: 'api.mixpanel.com:80:',
encoding: null },
[Function: oncreate] ]
NET 422: pipe false null
NET 422: connect: find host api.mixpanel.com
NET 422: connect: dns options { family: undefined, hints: 32 }
HTTP 422: sockets api.mixpanel.com:80: 1
HTTP 422: outgoing message end.
HTTP 422: call onSocket 1 0
HTTP 422: createConnection api.mixpanel.com:80: { servername: 'api.mixpanel.com',
path: null,
headers: {},
port: 80,
host: 'api.mixpanel.com',
_agentKey: 'api.mixpanel.com:80:' }
NET 422: createConnection [ { servername: 'api.mixpanel.com',
path: null,
headers: {},
port: 80,
host: 'api.mixpanel.com',
_agentKey: 'api.mixpanel.com:80:',
encoding: null },
[Function: oncreate] ]
NET 422: pipe false null
NET 422: connect: find host api.mixpanel.com
NET 422: connect: dns options { family: undefined, hints: 32 }
HTTP 422: sockets api.mixpanel.com:80: 2
HTTP 422: outgoing message end.
HTTP 422: call onSocket 2 0
HTTP 422: createConnection api.mixpanel.com:80: { servername: 'api.mixpanel.com',
path: null,
headers: {},
port: 80,
host: 'api.mixpanel.com',
_agentKey: 'api.mixpanel.com:80:' }
NET 422: createConnection [ { servername: 'api.mixpanel.com',
path: null,
headers: {},
port: 80,
host: 'api.mixpanel.com',
_agentKey: 'api.mixpanel.com:80:',
encoding: null },
[Function: oncreate] ]
NET 422: pipe false null
NET 422: connect: find host api.mixpanel.com
NET 422: connect: dns options { family: undefined, hints: 32 }
HTTP 422: sockets api.mixpanel.com:80: 3
HTTP 422: outgoing message end.
NET 422: _read
NET 422: _read wait for connection
NET 422: _read
NET 422: _read wait for connection
NET 422: _read
NET 422: _read wait for connection
NET 422: afterConnect
NET 422: _read
NET 422: Socket._read readStart
NET 422: afterConnect
NET 422: _read
NET 422: Socket._read readStart
NET 422: afterConnect
NET 422: _read
NET 422: Socket._read readStart
NET 422: onread 438
NET 422: got data
HTTP 422: AGENT incoming response!
HTTP 422: AGENT isHeadResponse false
NET 422: _read
HTTP 422: AGENT socket.destroySoon()
NET 422: onSocketFinish
NET 422: oSF: not ended, call shutdown()
NET 422: destroy undefined
NET 422: destroy
NET 422: close
NET 422: close handle
NET 422: afterShutdown destroyed=true ReadableState {
objectMode: false,
highWaterMark: 16384,
buffer: BufferList { head: null, tail: null, length: 0 },
length: 0,
pipes: null,
pipesCount: 0,
flowing: true,
ended: false,
endEmitted: false,
reading: true,
sync: false,
needReadable: true,
emittedReadable: false,
readableListening: false,
resumeScheduled: false,
defaultEncoding: 'utf8',
ranOut: false,
awaitDrain: 0,
readingMore: false,
decoder: null,
encoding: null }
NET 422: emit close
HTTP 422: CLIENT socket onClose
HTTP 422: removeSocket api.mixpanel.com:80: writable: false
HTTP 422: HTTP socket close
NET 422: onread 438
NET 422: got data
HTTP 422: AGENT incoming response!
HTTP 422: AGENT isHeadResponse false
NET 422: _read
HTTP 422: AGENT socket.destroySoon()
NET 422: onSocketFinish
NET 422: oSF: not ended, call shutdown()
NET 422: destroy undefined
NET 422: destroy
NET 422: close
NET 422: close handle
NET 422: onread 486
NET 422: got data
HTTP 422: AGENT incoming response!
HTTP 422: AGENT isHeadResponse false
NET 422: _read
HTTP 422: AGENT socket.destroySoon()
NET 422: onSocketFinish
NET 422: oSF: not ended, call shutdown()
NET 422: destroy undefined
NET 422: destroy
NET 422: close
NET 422: close handle
NET 422: afterShutdown destroyed=true ReadableState {
objectMode: false,
highWaterMark: 16384,
buffer: BufferList { head: null, tail: null, length: 0 },
length: 0,
pipes: null,
pipesCount: 0,
flowing: true,
ended: false,
endEmitted: false,
reading: true,
sync: false,
needReadable: true,
emittedReadable: false,
readableListening: false,
resumeScheduled: false,
defaultEncoding: 'utf8',
ranOut: false,
awaitDrain: 0,
readingMore: false,
decoder: null,
encoding: null }
NET 422: emit close
HTTP 422: CLIENT socket onClose
HTTP 422: removeSocket api.mixpanel.com:80: writable: false
HTTP 422: HTTP socket close
NET 422: afterShutdown destroyed=true ReadableState {
objectMode: false,
highWaterMark: 16384,
buffer: BufferList { head: null, tail: null, length: 0 },
length: 0,
pipes: null,
pipesCount: 0,
flowing: true,
ended: false,
endEmitted: false,
reading: true,
sync: false,
needReadable: true,
emittedReadable: false,
readableListening: false,
resumeScheduled: false,
defaultEncoding: 'utf8',
ranOut: false,
awaitDrain: 0,
readingMore: false,
decoder: null,
encoding: null }
NET 422: emit close
HTTP 422: CLIENT socket onClose
HTTP 422: removeSocket api.mixpanel.com:80: writable: false
HTTP 422: HTTP socket close
HTTP 422: write ret = true
HTTP 422: outgoing message end.
NET 422: onread -4095
NET 422: EOF
NET 422: onSocketEnd ReadableState {
objectMode: false,
highWaterMark: 16384,
buffer: BufferList { head: null, tail: null, length: 0 },
length: 0,
pipes: null,
pipesCount: 0,
flowing: true,
ended: true,
endEmitted: false,
reading: false,
sync: false,
needReadable: false,
emittedReadable: false,
readableListening: false,
resumeScheduled: false,
defaultEncoding: 'utf8',
ranOut: false,
awaitDrain: 0,
readingMore: false,
decoder: null,
encoding: null }
NET 422: onSocketFinish
NET 422: oSF: ended, destroy ReadableState {
objectMode: false,
highWaterMark: 16384,
buffer: BufferList { head: null, tail: null, length: 0 },
length: 0,
pipes: null,
pipesCount: 0,
flowing: true,
ended: true,
endEmitted: true,
reading: false,
sync: false,
needReadable: false,
emittedReadable: false,
readableListening: false,
resumeScheduled: false,
defaultEncoding: 'utf8',
ranOut: false,
awaitDrain: 0,
readingMore: false,
decoder: null,
encoding: null }
NET 422: destroy undefined
NET 422: destroy
NET 422: close
NET 422: close handle
NET 422: has server
NET 422: SERVER _emitCloseIfDrained
NET 422: SERVER handle? true connections? 15
NET 422: emit close
HTTP 422: server socket close
The next one is when the endpoint is hit from gohaqd, which is a go client.
NET 422: onread 405
NET 422: got data
NET 422: _read
NET 422: onconnection
NET 422: _read
NET 422: Socket._read readStart
HTTP 422: SERVER new http connection
HTTP 422: SERVER socketOnParserExecute 325
NET 422: onread 775
NET 422: got data
NET 422: _read
HTTP 422: call onSocket 0 0
HTTP 422: createConnection api.mixpanel.com:80: { servername: 'api.mixpanel.com',
path: null,
headers: {},
port: 80,
host: 'api.mixpanel.com',
_agentKey: 'api.mixpanel.com:80:' }
NET 422: createConnection [ { servername: 'api.mixpanel.com',
path: null,
headers: {},
port: 80,
host: 'api.mixpanel.com',
_agentKey: 'api.mixpanel.com:80:',
encoding: null },
[Function: oncreate] ]
NET 422: pipe false null
NET 422: connect: find host api.mixpanel.com
NET 422: connect: dns options { family: undefined, hints: 32 }
HTTP 422: sockets api.mixpanel.com:80: 1
HTTP 422: outgoing message end.
HTTP 422: call onSocket 1 0
HTTP 422: createConnection api.mixpanel.com:80: { servername: 'api.mixpanel.com',
path: null,
headers: {},
port: 80,
host: 'api.mixpanel.com',
_agentKey: 'api.mixpanel.com:80:' }
NET 422: createConnection [ { servername: 'api.mixpanel.com',
path: null,
headers: {},
port: 80,
host: 'api.mixpanel.com',
_agentKey: 'api.mixpanel.com:80:',
encoding: null },
[Function: oncreate] ]
NET 422: pipe false null
NET 422: connect: find host api.mixpanel.com
NET 422: connect: dns options { family: undefined, hints: 32 }
HTTP 422: sockets api.mixpanel.com:80: 2
HTTP 422: outgoing message end.
HTTP 422: call onSocket 2 0
HTTP 422: createConnection api.mixpanel.com:80: { servername: 'api.mixpanel.com',
path: null,
headers: {},
port: 80,
host: 'api.mixpanel.com',
_agentKey: 'api.mixpanel.com:80:' }
NET 422: createConnection [ { servername: 'api.mixpanel.com',
path: null,
headers: {},
port: 80,
host: 'api.mixpanel.com',
_agentKey: 'api.mixpanel.com:80:',
encoding: null },
[Function: oncreate] ]
NET 422: pipe false null
NET 422: connect: find host api.mixpanel.com
NET 422: connect: dns options { family: undefined, hints: 32 }
HTTP 422: sockets api.mixpanel.com:80: 3
HTTP 422: outgoing message end.
NET 422: _read
NET 422: _read wait for connection
NET 422: _read
NET 422: _read wait for connection
NET 422: _read
NET 422: _read wait for connection
NET 422: afterConnect
NET 422: _read
NET 422: Socket._read readStart
NET 422: afterConnect
NET 422: _read
NET 422: Socket._read readStart
NET 422: afterConnect
NET 422: _read
NET 422: Socket._read readStart
NET 422: onread 438
NET 422: got data
HTTP 422: AGENT incoming response!
HTTP 422: AGENT isHeadResponse false
NET 422: _read
HTTP 422: AGENT socket.destroySoon()
NET 422: onSocketFinish
NET 422: oSF: not ended, call shutdown()
NET 422: destroy undefined
NET 422: destroy
NET 422: close
NET 422: close handle
NET 422: afterShutdown destroyed=true ReadableState {
objectMode: false,
highWaterMark: 16384,
buffer: BufferList { head: null, tail: null, length: 0 },
length: 0,
pipes: null,
pipesCount: 0,
flowing: true,
ended: false,
endEmitted: false,
reading: true,
sync: false,
needReadable: true,
emittedReadable: false,
readableListening: false,
resumeScheduled: false,
defaultEncoding: 'utf8',
ranOut: false,
awaitDrain: 0,
readingMore: false,
decoder: null,
encoding: null }
NET 422: emit close
HTTP 422: CLIENT socket onClose
HTTP 422: removeSocket api.mixpanel.com:80: writable: false
HTTP 422: HTTP socket close
NET 422: onread 438
NET 422: got data
HTTP 422: AGENT incoming response!
HTTP 422: AGENT isHeadResponse false
NET 422: _read
HTTP 422: AGENT socket.destroySoon()
NET 422: onSocketFinish
NET 422: oSF: not ended, call shutdown()
NET 422: destroy undefined
NET 422: destroy
NET 422: close
NET 422: close handle
NET 422: onread 486
NET 422: got data
HTTP 422: AGENT incoming response!
HTTP 422: AGENT isHeadResponse false
NET 422: _read
HTTP 422: AGENT socket.destroySoon()
NET 422: onSocketFinish
NET 422: oSF: not ended, call shutdown()
NET 422: destroy undefined
NET 422: destroy
NET 422: close
NET 422: close handle
NET 422: afterShutdown destroyed=true ReadableState {
objectMode: false,
highWaterMark: 16384,
buffer: BufferList { head: null, tail: null, length: 0 },
length: 0,
pipes: null,
pipesCount: 0,
flowing: true,
ended: false,
endEmitted: false,
reading: true,
sync: false,
needReadable: true,
emittedReadable: false,
readableListening: false,
resumeScheduled: false,
defaultEncoding: 'utf8',
ranOut: false,
awaitDrain: 0,
readingMore: false,
decoder: null,
encoding: null }
NET 422: emit close
HTTP 422: CLIENT socket onClose
HTTP 422: removeSocket api.mixpanel.com:80: writable: false
HTTP 422: HTTP socket close
NET 422: afterShutdown destroyed=true ReadableState {
objectMode: false,
highWaterMark: 16384,
buffer: BufferList { head: null, tail: null, length: 0 },
length: 0,
pipes: null,
pipesCount: 0,
flowing: true,
ended: false,
endEmitted: false,
reading: true,
sync: false,
needReadable: true,
emittedReadable: false,
readableListening: false,
resumeScheduled: false,
defaultEncoding: 'utf8',
ranOut: false,
awaitDrain: 0,
readingMore: false,
decoder: null,
encoding: null }
NET 422: emit close
HTTP 422: CLIENT socket onClose
HTTP 422: removeSocket api.mixpanel.com:80: writable: false
HTTP 422: HTTP socket close
HTTP 422: write ret = true
NET 422: afterWrite 0
NET 422: afterWrite call cb
HTTP 422: write ret = true
HTTP 422: outgoing message end.
NET 422: onread -4095
NET 422: EOF
NET 422: onSocketEnd ReadableState {
objectMode: false,
highWaterMark: 16384,
buffer: BufferList { head: null, tail: null, length: 0 },
length: 0,
pipes: null,
pipesCount: 0,
flowing: true,
ended: true,
endEmitted: false,
reading: false,
sync: false,
needReadable: false,
emittedReadable: false,
readableListening: false,
resumeScheduled: false,
defaultEncoding: 'utf8',
ranOut: false,
awaitDrain: 0,
readingMore: false,
decoder: null,
encoding: null }
NET 422: afterWrite 0
NET 422: afterWrite call cb
NET 422: afterWrite -32
NET 422: write failure { Error: write EPIPE
at exports._errnoException (util.js:1018:11)
at WriteWrap.afterWrite (net.js:800:14) code: 'EPIPE', errno: 'EPIPE', syscall: 'write' }
NET 422: destroy
NET 422: close
NET 422: close handle
170809/101228.947, [log,connection,client,error] message: write EPIPE, stack: Error: write EPIPE
at exports._errnoException (util.js:1018:11)
at WriteWrap.afterWrite (net.js:800:14)
NET 422: has server
NET 422: SERVER _emitCloseIfDrained
NET 422: SERVER handle? true connections? 15
NET 422: emit close
HTTP 422: server socket close
The go code that calls this:
// Sends a POST request to consumption endpoint with the SQS message as body
func sendMessageToURL(msg string) bool {
var resp *http.Response
var err error
endpoint := url
if endpoint == "" {
m := make(map[string]string)
err := json.Unmarshal([]byte(msg), &m)
if err != nil {
log.Printf("Unable to parse JSON message to get the URL: %s", msg)
return false
}
endpoint = m["url"]
if endpoint == "" {
log.Printf("No 'url' field found in JSON message: %s", msg)
return false
}
}
for {
resp, err = httpClient.Post(endpoint, "application/json", bytes.NewBuffer([]byte(msg)))
if err == nil {
break
}
log.Printf("Error hitting endpoint, retrying after 1 second... Error: %s", err.Error())
time.Sleep(time.Second)
}
defer resp.Body.Close()
// return true only if response is 200 OK
if resp.StatusCode != 200 {
bodyBytes, _ := ioutil.ReadAll(resp.Body)
log.Printf("Error: Non OK response: %s Status Code: '%s' for sent message: '%s'", string(bodyBytes), resp.Status, msg)
return false
}
return true
}