0.7.24: exception "Header is missing ':'"

[sigod]

This exception happens in 0.7.24 when we make multipart request:

    Bad Request
    Internal error information:
    object.Exception@../.dub/packages/vibe-d-0.7.24/source/vibe/inet/message.d(56): Header is missing ':'.
    ----------------
    ./bin/server(pure @safe bool std.exception.enforce!(Exception, bool).enforce(bool, lazy const(char)[], immutable(char)[], ulong)+0x6b) [0x8b314b]
    ./bin/server(void vibe.inet.message.parseRFC5322Header(vibe.core.stream.InputStream, ref vibe.utils.dictionarylist.DictionaryList!(immutable(char)[], false, 32uL).DictionaryList, ulong, vibe.utils.memory.Allocator, bool)+0x130) [0xa45518]
    ./bin/server(bool vibe.inet.webform.parseMultipartFormPart(vibe.core.stream.InputStream, ref vibe.utils.dictionarylist.DictionaryList!(immutable(char)[], true, 16uL).DictionaryList, ref vibe.utils.dictionarylist.__T14DictionaryListTS4vibe4inet7webform8FilePartVbi1Vmi1Z.DictionaryList, immutable(char)[], ulong)+0x8c) [0xaac22c]
    ./bin/server(void vibe.inet.webform.parseMultiPartForm(ref vibe.utils.dictionarylist.DictionaryList!(immutable(char)[], true, 16uL).DictionaryList, ref vibe.utils.dictionarylist.__T14DictionaryListTS4vibe4inet7webform8FilePartVbi1Vmi1Z.DictionaryList, immutable(char)[], vibe.core.stream.InputStream, ulong)+0x24a) [0xaac156]
    ./bin/server(bool vibe.inet.webform.parseFormData(ref vibe.utils.dictionarylist.DictionaryList!(immutable(char)[], true, 16uL).DictionaryList, ref vibe.utils.dictionarylist.__T14DictionaryListTS4vibe4inet7webform8FilePartVbi1Vmi1Z.DictionaryList, immutable(char)[], vibe.core.stream.InputStream, ulong)+0xf8) [0xaabf08]
    ./bin/server(bool vibe.http.server.handleRequest(vibe.core.stream.Stream, vibe.core.net.TCPConnection, vibe.http.server.HTTPListenInfo, ref vibe.http.server.HTTPServerSettings, ref bool)+0x146d) [0xaa9b45]
    ./bin/server(void vibe.http.server.handleHTTPConnection(vibe.core.net.TCPConnection, vibe.http.server.HTTPListenInfo)+0x1b3) [0xaa85d3]
    ./bin/server(void vibe.http.server.listenHTTPPlain(vibe.http.server.HTTPServerSettings).doListen(vibe.http.server.HTTPListenInfo, bool).__lambda3(vibe.core.net.TCPConnection)+0x36) [0xaa7fa2]
    ./bin/server(void vibe.core.drivers.libevent2_tcp.ClientTask.execute()+0x4b8) [0xa82c14]
    ./bin/server(void vibe.core.core.makeTaskFuncInfo!(void delegate()).makeTaskFuncInfo(ref void delegate()).callDelegate(vibe.core.core.TaskFuncInfo*)+0x72) [0x9f794a]
    ./bin/server(void vibe.core.core.CoreTask.run()+0x12e) [0x9f5a46]
    ./bin/server(void core.thread.Fiber.run()+0x2a) [0xb65042]
    ./bin/server(fiber_entryPoint+0x61) [0xb64f31]
    [(nil)]

0.7.23 works flawlessly.

[s-ludwig]

I've tested with the uploaded example and that still seems to work. The only change in that area seems to be #1183, but it isn't obvious how that would result in this kind of error. Which way do you generate the client request?

[sigod]

I actually never saw client code. But I know that colleagues use retrofit.

Here, I extracted headers along with some data from client logs:

HTTP POST http://<url>/challenge/new
access_token: pwB1FO8uJuVCFwEGFR8fQPdlUkVXqS6IDJXJDpStaECg_r8FOdCUZPEcHg9laYq_GoGsLfqETQnv7bM_CdbdXQ
Content-Type: multipart/form-data; boundary=e7918c2f-d8b8-4c35-846f-dfd257cc1805
Content-Length: 402753
--e7918c2f-d8b8-4c35-846f-dfd257cc1805
    Content-Disposition: form-data; name="file"; filename="new_challenge.jpg"
    Content-Type: image/jpeg
    Content-Length: 401724
    Content-Transfer-Encoding: binary

[lots of portions of binary data]

[etcimon]

shouldn't there be a carriage-return and line-break after the HTTP headers? (after content-length)

would also end with another set of line-break and carriage-return and a

--e7918c2f-d8b8-4c35-846f-dfd257cc1805--

[sigod]

shouldn't there be a carriage-return and line-break after the HTTP headers? (after content-length)

It might be it got eaten up by logging facility. square/retrofit#650

[sigod]

would also end with another set of line-break and carriage-return and a

--e7918c2f-d8b8-4c35-846f-dfd257cc1805--

Hm. Actually, this request should consist of 5 values. File and some other data. But log doesn't have it. And boundary string appears only 2 times (in part mentioned above).

[etcimon]

Can you capture this through wireshark instead?

[sigod]

Can you capture this through wireshark instead?

Unfortunately, I can't do it right now.

Here's full logs (server and client, both): https://gist.github.com/sigod/524683e707f5efb9f416

logInfo("ln: %s", ln); // added this line to see what kills request
enforce(colonpos > 0 && colonpos < ln.length-1, "Header is missing ':'.");

[sigod]

I isolated changes from #1101. And now this requests works.

[etcimon]

Yes it looks like the issue is with this line:

https://github.com/rejectedsoftware/vibe.d/blob/master/source/vibe/inet/webform.d#L140

It expects \r\n--, but the following boundaries are \r\n\s\s\s-- where \s = whitespace

[etcimon]

I isolated changes from #1101. And now this requests works.

Good!

[sigod]

I isolated changes from #1101. And now this requests works.

Checked Content-Length:

ln: Content-Length: 368606

Saved file size: 368606

[s-ludwig]

Isn't the issue just that the Content-Length path fails to skip over the final boundary? The next multi-part would then read the boundary instead of the following header.

[sigod]

Yes, I'm sure in it.