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

NTLM with Expect: makes libcurl hang #741

Closed
weltling opened this Issue Mar 30, 2016 · 19 comments

Comments

Projects
None yet
3 participants
@weltling
Contributor

weltling commented Mar 30, 2016

I did this

There is a bug reported to PHP https://bugs.php.net/bug.php?id=71861 being currently investigated. From what I currently could trace, it looks like a bug or behavior change in cURL. I also wrote a simple C program to mimic the behavior https://gist.github.com/weltling/15400de1018c7e6a4b476a415f08768d .

When the NTLM authentication is not used, or the buffer size is a power of two, there's no hang. Otherwise the program hangs.

I expected the following

The program doesn't hang.

curl/libcurl version

With 7.42.1 the program encounters HTTP error and exits, with 7.47.1 or 7.48.0 the program hangs.

curl -V

curl 7.47.1 (x86_64-pc-win32) libcurl/7.47.1 OpenSSL/1.0.1s zlib/1.2.7.3 WinIDN libssh2/1.7.0
Protocols: dict file ftp ftps gopher http https imap imaps ldap pop3 pop3s rtsp scp sftp smtp smtps telnet tftp
Features: AsynchDNS IDN IPv6 Largefile SSPI Kerberos SPNEGO NTLM SSL libz

operating system

Windows

@frenche

This comment has been minimized.

Show comment
Hide comment
@frenche

frenche Mar 30, 2016

Contributor

Oh, what a coincidence :)
We've been troubleshooting a very similar issue a few days ago (still not figured out but we have some vague idea).

Can you try to add empty 'Expect' header (to disable Expect) and see if it resolves the issue as it does for us?

Contributor

frenche commented Mar 30, 2016

Oh, what a coincidence :)
We've been troubleshooting a very similar issue a few days ago (still not figured out but we have some vague idea).

Can you try to add empty 'Expect' header (to disable Expect) and see if it resolves the issue as it does for us?

@weltling

This comment has been minimized.

Show comment
Hide comment
@weltling

weltling Mar 30, 2016

Contributor

Thanks for the quick response :) Yeah, removing the Expect header fixes influences the behavior. This is what i did https://gist.github.com/weltling/39860fccf381eba6329b5c742d30ae08 . The verbose output with 7.47.1 is some different from 7.42.1, but there is no hang anymore.

Thanks.

Contributor

weltling commented Mar 30, 2016

Thanks for the quick response :) Yeah, removing the Expect header fixes influences the behavior. This is what i did https://gist.github.com/weltling/39860fccf381eba6329b5c742d30ae08 . The verbose output with 7.47.1 is some different from 7.42.1, but there is no hang anymore.

Thanks.

@frenche

This comment has been minimized.

Show comment
Hide comment
@frenche

frenche Mar 30, 2016

Contributor

With debug build I get a crash which I don't see how it is related :(
a.out: transfer.c:1231: Curl_single_getsock: Assertion `conn->writesockfd != -1' failed.

The fun part, is what you found about how the buffer size affects the behaviour.
Trying to look more in to it...

Contributor

frenche commented Mar 30, 2016

With debug build I get a crash which I don't see how it is related :(
a.out: transfer.c:1231: Curl_single_getsock: Assertion `conn->writesockfd != -1' failed.

The fun part, is what you found about how the buffer size affects the behaviour.
Trying to look more in to it...

@weltling

This comment has been minimized.

Show comment
Hide comment
@weltling

weltling Mar 30, 2016

Contributor

Yeah, I made a mistake in the latest gist. The buffer size in general - yes, it is one of the concerns in the origninal PHP bug. Namely, if the buffer is not a power of two.

Thanks.

Contributor

weltling commented Mar 30, 2016

Yeah, I made a mistake in the latest gist. The buffer size in general - yes, it is one of the concerns in the origninal PHP bug. Namely, if the buffer is not a power of two.

Thanks.

@bagder bagder changed the title from NTLM authentication brings the program to hang to NTLM with Expect: makes libcurl hang Mar 30, 2016

@bagder bagder added the HTTP label Mar 30, 2016

@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Mar 30, 2016

Member

The "buffer size" makes the request larger and it is only when the request is larger than a certain limit that libcurl will use the Expect: logic. Other than that, I can't think why power of 2 would have a significance. I personally don't have any live NTLM server to debug against, so this is a little hard for me to track down...

Member

bagder commented Mar 30, 2016

The "buffer size" makes the request larger and it is only when the request is larger than a certain limit that libcurl will use the Expect: logic. Other than that, I can't think why power of 2 would have a significance. I personally don't have any live NTLM server to debug against, so this is a little hard for me to track down...

@weltling

This comment has been minimized.

Show comment
Hide comment
@weltling

weltling Mar 30, 2016

Contributor

@bagder I din't state it were a valid concern, just mentioned as it were making a diff to the original reporter of the PHP bug. The actual URL reproducing the issue is https://mail.microsoft.com/ews/exchange.asmx , OFC there's only the client side available. But that's the only base one can refer to :(

Thanks.

Contributor

weltling commented Mar 30, 2016

@bagder I din't state it were a valid concern, just mentioned as it were making a diff to the original reporter of the PHP bug. The actual URL reproducing the issue is https://mail.microsoft.com/ews/exchange.asmx , OFC there's only the client side available. But that's the only base one can refer to :(

Thanks.

@weltling

This comment has been minimized.

Show comment
Hide comment
@weltling

weltling Mar 30, 2016

Contributor

Anyways clearing the Expect header did the trick in the current repro snippet, hopefully it were helpful.

Thanks.

Contributor

weltling commented Mar 30, 2016

Anyways clearing the Expect header did the trick in the current repro snippet, hopefully it were helpful.

Thanks.

@frenche

This comment has been minimized.

Show comment
Hide comment
@frenche

frenche Mar 30, 2016

Contributor

Ok, here is what I see so far.

If we don't send Expect then we send the data right away and once we receive 401 we rewind at http_perhapsrewind (since all the byte were sent).
But if we send Expect, we first receive the 401 message and we set the rewindaftersend flag and only then we send the bytes (to be discarded), however we don't seem to rewind and I looks like we try to resend the bytes again and it hangs (or crash in debug build).

See output from my lab at: http://pastebin.com/raw/XP3RYbMi
Notice it prints twice "Keep sending data to get tossed away!".

I managed to fix it to rewind with the patch below but I'm still not clear about the flow.
Also I think we didn't see this problem in older version of curl (~7.27).

POC fix:

diff --git a/lib/transfer.c b/lib/transfer.c
index 7481e0c..3881aef 100644
--- a/lib/transfer.c
+++ b/lib/transfer.c
@@ -986,6 +986,12 @@ static CURLcode readwrite_upload(struct SessionHandle *data,
       /* we have sent all data we were supposed to */
       k->upload_done = TRUE;
       infof(data, "We are completely uploaded and fine\n");
+
+      if(conn->bits.rewindaftersend) {
+        result = Curl_readrewind(conn);
+        if(result)
+          return result;
+      }
     }

     if(data->req.upload_present != bytes_written) {
Contributor

frenche commented Mar 30, 2016

Ok, here is what I see so far.

If we don't send Expect then we send the data right away and once we receive 401 we rewind at http_perhapsrewind (since all the byte were sent).
But if we send Expect, we first receive the 401 message and we set the rewindaftersend flag and only then we send the bytes (to be discarded), however we don't seem to rewind and I looks like we try to resend the bytes again and it hangs (or crash in debug build).

See output from my lab at: http://pastebin.com/raw/XP3RYbMi
Notice it prints twice "Keep sending data to get tossed away!".

I managed to fix it to rewind with the patch below but I'm still not clear about the flow.
Also I think we didn't see this problem in older version of curl (~7.27).

POC fix:

diff --git a/lib/transfer.c b/lib/transfer.c
index 7481e0c..3881aef 100644
--- a/lib/transfer.c
+++ b/lib/transfer.c
@@ -986,6 +986,12 @@ static CURLcode readwrite_upload(struct SessionHandle *data,
       /* we have sent all data we were supposed to */
       k->upload_done = TRUE;
       infof(data, "We are completely uploaded and fine\n");
+
+      if(conn->bits.rewindaftersend) {
+        result = Curl_readrewind(conn);
+        if(result)
+          return result;
+      }
     }

     if(data->req.upload_present != bytes_written) {
@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Mar 31, 2016

Member

Curios, can you figure out why it isn't rewound at the "proper" place https://github.com/curl/curl/blob/master/lib/transfer.c#L893 ?

Member

bagder commented Mar 31, 2016

Curios, can you figure out why it isn't rewound at the "proper" place https://github.com/curl/curl/blob/master/lib/transfer.c#L893 ?

@frenche

This comment has been minimized.

Show comment
Hide comment
@frenche

frenche Mar 31, 2016

Contributor

I think because we did not send the body yet, 'nread' prints 1025 before these lines.

Expect: 100-continue
...
< HTTP/1.1 401 Unauthorized
...
< WWW-Authenticate: NTLM
...
* Rewind stream after send
* Keep sending data to get tossed away!
<
* Ignoring the response-body
* nread: 1025
* We are completely uploaded and fine
* Curl_done
Contributor

frenche commented Mar 31, 2016

I think because we did not send the body yet, 'nread' prints 1025 before these lines.

Expect: 100-continue
...
< HTTP/1.1 401 Unauthorized
...
< WWW-Authenticate: NTLM
...
* Rewind stream after send
* Keep sending data to get tossed away!
<
* Ignoring the response-body
* nread: 1025
* We are completely uploaded and fine
* Curl_done
@frenche

This comment has been minimized.

Show comment
Hide comment
@frenche

frenche Mar 31, 2016

Contributor

The fix passes 'make test' btw.
I think it also make sense to check for rewindaftersend and rewind right after sending.

Contributor

frenche commented Mar 31, 2016

The fix passes 'make test' btw.
I think it also make sense to check for rewindaftersend and rewind right after sending.

@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Mar 31, 2016

Member

I think because we did not send the body yet, 'nread' prints 1025 before these lines.

Well OK, if it is 1025 there it just means it still has data to send. It still needs to decide it is done sending somewhere within that function and switch off the KEEP_SEND bit, right?

Does it do that on line 1008?

Member

bagder commented Mar 31, 2016

I think because we did not send the body yet, 'nread' prints 1025 before these lines.

Well OK, if it is 1025 there it just means it still has data to send. It still needs to decide it is done sending somewhere within that function and switch off the KEEP_SEND bit, right?

Does it do that on line 1008?

@frenche

This comment has been minimized.

Show comment
Hide comment
@frenche

frenche Apr 1, 2016

Contributor

Yes, it does that at line 1008 but it doesn't rewind.
Moving the rewind fix to line 1008 also works.

Contributor

frenche commented Apr 1, 2016

Yes, it does that at line 1008 but it doesn't rewind.
Moving the rewind fix to line 1008 also works.

@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Apr 1, 2016

Member

Roger that, makes sense. Thanks for verifying.

Member

bagder commented Apr 1, 2016

Roger that, makes sense. Thanks for verifying.

@bagder bagder closed this in 3e005a8 Apr 1, 2016

@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Apr 1, 2016

Member

@weltling any chance you can verify if that fix repairs your original case as well?

Member

bagder commented Apr 1, 2016

@weltling any chance you can verify if that fix repairs your original case as well?

@weltling

This comment has been minimized.

Show comment
Hide comment
@weltling

weltling Apr 2, 2016

Contributor

@bagder i can confirm the current master doesn't reproduce the issues anymore. Was waiting a bit for the reporter's response from https://bugs.php.net/bug.php?id=71861 . No response yet, guess there'll be some by next week. Anyway the current PHP reproducer looks fine to me with the today's 7.48.1-DEV and not having to touch any headers.

Thanks.

Contributor

weltling commented Apr 2, 2016

@bagder i can confirm the current master doesn't reproduce the issues anymore. Was waiting a bit for the reporter's response from https://bugs.php.net/bug.php?id=71861 . No response yet, guess there'll be some by next week. Anyway the current PHP reproducer looks fine to me with the today's 7.48.1-DEV and not having to touch any headers.

Thanks.

@bagder

This comment has been minimized.

Show comment
Hide comment
@bagder

bagder Apr 2, 2016

Member

Thanks for the confirmation! 👍

Member

bagder commented Apr 2, 2016

Thanks for the confirmation! 👍

@frenche

This comment has been minimized.

Show comment
Hide comment
@frenche

frenche Apr 3, 2016

Contributor

Thank you both =)

Contributor

frenche commented Apr 3, 2016

Thank you both =)

@weltling

This comment has been minimized.

Show comment
Hide comment
@weltling

weltling Apr 4, 2016

Contributor

Got the feedback from the reporter of the original issue in PHP, the fix is confirmed, so once for all :) Thanks, guys!

Contributor

weltling commented Apr 4, 2016

Got the feedback from the reporter of the original issue in PHP, the fix is confirmed, so once for all :) Thanks, guys!

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.