[ERR_STREAM_DESTROYED] seems sharedb is not closing connections

[sionzee]

Hey! I just upgraded to teamwork streamer.

ShareDb: 1.0.0-beta.21
sharedb-mongo: 1.0.0-beta.8
reconnecting-websocket: 4.1.10
@teamwork/websocket-json-stream: 2.0.0
rich-text: 3.1.0
ws: 6.2.1

node: 11.13.0
npm: 6.9.0

When I open page, everything is working right. Submitting op works without issues. Then I refresh the page and after first submitOp it throws an error.

Error what is crashing node server:

Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
    at doWrite (_stream_writable.js:411:19)
    at writeOrBuffer (_stream_writable.js:399:5)
    at WebSocketJSONStream.Writable.write (_stream_writable.js:299:11)
    at Agent.send (/projects/alganep/server/node_modules/sharedb/lib/agent.js:165:15)
    at Agent._sendOp (/projects/alganep/server/node_modules/sharedb/lib/agent.js:181:8)
    at OpStream.<anonymous> (/projects/alganep/server/node_modules/sharedb/lib/agent.js:103:11)
    at OpStream.emit (events.js:193:13)
    at addChunk (_stream_readable.js:296:12)
    at readableAddChunk (_stream_readable.js:277:11)
    at OpStream.Readable.push (_stream_readable.js:232:10)

Last data what reached server before crash (immediately after it)

bubbles: false
cancelBubble: false
cancelable: false
composed: false
currentTarget: WebSocket {__zone_symbol__openfalse: null, __zone_symbol__closefalse: null, __zone_symbol__messagefalse: null, __zone_symbol__errorfalse: null, url: "ws://alganep:7000/", …}
data: "{"src":"1c7ce151b76c9abff41d499afc4640db","seq":1,"v":85,"a":"op","c":"texts","d":"17435_Tester"}"
defaultPrevented: false
eventPhase: 0
isTrusted: true
lastEventId: ""
origin: "ws://alganep:7000"
path: []
ports: []
returnValue: true
source: null
srcElement: WebSocket {__zone_symbol__openfalse: null, __zone_symbol__closefalse: null, __zone_symbol__messagefalse: null, __zone_symbol__errorfalse: null, url: "ws://alganep:7000/", …}
target: WebSocket {__zone_symbol__openfalse: null, __zone_symbol__closefalse: null, __zone_symbol__messagefalse: null, __zone_symbol__errorfalse: null, url: "ws://alganep:7000/", …}
timeStamp: 11002.040000050329
type: "message"
userActivation: null
decoded: (...)
deepCopy: (...)
encoded: (...)
__proto__: MessageEvent
index.js?9e40:25 

UPDATE

I find out for every refresh is error duplicated.
So when I open page first time then the error comes only once.
When I refresh the page 10 times and let it connect everytime to ShareDb. Then the error is printed 10 times.

Seems like memory-leak?

I attached listener for stream#close and it is called everytime.
eg.:

// Connect any incoming WebSocket connection to ShareDB
	const webSocket = new WebSocket.Server({server: server})
	webSocket.on("connection", function (ws, req) {
		console.warn("Incoming websocket connection")
		const stream = new WebSocketJSONStream(ws)
		stream.on('error', error => {
			console.log("----------------------------------------")
			console.log(error)
		})
		stream.on("data", message => {
			console.log("data", message)
		})
		stream.on("close", () => {
			console.log("stream closed...")
		})
		sharedb.listen(stream)
	})

[curran]

I'm curious, if you swap out @teamwork/websocket-json-stream for websocket-json-stream, does the error still occur?

[sionzee]

I end up with using custom json stream and everything works right now. I also moved to SockJs. But it is denitely teamwork issue.

[gkubisa]

ShareDB is not cleaning up old connections in this case.

It would be possible to add a workaround in @teamwork/websocket-json-stream: add this.emit('end') just before this.destroy(). It does not feel right to me though... when a client disconnects, the communication medium (WebSocket connection) is forcefully destroyed and a close event is emitted as expected. The end event is not appropriate in this case because it only says that the client is not going to emit any more data events but it does not in itself say anything about the writable part of the Duplex stream - the server should still be able to send more data to the client, if it wants.

A better fix would be to update ShareDB to clean up a connection when a close event is received. It would surely be more reliable. I'll create a PR soon.

[curran]

Thanks @gkubisa for your insights! Are you saying the ShareDB implementation should look something like this?

function cleanup() {
  agent.backend.agentsCount--;
  if (!agent.stream.isServer) agent.backend.remoteAgentsCount--;
  agent._cleanup();
}
this.stream.on('end', cleanup);
this.stream.on('close', cleanup);  // <------------- this would be the new part

For now my workaround is to use the original websocket-json-stream package, which does not suffer from this error (because it does emit end when it closes).

[gkubisa]

Yes, the general idea is good, however, your code will reduce the agent counts twice for streams which emit both end and close events.

[curran]

I cleaned up the solution in #283 . Thanks for reviewing!

[ericyhwang]

Curran's fix for this is published in [email protected]

[curran]

Hooray! Thanks @ericyhwang

[curran]

FWIW I'm still seeing this error pop up. This seems odd as the fix has been released, and I'm definitely using a version of ShareDB that contains the fix.

  "dependencies": {
    "@teamwork/sharedb": "^3.1.0",
    "@teamwork/websocket-json-stream": "^2.0.0",
    ...

Error I'm seeing:

WebSocket stream error: Cannot call write after a stream was destroyed

I'm using Webpack dev server which is doing automatic reloading all the time, which may or may not be related to this.

[gkubisa]

@curran , could you provide a full stack trace?

[curran]

Realized this was coming from my code here:

    // Prevent server crashes on errors.
    stream.on('error', error => {
      console.log('WebSocket stream error: ' + error.message);
    });

Removing that, here's the full stack trace:

Error [ERR_STREAM_DESTROYED]: Cannot call write after a stream was destroyed
    at doWrite (_stream_writable.js:413:19)
    at writeOrBuffer (_stream_writable.js:401:5)
    at WebSocketJSONStream.Writable.write (_stream_writable.js:301:11)
    at Agent.send (/home/curran/repos/vizhub/packages/serverGateways/node_modules/@teamwork/sharedb/lib/agent.js:175:15)
    at Agent._sendOp (/home/curran/repos/vizhub/packages/serverGateways/node_modules/@teamwork/sharedb/lib/agent.js:191:8)
    at OpStream.<anonymous> (/home/curran/repos/vizhub/packages/serverGateways/node_modules/@teamwork/sharedb/lib/agent.js:111:11)
    at OpStream.emit (events.js:196:13)
    at OpStream.EventEmitter.emit (domain.js:471:20)
    at addChunk (_stream_readable.js:290:12)
    at readableAddChunk (_stream_readable.js:271:11)
Emitted 'error' event at:
    at errorOrDestroy (internal/streams/destroy.js:107:12)
    at onwriteError (_stream_writable.js:432:5)
    at onwrite (_stream_writable.js:459:5)
    at doWrite (_stream_writable.js:413:11)
    at writeOrBuffer (_stream_writable.js:401:5)
    [... lines matching original stack trace ...]
    at OpStream.emit (events.js:196:13)

[curran]

Wait a minute - I was confused about which package was importing ShareDB, and the package in the stack trace was using "@teamwork/sharedb": "^2.0.1". Let me try upgrading it there..

[curran]

The error is gone after upgrading. Sorry for the false alarm!

Thank you @gkubisa for your willingness to help here.