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

dialTLS Conn.read() stops resolving after writing to connection from promise resolution #3160

Closed
qwerasd205 opened this issue Oct 20, 2019 · 21 comments
Labels
bug Something isn't working

Comments

@qwerasd205
Copy link
Contributor

qwerasd205 commented Oct 20, 2019

When using dialTLS, Conn.read() will stop resolving if you write to the connection from a promise resolution if the promise is not immediately resolved.
Repro code
Expected output:

Sending req #1 (normal)
Response!
Sending req #2 (Immediate promise resolution)
Resolved! (sending)
Response!
Sending req #3 (Delayed promise resolution)
Resolved! (sending)
Response!
All responses recieved correctly, exiting.

Actual output:

Sending req #1 (normal)
Response!
Sending req #2 (Immediate promise resolution)
Resolved! (sending)
Response!
Sending req #3 (Delayed promise resolution)
Resolved! (sending)
No response after 8 seconds, exiting.

If you change the code to use Deno.dial and port 80 you get the expected output, so the issue is unique to dialTLS.

@bartlomieju
Copy link
Member

@qwerasd205 I think it might be bug in your code. You're not awaiting writes, that may lead to racy results. For example I run your repro against github.com and it works as expected. Could you try updating your repro to hit some actual site (like request bin) so we can reason about it on exactly the same reproduction?

@qwerasd205
Copy link
Contributor Author

qwerasd205 commented Oct 20, 2019

For example I run your repro against github.com and it works as expected.

That's a bug in the repro code which is hastily written. Large pages (like GitHub.com) will end up resulting in several reads. (example.com was an intentional target because it's small and supports https)

@qwerasd205
Copy link
Contributor Author

qwerasd205 commented Oct 20, 2019

Interesting note on the awaiting though. That shouldn't result in a silent failure either way, though.
Edit: Decided to check real quick, awaiting the write does not stop the bug from rearing its ugly head.

@bartlomieju
Copy link
Member

Sorry @qwerasd205 but I can't reproduce the problem, I had no problem with dialTLS whatsoever.

@qwerasd205
Copy link
Contributor Author

That's very strange. Could it possibly be specific to macOS?

@bartlomieju
Copy link
Member

I don't think so. Try rewriting your example to use async/await it should be easier to reason about. I'm confident there's some hanging promise in your example.

@qwerasd205
Copy link
Contributor Author

Well if you ran my repro code and didn't get the same result as I did then I don't see how else you could explain the discrepancy.

@qwerasd205
Copy link
Contributor Author

And as I said, the same exact code, except converted to dial and port 80 works perfectly, if it were a hanging promise or something of that sort then you would expect it to affect that, too.

@qwerasd205
Copy link
Contributor Author

qwerasd205 commented Oct 22, 2019

What code did you use to try to reproduce the problem? @bartlomieju

@bartlomieju
Copy link
Member

@qwerasd205 please try this solution:

'use strict';

const buff = new Uint8Array(16384);
const encode = new TextEncoder().encode;

async function sendRequest (conn) {
    await conn.write(encode('GET / HTTP/1.1\nHost: example.com\n\n'));
}


let i = 0;
let to;

async function doStep (conn) {
    console.log("doing step", i);
    switch (i) {
        case 0: {
            console.log('Sending req #1 (normal)');
            await sendRequest(conn);
        } break;
        case 1: {
            console.log('Sending req #2 (Immediate promise resolution)');
            await new Promise(r => r());
            console.log('Resolved! (sending)');
            await sendRequest(conn);
        } break;
        case 2: {
            console.log('Sending req #3 (Delayed promise resolution)');
            await new Promise(r => setTimeout(r, 100));
            console.log('Resolved! (sending)');
            await sendRequest(conn);
        } break;
        case 3: {
            console.log('All responses recieved correctly, exiting.');
            Deno.exit();
        } break;
    }
    clearTimeout(to);
    to = setTimeout(() => {
        console.log('No response after 8 seconds, exiting.');
        Deno.exit();
    }, 8e3);
    i++;
}

const conn = await Deno.dialTLS({hostname: 'example.com', port: 443});

async function dataLoop() {
  console.log("Starting dataloop");
  try {
    const nread = await conn.read(buff);
    console.log("Response!");
    await doStep(conn);
  } catch (e) {
    throw e;
  } finally {
    await dataLoop()
  }
}

doStep(conn);
await dataLoop()

I believe it does what you intended and doesn't hang ;)

@qwerasd205
Copy link
Contributor Author

The issue is with writing from within a Promise resolution, so of course awaiting said promise will avoid the issue...

@qwerasd205
Copy link
Contributor Author

You haven't shown me that this isn't a bug in the dialTLS connection, only that it doesn't occur when you write from outside of the resolve function of a Promise which didn't resolve immediately, which I already knew.

@bartlomieju
Copy link
Member

Okay now I see problem occurring. Interesting indeed... I can dig into it later this week or next week.

@qwerasd205
Copy link
Contributor Author

With a little modification to my original repro code, simply making sure that the write is complete before attempting to read again (by using awaits in appropriate places) does prevent the issue from occurring, but just because there's a solution doesn't mean it's not an issue. dial does not act this way, and it shouldn't. Writing to the socket while waiting to read from it shouldn't prevent ever reading from it again.

@qwerasd205
Copy link
Contributor Author

That is, I'm fairly confident now that the bug occurs when a write is made to the socket while a read is pending (waiting for data so it can resolve).

@nayeemrmn
Copy link
Collaborator

nayeemrmn commented Oct 22, 2019

Better repro:

const buff = new Uint8Array(16384);
const encode = new TextEncoder().encode;

const conn = await Deno.dialTLS({hostname: 'example.com', port: 443});
setTimeout(() => {
  console.log('No response after 8 seconds, exiting.');
  Deno.exit();
}, 8e3);
console.log('Starting read.');
conn.read(buff).then(() => {
  console.log('Finished read!');
  Deno.exit(0);
});
await new Promise(r => setTimeout(r, 100));
console.log('Starting write.');
await conn.write(encode('GET / HTTP/1.1\nHost: example.com\n\n'));
console.log('Finished write!');

@qwerasd205
Copy link
Contributor Author

Yes, that is a much better repro, as it encapsulates the problem a lot better. When I wrote the first one I still wasn't sure about the nature of the problem.

@bartlomieju
Copy link
Member

Nice repro @nayeemrmn, now I can clearly see buggy behavior. @qwerasd205 this should be fixed, sorry for denying 👍 nice catch

@qwerasd205
Copy link
Contributor Author

qwerasd205 commented Oct 22, 2019

sorry for denying

Don't worry about it, when this issue first appeared in my code I spent quite a while trying to figure out if it was a bug in my code, and not a Deno issue. And as you can see, I still didn't have the exact nature of the issue nailed down until after you forced me to examine my assumption by adding some awaits in.

@bartlomieju bartlomieju added the bug Something isn't working label Dec 27, 2019
@nayeemrmn
Copy link
Collaborator

I found a bug in both our repros (which exits with a proper error message now, probably due to changes to the encode implementation):

const encode = new TextEncoder().encode;

This removes the binding from the encoder object -- we should have only extracted the encoder object:

const encoder = new TextEncoder();
// Using encoder.encode() instead of encode().

🤦‍♂️

@qwerasd205 Not an issue for me, can you check as well?

@bartlomieju
Copy link
Member

Checked repro code with 0.28.1 - it works.

Checked with patch from @nayeemrmn with 0.29.0 - it also works.

Seems the issue is resolved 👍

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

3 participants