Timeout receiving data with vibe-d subconfiguration

[llJochemll]

When performing a request to https://test.documents.azure.com the request fails with "Timeout receiving data". This only happens withe the "vibed" subconfiguration.

Tested multiple other sites (such as httpbin.org), could only reproduce with this one (any on the .documents.azure.com domain). Also tested using the 401 status page from httpbin.org, worked fine too.

Don't know wether it's a vibe-d bug or not, but thought I post it here first since the error is thrown in a file from this library.

Code:

import requests;
import std.datetime;
import std.stdio;

void main() {
    auto request = Request();
    request.keepAlive = true;
    request.sslSetCaCert = "ca.pem";
    request.verbosity = 3;
    request.timeout = 2.seconds;
    
    request.exec!"GET"("https://test.documents.azure.com");
}

dub.json:

{
	"name": "testd",
	"dependencies": {
		"requests": "1.0.0"
	},
	"subConfigurations": {
		"requests": "vibed"
	}
}

Output (note that the full body is received):

> GET / HTTP/1.1
> User-Agent: dlang-requests
> Host: test.documents.azure.com
> Connection: Keep-Alive
> Accept-Encoding: gzip,deflate
>
00000  48 54 54 50 2F 31 2E 31  20 34 30 31 20 55 6E 61  |HTTP/1.1 401 Una|
00010  75 74 68 6F 72 69 7A 65  64 0D 0A 54 72 61 6E 73  |uthorized..Trans|
00020  66 65 72 2D 45 6E 63 6F  64 69 6E 67 3A 20 63 68  |fer-Encoding: ch|
00030  75 6E 6B 65 64 0D 0A 43  6F 6E 74 65 6E 74 2D 54  |unked..Content-T|
00040  79 70 65 3A 20 61 70 70  6C 69 63 61 74 69 6F 6E  |ype: application|
00050  2F 6A 73 6F 6E 0D 0A 43  6F 6E 74 65 6E 74 2D 4C  |/json..Content-L|
00060  6F 63 61 74 69 6F 6E 3A  20 68 74 74 70 73 3A 2F  |ocation: https:/|
00070  2F 74 65 73 74 2E 64 6F  63 75 6D 65 6E 74 73 2E  |/test.documents.|
00080  61 7A 75 72 65 2E 63 6F  6D 2F 0D 0A 53 65 72 76  |azure.com/..Serv|
00090  65 72 3A 20 4D 69 63 72  6F 73 6F 66 74 2D 48 54  |er: Microsoft-HT|
000A0  54 50 41 50 49 2F 32 2E  30 0D 0A 78 2D 6D 73 2D  |TPAPI/2.0..x-ms-|
000B0  61 63 74 69 76 69 74 79  2D 69 64 3A 20 38 33 34  |activity-id: 834|
000C0  30 32 39 62 64 2D 39 32  38 32 2D 34 61 66 37 2D  |029bd-9282-4af7-|
000D0  62 66 65 32 2D 36 30 32  32 32 63 32 62 63 63 65  |bfe2-60222c2bcce|
000E0  37 0D 0A 53 74 72 69 63  74 2D 54 72 61 6E 73 70  |7..Strict-Transp|
000F0  6F 72 74 2D 53 65 63 75  72 69 74 79 3A 20 6D 61  |ort-Security: ma|
00100  78 2D 61 67 65 3D 33 31  35 33 36 30 30 30 0D 0A  |x-age=31536000..|
00110  78 2D 6D 73 2D 67 61 74  65 77 61 79 76 65 72 73  |x-ms-gatewayvers|
00120  69 6F 6E 3A 20 76 65 72  73 69 6F 6E 3D 32 2E 30  |ion: version=2.0|
00130  2E 30 2E 30 0D 0A 44 61  74 65 3A 20 54 68 75 2C  |.0.0..Date: Thu,|
00140  20 32 35 20 4F 63 74 20  32 30 31 38 20 31 37 3A  | 25 Oct 2018 17:|
00150  34 32 3A 35 36 20 47 4D  54 0D 0A 0D 0A 44 39 0D  |42:56 GMT....D9.|
00160  0A 7B 22 63 6F 64 65 22  3A 22 55 6E 61 75 74 68  |.{"code":"Unauth|
00170  6F 72 69 7A 65 64 22 2C  22 6D 65 73 73 61 67 65  |orized","message|
00180  22 3A 22 52 65 71 75 69  72 65 64 20 48 65 61 64  |":"Required Head|
00190  65 72 20 61 75 74 68 6F  72 69 7A 61 74 69 6F 6E  |er authorization|
001A0  20 69 73 20 6D 69 73 73  69 6E 67 2E 20 45 6E 73  | is missing. Ens|
001B0  75 72 65 20 61 20 76 61  6C 69 64 20 41 75 74 68  |ure a valid Auth|
001C0  6F 72 69 7A 61 74 69 6F  6E 20 74 6F 6B 65 6E 20  |orization token |
001D0  69 73 20 70 61 73 73 65  64 2E 5C 72 5C 6E 41 63  |is passed.\r\nAc|
001E0  74 69 76 69 74 79 49 64  3A 20 38 33 34 30 32 39  |tivityId: 834029|
001F0  62 64 2D 39 32 38 32 2D  34 61 66 37 2D 62 66 65  |bd-9282-4af7-bfe|
00200  32 2D 36 30 32 32 32 63  32 62 63 63 65 37 2C 20  |2-60222c2bcce7, |
00210  4D 69 63 72 6F 73 6F 66  74 2E 41 7A 75 72 65 2E  |Microsoft.Azure.|
00220  44 6F 63 75 6D 65 6E 74  73 2E 43 6F 6D 6D 6F 6E  |Documents.Common|
00230  2F 32 2E 30 2E 30 2E 30  22 7D 0D 0A              |/2.0.0.0"}..    |
< HTTP/1.1 401 Unauthorized
< transfer-encoding: chunked
< content-type: application/json
< content-location: https://test.documents.azure.com/
< server: Microsoft-HTTPAPI/2.0
< x-ms-activity-id: 834029bd-9282-4af7-bfe2-60222c2bcce7
< strict-transport-security: max-age=31536000
< x-ms-gatewayversion: version=2.0.0.0
< date: Thu, 25 Oct 2018 17:42:56 GMT
< 223 bytes of body received

requests.streams.TimeoutException@C:\Users\joche\AppData\Local\dub\packages\requests-1.0.0\requests\source\requests\streams.d(1266): Timeout receiving data
----------------
0x00007FF6BD419C4E in requests.streams.SSLVibeStream.receive at C:\Users\joche\AppData\Local\dub\packages\requests-1.0.0\requests\source\requests\streams.d(1270)
0x00007FF6BD409980 in requests.http.HTTPRequest.receiveResponse at C:\Users\joche\AppData\Local\dub\packages\requests-1.0.0\requests\source\requests\http.d(874)
0x00007FF6BD40FCBA in requests.http.HTTPRequest.exec_from_parameters at C:\Users\joche\AppData\Local\dub\packages\requests-1.0.0\requests\source\requests\http.d(2214)
0x00007FF6BD4112D9 in requests.http.HTTPRequest.execute at C:\Users\joche\AppData\Local\dub\packages\requests-1.0.0\requests\source\requests\http.d(2374)
0x00007FF6BD3EC8D1 in requests.request.Request.LastInterceptor.opCall at C:\Users\joche\AppData\Local\dub\packages\requests-1.0.0\requests\source\requests\request.d(499)
0x00007FF6BD412E00 in requests.request.RequestHandler.handle at C:\Users\joche\AppData\Local\dub\packages\requests-1.0.0\requests\source\requests\request.d(184)
0x00007FF6BD3ED8FA in requests.request.Request.execute at C:\Users\joche\AppData\Local\dub\packages\requests-1.0.0\requests\source\requests\request.d(600)
0x00007FF6BD3E6858 in requests.request.Request.exec!"GET".exec at C:\Users\joche\AppData\Local\dub\packages\requests-1.0.0\requests\source\requests\request.d(429)
0x00007FF6BD3E66A7 in D main at D:\Projects\testD\source\app.d(12)
0x00007FF6BD5FDB92 in void rt.dmain2._d_run_main(int, char**, extern (C) int function(char[][])*).runAll().__lambda1()
0x00007FF6BD5FD9AF in void rt.dmain2._d_run_main(int, char**, extern (C) int function(char[][])*).tryExec(scope void delegate())
0x00007FF6BD5FDABB in void rt.dmain2._d_run_main(int, char**, extern (C) int function(char[][])*).runAll()
0x00007FF6BD5FD9AF in void rt.dmain2._d_run_main(int, char**, extern (C) int function(char[][])*).tryExec(scope void delegate())
0x00007FF6BD5FD766 in d_run_main
0x00007FF6BD3E8662 in __entrypoint.main
0x00007FF6BD6E35B8 in __scrt_common_main_seh at f:\dd\vctools\crt\vcstartup\src\startup\exe_common.inl(288)
0x00007FFA90B93034 in BaseThreadInitThunk
0x00007FFA93671461 in RtlUserThreadStart
Program exited with code 1
The terminal process terminated with exit code: 2

Tested with dub run --arch=x86_64 --build=plain --compiler=dmd on a Windows 10 64bit PC.

Some comments about the code:

• request.exec!"GET" and request.get give the same result
• the error also occurs with the default timeout of 30 seconds, set here for 2 seconds to reduce waiting time

FYI this bug isn't new to 1.0.0, it was also present in the last couple of releases.

[ikod]

Hello @llJochemll

Thanks for your report! Will look very soon.

[ikod]

looks like it is vibe-on-windows specific, as under osx and linux I can't reproduce:

001C0  6F 72 69 7A 61 74 69 6F  6E 20 74 6F 6B 65 6E 20  |orization token |
001D0  69 73 20 70 61 73 73 65  64 2E 5C 72 5C 6E 41 63  |is passed.\r\nAc|
001E0  74 69 76 69 74 79 49 64  3A 20 32 36 36 32 32 63  |tivityId: 26622c|
001F0  39 30 2D 35 32 36 61 2D  34 39 35 34 2D 62 65 65  |90-526a-4954-bee|
00200  61 2D 62 64 61 30 32 63  66 36 61 39 61 64 2C 20  |a-bda02cf6a9ad, |
00210  4D 69 63 72 6F 73 6F 66  74 2E 41 7A 75 72 65 2E  |Microsoft.Azure.|
00220  44 6F 63 75 6D 65 6E 74  73 2E 43 6F 6D 6D 6F 6E  |Documents.Common|
00230  2F 32 2E 30 2E 30 2E 30  22 7D 0D 0A              |/2.0.0.0"}..    |
< HTTP/1.1 401 Unauthorized
< transfer-encoding: chunked
< content-type: application/json
< content-location: https://test.documents.azure.com/
< server: Microsoft-HTTPAPI/2.0
< x-ms-activity-id: 26622c90-526a-4954-beea-bda02cf6a9ad
< strict-transport-security: max-age=31536000
< x-ms-gatewayversion: version=2.0.0.0
< date: Thu, 25 Oct 2018 18:45:34 GMT
< 223 bytes of body received
< 5 bytes of body received
00000  30 0D 0A 0D 0A                                    |0....           |
>> Connect time: 559 ms and 598 μs
>> Request send time: 320 μs
>> Response recv time: 163 ms and 408 μs

This will take more time (I need to set up windows virtual machine).

[ikod]

Hello, @llJochemll

Sorry for long delay, it took some time to set up windows environment and reproduce problem. Working on it.

[ikod]

Hello, @llJochemll

Looks like this is really some problem with vibe.d and ssl - vibe.d do not report availability of last several bytes in some cases when request doc from test.documents.azure.com (50% of tests). My ability to debug vibe.d and ssl under Windows are very limited. I'm afraid I have to put this on hold now.

What do you think?

[llJochemll]

I was not sure whether the bug originated in vibe or not, but since the exception originated from requests and the build-in vibe http request (http://vibed.org/api/vibe.http.client/requestHTTP) didn't have any problems, I thought I'd post it here first.

I understand that the issue is very specific (specific domain and platform) and it's not a big deal for me anyway since I mostly run my code on linux, but just figured I'd let you know the problem existed.

Thanks for taking the time to look into this!

(Also, if you'd need access to a Windows VM in the future, let me know and I'd probably be able to provision one for a while)

[ikod]

Hello, @llJochemll

Always glad to receive your bug reports. I was a little busy with my another project 'cachetools'. Now I'm returning back to this problem. Looks like our knowledge on windows sockets are very limited. dub test also fails on one of the tests.

[bagomot]

This is not a Vibe-d problem, it's a Windows socket problem. I get the same error at random times with any http library and even using std.net.curl. I've been struggling with this for a couple of weeks now and still can't find the source of the problem.

[danbarbarito]

Seeing this issue as well. Anyone have a workaround?

[danbarbarito]

std.net.curl works fine for me. Looks like I have to switch over to that until this is fixed.