TkSlf4j can fail for specific request

[g4s8]

Hi.
If TkSlf4j wraps Take that returns empty response (without body),
and if POST request with some body has been sent through VerboseWire (from jcabi-http),
RqMethod.Base will fail with this exception:

java.io.IOException: Invalid HTTP method: X-Takes-LocalAddress:
    at org.takes.rq.RqMethod$Base.method(RqMethod.java:127)
    at org.takes.tk.TkSlf4j.act(TkSlf4j.java:105)
    at org.takes.http.BkBasic.print(BkBasic.java:108)
    at org.takes.http.BkBasic.accept(BkBasic.java:84)
    at org.takes.http.BkParallel$1$1.run(BkParallel.java:89)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

Test for reproducing:

    @Test
    public void test() throws IOException {
        new FtRemote(
            new TkSlf4j(
                req -> new RsEmpty()
            )
        ).exec(
            home ->
                new JdkRequest(home)
                    .method("POST")
                    .body().set("test").back()
                    .through(VerboseWire.class)
                    .fetch()
                    .as(RestResponse.class)
                    .assertStatus(HttpURLConnection.HTTP_OK)
        );
    }

Environment:
java - 1.8.0_102-b14
takes - 1.1
jcabi-http - 1.16

http:

POST / HTTP/1.1
Cache-Control: no-cache
Pragma: no-cache
User-Agent: Java/1.8.0_102
Host: localhost:41997
Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2
Connection: keep-alive
Content-type: application/x-www-form-urlencoded
Content-Length: 4

testHTTP/1.1 200 OK

HTTP/1.1 500 Internal Error
Content-Length: 538
Content-Type: text/plain

java.io.IOException: Invalid HTTP method: X-Takes-LocalAddress:
.at org.takes.rq.RqMethod$Base.method(RqMethod.java:127)
.at org.takes.tk.TkSlf4j.act(TkSlf4j.java:105)
.at org.takes.http.BkBasic.print(BkBasic.java:108)
.at org.takes.http.BkBasic.accept(BkBasic.java:84)
.at org.takes.http.BkParallel$1$1.run(BkParallel.java:89)
.at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
.at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
.at java.lang.Thread.run(Thread.java:745)

[davvd]

@yegor256 please pay attention to this issue (par.21)

[yegor256]

@g4s8 definitely a bug, thanks for reporting

[davvd]

@g4s8 attached this issue to milestone "1.0" (let me know if this is wrong)

[davvd]

@dalifreire please pick this up, and keep in mind these instructions. Any technical questions - ask right here

Task's budget is 30 mins (see this for explanation)

[dalifreire]

@davvd Please, find someone else... I'll be away for the next weeks. Thanks.

[davvd]

@davvd Please, find someone else... I'll be away for the next weeks. Thanks.

@dalifreire deducted 30 from your rating :(

[davvd]

@davvd Please, find someone else... I'll be away for the next weeks. Thanks.

@dalifreire someone else will help in this task, no problem at all

[davvd]

@rui-castro This task is yours, please go ahead keeping in mind this. If any questions, don't hesitate to ask right here; This task's budget is 30 mins. This is exactly how much will be paid when the problem explained above is solved. See this for more information

[rui-castro]

@davvd done in PR #716

The problem reported is caused by BkBasic not handling requests properly.

I'm not entirely confident that I diagnosed the problem correctly, because it seems very unlikely that this problem in BkBasic only comes up now. Anyway, this is what I've found...

The Take in the test req -> new RsEmpty() doesn't read the request body, so the body remains in the InputStream.

After the Take is finished, BkBasic checks if there is more content (supposedly a new request) in the InputStream. Since the body of the previous request is still in the InputStream, BkBasic constructs a new RqLive with that content and passes it to the Take.

The new request doesn't have a method or body and has only the headers X-Takes-... injected by BkBasic.

In the test example, since the TkSlf4j tries to log the request info method, url and headers, it fails with error Invalid HTTP method: X-Takes-LocalAddress:.

The proposed solution introduces a new Take (TkConsumeBody) that is always used to wrap the RqLive and that, after the inner Take executes, it consumes (skip) the remaining body data accordingly to Content-Length or Transfer-Encoding: chuncked.

[rui-castro]

@davvd the PR #716 is ready for 6 days. Could you please do something to close the PR and this issue?

[davvd]

@rui-castro you're working with this ticket for the last 15 days. If it is not closed within the next 48 hours, it will be re-assigned to someone else, see No Obligations principle. This article should help if you're stuck... -30 added to your rating, at the moment it is: -30

[rui-castro]

@davvd That's not fair! The work is done and waiting for @yegor256 approval for 7 days.

[davvd]

@rui-castro the task is overdue, and I have to re-assign it to someone else. Please, stop working with it immediately. In general, we're against overdue tasks, check this page; added -60 to your rating, now it is equal to -90

[davvd]

@prondzyn it's yours now, please proceed keeping in mind our principles. Feel free to ask any technical questions right here in the ticket; Total fixed cost of this task is 30 mins (see this for more info)

[prondzyn]

@davvd I'm on it.

[prondzyn]

@davvd PR #717 is ready.

[davvd]

@davvd PR #717 is ready.

@prondzyn thank you

[davvd]

@davvd still need more time here. I'm waiting on @yegor256's in #717

@prondzyn sure, take your time, I know about this pause

[prondzyn]

@davvd still need more time here. I'm waiting on @yegor256's in #717

[davvd]

@davvd still need more time here. I'm waiting on @yegor256's in #717

@prondzyn sure, take your time, I know about this pause

[prondzyn]

@davvd still need more time here. I'm waiting on @yegor256's in #717

[davvd]

@davvd still need more time here. I'm waiting on @yegor256's in #717

@prondzyn take your time, I am aware that we're waiting here

[prondzyn]

@davvd still need more time here. I'm waiting on @yegor256's in #717

[davvd]

@davvd still need more time here. I'm waiting on @yegor256's in #717

@prondzyn yeah, I know, take your time

[prondzyn]

@davvd still need more time here. I'm waiting on @yegor256's in #717

[davvd]

@davvd still need more time here. I'm waiting on @yegor256's in #717

@prondzyn take your time, I am aware that we're waiting here

[prondzyn]

@davvd still need more time here. I'm waiting on @yegor256's in #717

[davvd]

@davvd still need more time here. I'm waiting on @yegor256's in #717

@prondzyn sure, take your time, I know about this pause

[prondzyn]

@davvd still need more time here. I'm waiting on @yegor256's in #717

[davvd]

@davvd still need more time here. I'm waiting on @yegor256's in #717

@prondzyn sure, take your time, I know about this pause

[prondzyn]

@davvd still need more time here. I'm waiting on @yegor256's in #717

[davvd]

@davvd still need more time here. I'm waiting on @yegor256's in #717

@prondzyn sure, take your time, I know about this pause

[prondzyn]

@davvd still need more time here. I'm waiting on @yegor256's in #717

[davvd]

@davvd still need more time here. I'm waiting on @yegor256's in #717

@prondzyn take your time, I am aware that we're waiting here

[prondzyn]

@g4s8 could you close this issue, please? I pushed test to reproduce the issue and additional task (#730) was automatically created to resolve the issue.

[g4s8]

@prondzyn ok, thanks

[0crat]

Oops! Job gh:yegor256/takes#712 was not in scope

[prondzyn]

@davvd the task is closed.

[0pdd]

@g4s8 the puzzle #869 is still not solved; solved: #730, #731, #800.

[0pdd]

@g4s8 all 4 puzzles are solved here: #730, #731, #800, #869.