Strange Streams behavior

[scheibo]

Something fishy seems to be occurring with lib/streams.js where code after while ((chunk = await stream.read()) {} does not get executed. I noticed this when trying to run sim/battle-stream-example.js, but a more minimal example of the bug can be found below:

'use strict';
const Streams = require('../lib/streams');

class FooStream extends Streams.ObjectReadWriteStream {
    _write(message) {}
    _end() { this.push(null); }
}

function getStreams(stream) {
    let omni = new Streams.ObjectReadWriteStream({
        write(data) {
            stream.write(data);
        }
    });

    (async() => {
        console.log('before logged');
        let chunk;
        while ((chunk = await stream.read())) {
            if (chunk !== 'end') {
                omni.push(chunk);
            }
        }
        console.log('never logged');
    })();

    return {omni};
}

let fooStream = new FooStream();
const streams = getStreams(fooStream);

(async() => {
    console.log('also logged');
    let chunk;
    while ((chunk = await streams.omni.read())) {
        console.log(chunk);
    }
    console.log('also never logged');
})();

console.log('start');
for (let i = 0; i < 10; i++) {
    fooStream.push(`data ${i}`);
}
fooStream.push('end');

console.log('stop');

When run, this code outputs:

before logged
also logged
start
stop
data 0
data 1
data 2
data 3
data 4
data 5
data 6
data 7
data 8
data 9

With never logged and also never logged not appearing. If I replace the await streams.read() method with a different async method the code after the while will execute, so something Streams is doing seems to be to blame here. I tried single stepping through streams with a debugger but couldn't garner any additional insight.

[Zarel]

So, a stream can be thought of as a string (or, in the case of an object string, an array) that you go through asynchronously.

But the array or string doesn't end until you tell it to end. With the current API, you tell the stream to end by sending .push(null). This says "we've reached the end of the string/array".

So say we start an object stream. We do stream.push("data 0"); stream.push("data 1");

This is kind of like the array ["data 0", "data 1", ...]

But notice, we haven't ended the stream yet. There could be more elements! We could push "data 2" a few minutes later. So the code will just keep on waiting for the next element of the array.

If we want to tell the code "this is the end of the array", you'd have to instead do stream.push("data 0"); stream.push("data 1"); stream.push(null);

This would be more like the array ["data 0", "data 1"]. It now has a defined "end of the stream".

[scheibo]

Sorry, you're completely right, my example was missing some stream.push(null). I had tried to simplify what was going on in sim/battle-stream-example.js but was mistaken. A different 'repro' would be to add a log statement after the while loop here, but extrapolating from above this probably indicates that a stream.push(null) is probably missing there as well?

[Zarel]

Anyway, stream.push should never be called outside the stream implementation. Notice that the STREAMS documentation doesn't mention it at all:

https://github.com/Zarel/Pokemon-Showdown/blob/master/lib/STREAMS.md

Adding stream.push(null); after your stream.push('end'); stuff does fix the problem you were talking about, but I think the real problem is that you're confusing it with stream.write.

[Zarel]

I see what you mean. Yeah, my code doesn't really send stream ends very reliably. I'll try to fix the example.

[scheibo]

I think the problem is that https://github.com/Zarel/Pokemon-Showdown/blob/master/sim/battle-stream.js#L157 is never called because https://github.com/Zarel/Pokemon-Showdown/blob/master/sim/battle-stream.js#L99 will never push null

EDIT: I think we're on the same page now :)

[Zarel]

This is actually really hard to fix because everything is a bit too async, so I kind of just hacked in a solution... It should be good enough in the usual case.

[scheibo]

This bug is back. If I add console.log("foo") to https://github.com/Zarel/Pokemon-Showdown/blob/fc95f6e7d96db09fa2896bbd595b15327c2d112e/sim/battle-stream-example.ts#L100 outside the while it won't print. :(

[Zarel]

You're a full-fledged PS dev this time around. Figure it out yourself. :p

Anyway, the stream will only end if the battle ends, but the battle ending should make the stream end.

[scheibo]

Yeah... I was hoping you might have some ideas to save me some headaches debugging. From "This is actually really hard to fix because everything is a bit too async, so I kind of just hacked in a solution... It should be good enough in the usual case." it sounded like you maybe have additional concerns/thoughts about where the problems could lie? I'll obviously get around to fixing it because its blocking me.

[Zarel]

My original hacky fix is documented in the commit summary here: https://github.com/Zarel/Pokemon-Showdown/commit/b7c252fbd6bb8ab75900293799bb0d8dd6b38439

I wanted to make it so the ReadStream didn't close until the WriteStream closed (because >eval is always a valid message type, even post-battle), but I decided to make it close on end of battle by default. If it doesn't work, it's because something in there messed up.

[scheibo]

Using bisection, b09fd63 is when this broke (because of course)

[Zarel]

If you want, I can fix this myself, but it'll take around a week.

[scheibo]

Thanks, but im digging into it now. If I can't figure it out I'll wait :)

[scheibo]

Found it. 100% my fault, too. Yay.