Receiving invalid stream id

[nkzawa]

Receiving invalid stream id

[nkzawa]

Could you post a simple example which I can reproduce the problem?

[peteruithoven]

I'm also getting this error, but only sometimes. This last part makes it very hard to debug, or to make a example.

I do have some logs. cloud:ws:StreamManager push or cloud:ws:StreamManager _read are called when the push or push method are called on a outgoing socket.io-stream.

  socket.io-stream:socket read: "b1534aca-180e-465f-8b26-d25d64b2ab12" +1ms
  socket.io-stream:socket write: "285d89ea-eb69-4579-86cc-53aa827a0d2c" +3ms
  cloud:ws:StreamManager push:  +4ms 55005c2b7a1c945b87bfa9a7-webcam/285d89ea-eb69-4579-86cc-53aa827a0d2c
  cloud:ws:StreamManager _read:  +0ms 55005c2b7a1c945b87bfa9a7-webcam/285d89ea-eb69-4579-86cc-53aa827a0d2c
  socket.io-stream:socket read: "b1534aca-180e-465f-8b26-d25d64b2ab12" +2ms
  socket.io-stream:socket write: "285d89ea-eb69-4579-86cc-53aa827a0d2c" +1ms
  cloud:ws:StreamManager push:  +3ms 55005c2b7a1c945b87bfa9a7-webcam/285d89ea-eb69-4579-86cc-53aa827a0d2c
  cloud:ws:StreamManager _read:  +0ms 55005c2b7a1c945b87bfa9a7-webcam/285d89ea-eb69-4579-86cc-53aa827a0d2c
  socket.io-stream:socket end: "285d89ea-eb69-4579-86cc-53aa827a0d2c" +1ms
  cloud:ws:StreamManager push:  +1ms 55005c2b7a1c945b87bfa9a7-webcam/285d89ea-eb69-4579-86cc-53aa827a0d2c
  socket.io-stream:socket error: "285d89ea-eb69-4579-86cc-53aa827a0d2c", "invalid stream id" +0ms
  socket.io-stream:iostream destroy +0ms
  socket.io-stream:iostream clean up +0ms
  cloud:ws:StreamManager error:  +0ms 55005c2b7a1c945b87bfa9a7-webcam/285d89ea-eb69-4579-86cc-53aa827a0d2c { [Error: invalid stream id] remote: true }
  socket.io-stream:iostream destroy +0ms
  socket.io-stream:iostream already destroyed +0ms

It looks like I'm getting this error after the end event.

I also notice it logs an error when running the first unit test:

$ DEBUG=socket.io-stream* mocha --require test/support/server.js
  socket.io-stream
  socket.io-stream:socket sending new streams +0ms
  socket.io-stream:socket sending new streams +2ms
  socket.io-stream:socket new streams +6ms
  socket.io-stream:socket new streams +101ms
  socket.io-stream:socket read: "41a0e462-d373-4a38-90fe-af00e30cf504" +2ms
  socket.io-stream:socket read: "fe90186d-6f0c-4d0f-9d01-1b59e57cfb3c" +2ms
  socket.io-stream:socket write: "41a0e462-d373-4a38-90fe-af00e30cf504" +2ms
  socket.io-stream:socket read: "41a0e462-d373-4a38-90fe-af00e30cf504" +2ms
  socket.io-stream:socket write: "fe90186d-6f0c-4d0f-9d01-1b59e57cfb3c" +2ms
  socket.io-stream:socket read: "fe90186d-6f0c-4d0f-9d01-1b59e57cfb3c" +2ms
  socket.io-stream:socket write: "41a0e462-d373-4a38-90fe-af00e30cf504" +1ms
  socket.io-stream:socket read: "41a0e462-d373-4a38-90fe-af00e30cf504" +0ms
  socket.io-stream:socket write: "fe90186d-6f0c-4d0f-9d01-1b59e57cfb3c" +5ms
  socket.io-stream:socket read: "fe90186d-6f0c-4d0f-9d01-1b59e57cfb3c" +2ms
  socket.io-stream:socket write: "41a0e462-d373-4a38-90fe-af00e30cf504" +0ms
  socket.io-stream:socket read: "41a0e462-d373-4a38-90fe-af00e30cf504" +1ms
  socket.io-stream:socket write: "fe90186d-6f0c-4d0f-9d01-1b59e57cfb3c" +4ms
  socket.io-stream:iostream _onfinish +1ms
  socket.io-stream:iostream _onfinish: not ended +0ms
  socket.io-stream:iostream _onend +0ms
  socket.io-stream:iostream _onend: [object Object] +0ms
  socket.io-stream:iostream destroy +0ms
  socket.io-stream:iostream clean up +0ms
  socket.io-stream:socket read: "fe90186d-6f0c-4d0f-9d01-1b59e57cfb3c" +1ms
  socket.io-stream:socket end: "41a0e462-d373-4a38-90fe-af00e30cf504" +0ms
  socket.io-stream:iostream _onend +0ms
  socket.io-stream:iostream _onend: not finished +0ms
  socket.io-stream:iostream _onfinish +0ms
  socket.io-stream:iostream _onfinish: ended, destroy [object Object] +0ms
  socket.io-stream:iostream destroy +0ms
  socket.io-stream:iostream clean up +0ms
  socket.io-stream:iostream _onfinish +1ms
  socket.io-stream:iostream _onfinish: not ended +0ms
  socket.io-stream:iostream _onend +0ms
  socket.io-stream:iostream _onend: [object Object] +0ms
  socket.io-stream:iostream destroy +0ms
  socket.io-stream:iostream clean up +0ms
  socket.io-stream:socket end: "41a0e462-d373-4a38-90fe-af00e30cf504" +0ms
  socket.io-stream:socket end: "fe90186d-6f0c-4d0f-9d01-1b59e57cfb3c" +0ms
  socket.io-stream:iostream _onend +0ms
  socket.io-stream:iostream _onend: not finished +0ms
  socket.io-stream:iostream _onfinish +0ms
  socket.io-stream:iostream _onfinish: ended, destroy [object Object] +0ms
  socket.io-stream:iostream destroy +0ms
  socket.io-stream:iostream clean up +0ms
  socket.io-stream:socket error: "41a0e462-d373-4a38-90fe-af00e30cf504", "invalid stream id" +1ms
  socket.io-stream:socket invalid stream id: "41a0e462-d373-4a38-90fe-af00e30cf504" +0ms
  socket.io-stream:socket end: "fe90186d-6f0c-4d0f-9d01-1b59e57cfb3c" +0ms
    ✓ should send/receive a file (175ms)

[peteruithoven]

(I find it quite hard to debug, because when I enable more socket.io debug's my terminal can't handle all the buffers, it starts drawing all sorts of strange characters.)
Update: I'm using a 10x10 pixels image now, that mostly solves that issue.

[peteruithoven]

Those errors I noticed in the test are coming from the _onend method in the socket.js module. It looks like _onend is called a second time and the second time, when the stream is already destroyed it can't find it.
The _onend method:

Socket.prototype._onend = function(id) {
  debug('end: "%s"', id);

  var stream = this.streams[id];
  if (!stream) {
    debug('_onend error: invalid stream id');
    this._error(id, 'invalid stream id');
    return;
  }

  stream._end();
};

[peteruithoven]

Client: Sends image (reads from file)

$ DEBUG=client*,socket.io-stream*,socket.io-parser* node client/client.js 
...
  client sendImage +0ms
  socket.io-stream:socket sending new streams +0ms
  socket.io-parser encoding packet {"type":2,"data":["$stream","image",[0],"d0b576a0-9d72-46b1-82d4-8865cfc39853",{"name":"10x10.jpg"}],"nsp":"/user"} +1s
  socket.io-parser encoded {"type":2,"data":["$stream","image",[0],"d0b576a0-9d72-46b1-82d4-8865cfc39853",{"name":"10x10.jpg"}],"nsp":"/user"} as 2/user,["$stream","image",[0],"d0b576a0-9d72-46b1-82d4-8865cfc39853",{"name":"10x10.jpg"}] +0ms
  socket.io-parser decoded 2/user,["$stream-read","d0b576a0-9d72-46b1-82d4-8865cfc39853",16384] as {"type":2,"nsp":"/user","data":["$stream-read","d0b576a0-9d72-46b1-82d4-8865cfc39853",16384]} +5ms
  socket.io-stream:socket read: "d0b576a0-9d72-46b1-82d4-8865cfc39853" +7ms
  socket.io-parser encoding packet {"type":5,"data":["$stream-write","d0b576a0-9d72-46b1-82d4-8865cfc39853",[...],"buffer"],"id":0,"nsp":"/user"} +1ms
  socket.io-parser encoded {"type":5,"data":["$stream-write","d0b576a0-9d72-46b1-82d4-8865cfc39853",{"_placeholder":true,"num":0},"buffer"],"id":0,"nsp":"/user","attachments":1} as 51-/user,0["$stream-write","d0b576a0-9d72-46b1-82d4-8865cfc39853",{"_placeholder":true,"num":0},"buffer"] +4ms
  socket.io-parser decoded 2/user,["$stream-read","d0b576a0-9d72-46b1-82d4-8865cfc39853",16384] as {"type":2,"nsp":"/user","data":["$stream-read","d0b576a0-9d72-46b1-82d4-8865cfc39853",16384]} +4ms
  socket.io-stream:socket read: "d0b576a0-9d72-46b1-82d4-8865cfc39853" +9ms
  socket.io-stream:iostream _onfinish +1ms
  socket.io-stream:iostream _onfinish: not ended +0ms
  socket.io-stream:iostream _onend +1ms
  socket.io-stream:iostream _onend: [object Object] +0ms
  socket.io-stream:iostream destroy +0ms
  socket.io-stream:iostream clean up +0ms
  socket.io-parser decoded 2/user,["$stream-end","d0b576a0-9d72-46b1-82d4-8865cfc39853"] as {"type":2,"nsp":"/user","data":["$stream-end","d0b576a0-9d72-46b1-82d4-8865cfc39853"]} +1ms
  socket.io-stream:socket end: "d0b576a0-9d72-46b1-82d4-8865cfc39853" +1ms
  socket.io-parser encoding packet {"type":2,"data":["$stream-error","d0b576a0-9d72-46b1-82d4-8865cfc39853","invalid stream id"],"nsp":"/user"} +1ms
  socket.io-parser encoded {"type":2,"data":["$stream-error","d0b576a0-9d72-46b1-82d4-8865cfc39853","invalid stream id"],"nsp":"/user"} as 2/user,["$stream-error","d0b576a0-9d72-46b1-82d4-8865cfc39853","invalid stream id"] +0ms

Server: Receives image, writes to file

$ DEBUG=server*,socket.io-stream*,socket.io-parser* node server/server.js 
...
  server server listening on *:7000 +0ms
  socket.io-parser encoding packet {"type":0,"nsp":"/"} +0ms
  socket.io-parser encoded {"type":0,"nsp":"/"} as 0 +2ms
  socket.io-parser decoded 0/user as {"type":0,"nsp":"/user"} +11ms
  socket.io-parser encoding packet {"type":0,"nsp":"/user"} +1ms
  socket.io-parser encoded {"type":0,"nsp":"/user"} as 0/user +0ms
  server /user new connection +1s
  socket.io-parser decoded 2/user,["$stream","image",[0],"d0b576a0-9d72-46b1-82d4-8865cfc39853",{"name":"10x10.jpg"}] as {"type":2,"nsp":"/user","data":["$stream","image",[0],"d0b576a0-9d72-46b1-82d4-8865cfc39853",{"name":"10x10.jpg"}]} +1s
  socket.io-stream:socket new streams +2s
  server on image +0ms
  socket.io-parser encoding packet {"type":2,"data":["$stream-read","d0b576a0-9d72-46b1-82d4-8865cfc39853",16384],"nsp":"/user"} +3ms
  socket.io-parser encoded {"type":2,"data":["$stream-read","d0b576a0-9d72-46b1-82d4-8865cfc39853",16384],"nsp":"/user"} as 2/user,["$stream-read","d0b576a0-9d72-46b1-82d4-8865cfc39853",16384] +0ms
  socket.io-parser decoded 51-/user,0["$stream-write","d0b576a0-9d72-46b1-82d4-8865cfc39853",{"_placeholder":true,"num":0},"buffer"] as {"type":5,"attachments":1,"nsp":"/user","id":0,"data":["$stream-write","d0b576a0-9d72-46b1-82d4-8865cfc39853",{"_placeholder":true,"num":0},"buffer"]} +7ms
  socket.io-stream:socket write: "d0b576a0-9d72-46b1-82d4-8865cfc39853" +11ms
  socket.io-parser encoding packet {"type":2,"data":["$stream-read","d0b576a0-9d72-46b1-82d4-8865cfc39853",16384],"nsp":"/user"} +3ms
  socket.io-parser encoded {"type":2,"data":["$stream-read","d0b576a0-9d72-46b1-82d4-8865cfc39853",16384],"nsp":"/user"} as 2/user,["$stream-read","d0b576a0-9d72-46b1-82d4-8865cfc39853",16384] +0ms
  socket.io-parser encoding packet {"id":0,"type":3,"data":[],"nsp":"/user"} +0ms
  socket.io-parser encoded {"id":0,"type":3,"data":[],"nsp":"/user"} as 3/user,0[] +0ms
  socket.io-parser decoded 2/user,["$stream-end","d0b576a0-9d72-46b1-82d4-8865cfc39853"] as {"type":2,"nsp":"/user","data":["$stream-end","d0b576a0-9d72-46b1-82d4-8865cfc39853"]} +1ms
  socket.io-stream:socket end: "d0b576a0-9d72-46b1-82d4-8865cfc39853" +3ms
  socket.io-stream:iostream _onend +0ms
  socket.io-stream:iostream _onend: not finished +0ms
  socket.io-stream:iostream _onfinish +0ms
  socket.io-parser encoding packet {"type":2,"data":["$stream-end","d0b576a0-9d72-46b1-82d4-8865cfc39853"],"nsp":"/user"} +1ms
  socket.io-parser encoded {"type":2,"data":["$stream-end","d0b576a0-9d72-46b1-82d4-8865cfc39853"],"nsp":"/user"} as 2/user,["$stream-end","d0b576a0-9d72-46b1-82d4-8865cfc39853"] +0ms
  socket.io-stream:iostream _onfinish: ended, destroy [object Object] +0ms
  socket.io-stream:iostream destroy +0ms
  socket.io-stream:iostream clean up +1ms
  socket.io-parser decoded 2/user,["$stream-error","d0b576a0-9d72-46b1-82d4-8865cfc39853","invalid stream id"] as {"type":2,"nsp":"/user","data":["$stream-error","d0b576a0-9d72-46b1-82d4-8865cfc39853","invalid stream id"]} +1ms
  socket.io-stream:socket error: "d0b576a0-9d72-46b1-82d4-8865cfc39853", "invalid stream id" +0ms
  socket.io-stream:socket invalid stream id: "d0b576a0-9d72-46b1-82d4-8865cfc39853" +0ms

So:

1. client: was finished sending a stream
2. client: sends a $stream-end
3. client: destroys the stream
4. server: receives this $stream-end
5. server: destroys stream
   5. server: for some reason sends a $stream-end back (why?)
6. client: receives this second $stream-end
7. client: tries to destroy a stream that doesn't exist anymore and sends a $stream-error back.
8. server: receives $stream-error, but can't emit error because stream doesn't exist anymore.

Why would the server respond with an $stream-end when it received a $stream-end?

[peteruithoven]

I now understand the tricky thing is that a socket.io-stream is a duplex stream, it's writable and readable. The socket.io events that are send reflect the events the stream emits. So if a local socket.io-stream is fully consumed it will emit a end event and send a $stream-end to a remote socket.io-stream, whether that remote socket.io-stream was reading or writing.
The remote socket.io-stream will always receive this, whether he still had that stream or not. This is handy because it can clearly indicate it when a certain stream (id) doesn't exist.

So I'll admit I'm not sure what to do here. The following solutions don't seem adequate:

• Not send $stream-end to a remote that wasn't reading. (Won't that break anything / limit the functionality somehow?)
• Ignore $stream-... events for streams that don't exist. (It can fail silently, which is harder to debug)

[peteruithoven]

How only sending a $stream-end to a reading remote could work: #41

[nkzawa]

@peteruithoven I think I'm not fully understanding the issue, but doesn't the allowHalfOpen option solve it?

var stream = ss.createStream({ allowHalfOpen: true });

This allows the stream to keep the other side open like the option of net module.

https://nodejs.org/api/net.html#net_new_net_socket_options

[peteruithoven]

@nkzawa, it could solve it, but I'm not sure using allowHalfOpen is always appropriate. I'll try to summarize the issue.
When you send a stream using socket.io-stream (so you write to the stream) the stream will be destroyed when sending finishes. (I think when the acknowledgment callback of the last write event is called). The receiving end will read the stream and, a $stream-end event will be send back to the sender, even though it has already destroyed this stream on his end because it was writing. It looks like it only makes sense to receive a $stream-end when you are reading from the stream, just like you only use the regular stream end event when you're reading.

When the $stream-end is send anyway (like it currently is) you'll see this $stream-error with invalid stream id being send back as response to the $stream-end. While this error is not thrown or emitted, it does show up in the logs and Chrome's network dev tools, which is quite confusing.

[nkzawa]

@peteruithoven thank you very much for your great explanation. I think I understand the issue.

Ignore $stream-... events for streams that don't exist. (It can fail silently, which is harder to debug)

I'd like to take this way but apply it only for Socket#_onend. That is a simplest solution and it'd be nothing wrong to notify the event to the corresponding endpoint anyway. What do you think?

[peteruithoven]

I'd like to take this way but apply it only for Socket#_onend. That is a simplest solution and it'd be nothing wrong to notify the event to the corresponding endpoint anyway. What do you think?

With the corresponding endpoint you mean the remote socket.io-stream right? I like the fact that the events send over socket.io are in sync with the events that are emitted locally.
Limiting ignoring only the end events send to not existing streams seems like a okay compromise.

[nkzawa]

Released as 0.6.1. Thank you very much for your help @peteruithoven 😄

[peteruithoven]

My pleasure.
I hope to contribute more in the near future, especially around preventing memory leaks.