Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Stream closed before all message are received #2375

Closed
phoenix741 opened this issue Feb 26, 2023 · 2 comments
Closed

Stream closed before all message are received #2375

phoenix741 opened this issue Feb 26, 2023 · 2 comments

Comments

@phoenix741
Copy link
Contributor

phoenix741 commented Feb 26, 2023

Problem description

The client send multiple message through a stream, then close the stream and wait a response. The server receive all the element, but the end of stream can be receive before all the message and then last message are ignored.

Reproduction steps

I have a client that write to the stream :

      for await (const y of x) {
        console.log('write', y.toString('utf-8'));
        writer.write(y);
      }
      console.log('end');
      writer.end();

The server use requestStream: ServerReadableStream<RefreshCacheRequest, RefreshCacheReply> :

    for await (const x of request) {
      console.log('read', x.toString('utf8'));
    }

I have some missing event in read. If i had a setTimeout 5s arroud writer.end() i have all the message.

In the log i have :

[w:client] D 2023-02-25T22:18:39.562Z | server_call | Received message of length 361
[w:client] D 2023-02-25T22:18:39.562Z | server_call | Received message of length 859
[w:client] D 2023-02-25T22:18:39.562Z | server_call | Received message of length 1028
[w:client] D 2023-02-25T22:18:39.562Z | server_call | Received message of length 1267
[w:client] D 2023-02-25T22:18:39.562Z | server_call | Received message of length 1311
[w:client] D 2023-02-25T22:18:39.562Z | server_call | Received message of length 1437
[w:client] D 2023-02-25T22:18:39.563Z | server_call | Received message of length 1431
[w:client] D 2023-02-25T22:18:39.563Z | server_call | Received end of stream
[w:client] D 2023-02-25T22:18:39.563Z | server_call | Request to method /woodstock.WoodstockClientService/RefreshCache ended with status code: OK details: OK
[w:client] D 2023-02-25T22:18:39.563Z | server_call | Received message of length 3390
[w:client] D 2023-02-25T22:18:39.563Z | server_call | Received message of length 3937
[w:client] D 2023-02-25T22:18:39.565Z | server_call | Request to method /woodstock.WoodstockClientService/RefreshCache stream closed with rstCode 0

And the last two message are lost. The Request to method send the response because the stream is ended.

If i read with a setTimeout, all message are processed and the event are in the good order:

    for await (const x of request) {
      console.log('read', x.toString('utf8'));
      await setTimeout(0);
    }

Log:

[w:client] D 2023-02-26T11:16:58.697Z | server_call | Received message of length 859
[w:client] D 2023-02-26T11:16:58.697Z | server_call | Received message of length 1028
[w:client] D 2023-02-26T11:16:58.697Z | server_call | Received message of length 1267
[w:client] D 2023-02-26T11:16:58.697Z | server_call | Received message of length 1311
[w:client] D 2023-02-26T11:16:58.697Z | server_call | Received message of length 1437
[w:client] D 2023-02-26T11:16:58.697Z | server_call | Received message of length 1431
[w:client] D 2023-02-26T11:16:58.697Z | server_call | Received message of length 3390
[w:client] D 2023-02-26T11:16:58.698Z | server_call | Received message of length 3937
[w:client] D 2023-02-26T11:16:58.698Z | server_call | Received end of stream
[w:client] D 2023-02-26T11:16:59.099Z | server_call | Request to method /woodstock.WoodstockClientService/RefreshCache ended with status code: OK details: OK
[w:client] D 2023-02-26T11:16:59.099Z | server_call | Request to method /woodstock.WoodstockClientService/RefreshCache stream closed with rstCode 0

Environment

  • OS name, version and architecture: Linux Debian bullseye
  • Node version: Node 18 and Node 16
  • Node installation method: nvm
  • Package name and version: "@grpc/grpc-js": "^1.8.11" (but i have the problem with "@grpc/grpc-js": "^1.6.8" too)

Additional context

  • I will try to analyse more the code to understand why.
  • Before using a loop with a close, i use pipeline (stream) that close automatically the stream at the end.
  • If i had setTimeout (0ms) between each message read, all message are processed, but if i process all message as quickly as possible, i have the problem
@phoenix741
Copy link
Contributor Author

I have added some log in setupReadable:

        this.stream.on('data', async (data) => {
            trace('ULRICH: Data received');
            const messages = decoder.write(data);
            pendingMessageProcessing = true;
            trace('ULRICH: Pause ');
            this.stream.pause();
            for (const message of messages) {
                trace('ULRICH: Process message ');
                if (this.maxReceiveMessageSize !== -1 &&
                    message.length > this.maxReceiveMessageSize) {
                    this.sendError({
                        code: constants_1.Status.RESOURCE_EXHAUSTED,
                        details: `Received message larger than max (${message.length} vs. ${this.maxReceiveMessageSize})`,
                    });
                    return;
                }
                this.emit('receiveMessage');
                const compressed = message.readUInt8(0) === 1;
                const compressedMessageEncoding = compressed ? encoding : 'identity';
                const decompressedMessage = await this.getDecompressedMessage(message, compressedMessageEncoding);
                // Encountered an error with decompression; it'll already have been propogated back
                // Just return early
                if (!decompressedMessage)
                    return;
                this.pushOrBufferMessage(readable, decompressedMessage);
            }
            pendingMessageProcessing = false;
            trace('ULRICH: Resume ');
            this.stream.resume();
            maybePushEnd();
        });
        this.stream.once('end', () => {
            trace('ULRICH: End of stream called');
            readsDone = true;
            maybePushEnd();
        });

The result is :

[w:client] D 2023-02-26T11:28:14.575Z | server_call | Received message of length 172
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Resume 
[w:client] D 2023-02-26T11:28:14.576Z | server_call | Received message of length 585
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Resume 
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Data received
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Pause 
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Process message 
[w:client] D 2023-02-26T11:28:14.576Z | server_call | Received message of length 499
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Resume 
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Data received
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Pause 
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Process message 
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Data received
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Pause 
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Process message 
[w:client] D 2023-02-26T11:28:14.576Z | server_call | Received message of length 723
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Resume 
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Data received
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Pause 
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Process message 
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Data received
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Pause 
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Process message 
[w:client] D 2023-02-26T11:28:14.576Z | server_call | Received message of length 543
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Resume 
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Data received
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Pause 
[w:client] D 2023-02-26T11:28:14.576Z | server_call | ULRICH: Process message 
[w:client] D 2023-02-26T11:28:14.577Z | server_call | ULRICH: Data received
[w:client] D 2023-02-26T11:28:14.577Z | server_call | ULRICH: Pause 
[w:client] D 2023-02-26T11:28:14.577Z | server_call | ULRICH: Process message 
[w:client] D 2023-02-26T11:28:14.577Z | server_call | Received message of length 361
[w:client] D 2023-02-26T11:28:14.577Z | server_call | ULRICH: Resume 
[w:client] D 2023-02-26T11:28:14.577Z | server_call | ULRICH: Data received
[w:client] D 2023-02-26T11:28:14.577Z | server_call | ULRICH: Pause 
[w:client] D 2023-02-26T11:28:14.577Z | server_call | ULRICH: Process message 
[w:client] D 2023-02-26T11:28:14.577Z | server_call | ULRICH: Data received
[w:client] D 2023-02-26T11:28:14.577Z | server_call | ULRICH: Pause 
[w:client] D 2023-02-26T11:28:14.577Z | server_call | ULRICH: Process message 
[w:client] D 2023-02-26T11:28:14.577Z | server_call | ULRICH: End of stream called
[w:client] D 2023-02-26T11:28:14.577Z | server_call | Received message of length 859
[w:client] D 2023-02-26T11:28:14.577Z | server_call | ULRICH: Resume 
[w:client] D 2023-02-26T11:28:14.577Z | server_call | Received end of stream
[w:client] D 2023-02-26T11:28:14.578Z | server_call | Request to method /woodstock.WoodstockClientService/RefreshCache ended with status code: OK details: OK
[w:client] D 2023-02-26T11:28:14.578Z | server_call | Received message of length 1028
[w:client] D 2023-02-26T11:28:14.578Z | server_call | ULRICH: Resume 
[w:client] D 2023-02-26T11:28:14.578Z | server_call | Received message of length 1267
[w:client] D 2023-02-26T11:28:14.579Z | server_call | ULRICH: Resume 
[w:client] D 2023-02-26T11:28:14.579Z | server_call | Received message of length 1311
[w:client] D 2023-02-26T11:28:14.579Z | server_call | ULRICH: Resume 
[w:client] D 2023-02-26T11:28:14.579Z | server_call | Received message of length 1437
[w:client] D 2023-02-26T11:28:14.579Z | server_call | ULRICH: Resume 
[w:client] D 2023-02-26T11:28:14.579Z | server_call | Received message of length 1431
[w:client] D 2023-02-26T11:28:14.579Z | server_call | ULRICH: Resume 
[w:client] D 2023-02-26T11:28:14.579Z | server_call | Received message of length 3390
[w:client] D 2023-02-26T11:28:14.579Z | server_call | ULRICH: Resume 
[w:client] D 2023-02-26T11:28:14.579Z | server_call | Received message of length 3937
[w:client] D 2023-02-26T11:28:14.579Z | server_call | ULRICH: Resume 
[w:client] D 2023-02-26T11:28:14.579Z | server_call | Request to method /woodstock.WoodstockClientService/RefreshCache stream closed with rstCode 0

Pause is called but data method is called ...

@phoenix741
Copy link
Contributor Author

phoenix741 commented Feb 26, 2023

I have made a correction on local on my computer, for all work correctly, there should not have promise that not have been awaited:

    setupReadable(readable, encoding) {
        const decoder = new stream_decoder_1.StreamDecoder();
        let readsDone = false;
        let pendingMessageProcessing = false;
        let pushedEnd = false;
        const maybePushEnd = () => {
            if (!pushedEnd && readsDone && !pendingMessageProcessing) {
                pushedEnd = true;
                this.pushOrBufferMessage(readable, null);
            }
        };
        this.stream.on('data', async (data) => {
            trace('ULRICH: Data received');
            const messages = decoder.write(data);
            pendingMessageProcessing = true;
            trace('ULRICH: Pause ');
            this.stream.pause();
            for (const message of messages) {
                trace('ULRICH: Process message ');
                if (this.maxReceiveMessageSize !== -1 &&
                    message.length > this.maxReceiveMessageSize) {
                    this.sendError({
                        code: constants_1.Status.RESOURCE_EXHAUSTED,
                        details: `Received message larger than max (${message.length} vs. ${this.maxReceiveMessageSize})`,
                    });
                    return;
                }
                trace('ULRICH: BeforeEmit ');
                this.emit('receiveMessage');
                trace('ULRICH: AfterEmit ');
                const compressed = message.readUInt8(0) === 1;
                const compressedMessageEncoding = compressed ? encoding : 'identity';
                trace('ULRICH: BeforeDecompress ');
                const decompressedMessage = await this.getDecompressedMessage(message, compressedMessageEncoding);
                trace('ULRICH: AfterDecompress ');
                // Encountered an error with decompression; it'll already have been propogated back
                // Just return early
                if (!decompressedMessage)
                    return;
                trace('ULRICH: PushOrBufferMessage ');
                await this.pushOrBufferMessage(readable, decompressedMessage);
            }
            pendingMessageProcessing = false;
            trace('ULRICH: Resume ');
            this.stream.resume();
            maybePushEnd();
        });
        this.stream.once('end', () => {
            trace('ULRICH: End of stream called');
            readsDone = true;
            maybePushEnd();
        });
        this.stream.on('pipe', () => {
            trace('ULRICH: Pipe called');
        })
    }
    consumeUnpushedMessages(readable) {
        this.canPush = true;
        while (this.messagesToPush.length > 0) {
            const nextMessage = this.messagesToPush.shift();
            const canPush = readable.push(nextMessage);
            if (nextMessage === null || canPush === false) {
                this.canPush = false;
                break;
            }
        }
        return this.canPush;
    }
    async pushOrBufferMessage(readable, messageBytes) {
        if (this.isPushPending) {
            this.bufferedMessages.push(messageBytes);
        }
        else {
            await this.pushMessage(readable, messageBytes);
        }
    }
    async pushMessage(readable, messageBytes) {
        if (messageBytes === null) {
            trace('Received end of stream');
            if (this.canPush) {
                readable.push(null);
            }
            else {
                this.messagesToPush.push(null);
            }
            return;
        }
        trace('Received message of length ' + messageBytes.length);
        this.isPushPending = true;
        try {
            const deserialized = await this.deserializeMessage(messageBytes);
            if (this.canPush) {
                if (!readable.push(deserialized)) {
                    this.canPush = false;
                    this.stream.pause();
                }
            }
            else {
                this.messagesToPush.push(deserialized);
            }
        }
        catch (error) {
            // Ignore any remaining messages when errors occur.
            this.bufferedMessages.length = 0;
            let code = (0, error_1.getErrorCode)(error);
            if (code === null || code < constants_1.Status.OK || code > constants_1.Status.UNAUTHENTICATED) {
                code = constants_1.Status.INTERNAL;
            }
            readable.emit('error', {
                details: (0, error_1.getErrorMessage)(error),
                code: code
            });
        }
        this.isPushPending = false;
        if (this.bufferedMessages.length > 0) {
            await this.pushMessage(readable, this.bufferedMessages.shift());
        }
    }

I will propose a PR

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants