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

Invalid HTTP method: X-Takes-LocalAddress #1227

Open
baudoliver7 opened this issue Jun 8, 2023 · 17 comments
Open

Invalid HTTP method: X-Takes-LocalAddress #1227

baudoliver7 opened this issue Jun 8, 2023 · 17 comments
Labels

Comments

@baudoliver7
Copy link
Contributor

baudoliver7 commented Jun 8, 2023

I got this error sometimes with the current version of Takes :

java.io.IOException: Invalid HTTP method: X-Takes-LocalAddress:
	at org.takes.rq.RqMethod$Base.method(RqMethod.java:124)
	at org.takes.facets.fallback.TkFallback.error(TkFallback.java:234)
	at org.takes.facets.fallback.TkFallback.fallback(TkFallback.java:138)
	at org.takes.facets.fallback.TkFallback.route(TkFallback.java:88)
	at org.takes.facets.fallback.TkFallback.lambda$new$0(TkFallback.java:66)
	at org.takes.tk.TkWrap.act(TkWrap.java:58)
	at org.takes.tk.TkWrap.act(TkWrap.java:58)
	at org.takes.tk.TkSlf4j.act(TkSlf4j.java:110)
	at org.takes.http.FtCli.lambda$start$0(FtCli.java:91)
	at org.takes.http.BkBasic.print(BkBasic.java:123)
	at org.takes.http.BkBasic.accept(BkBasic.java:99)
	at org.takes.http.BkSafe.lambda$new$0(BkSafe.java:46)
	at org.takes.http.BkWrap.accept(BkWrap.java:51)
	at org.takes.http.BkTimeable.accept(BkTimeable.java:92)
	at org.takes.http.BkParallel.lambda$new$0(BkParallel.java:81)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:750)

While debugging, we got this:
image

It looks like RqRequestLine.Base doesn't do the right job :-(

@baudoliver7
Copy link
Contributor Author

@yegor256 Do you have any idea of this error ?

@yegor256
Copy link
Owner

@baudoliver7 do you know how can I reproduce it?

@baudoliver7
Copy link
Contributor Author

@yegor256 It is a bit difficult to reproduce it. It generally happens when I query a GET method on my local machine. It doesn't happen on a distant server.

@EugenDueck
Copy link
Contributor

EugenDueck commented May 2, 2024

We are probably encountering the same issue in production, for a couple of POST requests we do every day and which are exactly identical every day. However, sometimes, one of the requests fails.

In these cases, (new Base(req)).method() returns "OST", rather than "POST", so the first byte of the method - which happens to be the first byte of the TCP payload - seems to have disappeared at some point.

I was able to replicate the problem locally by hammering the service using curl in an infinite loop (but serially, one after the other, never concurrently):

  • so far, I could only replicate it on Windows (which is also where the service runs in production :-( )
    • it happens after a couple hundred to a few tens of thousands of requests
    • note however on one attempt on Windows, I could not replicate it having tried > 80k times before giving up
    • on Mac and not on Linux, I gave up after doing > 200k tries each without replicating
  • it replicated on all JVMs I tried: OpenJDK 17.0.1 and OpenJDK 11.0.12
  • we are still on takes version 1.19

Example stack trace:

java.io.IOException: Invalid HTTP method: X-Takes-LocalAddress:
        at org.takes.rq.RqMethod$Base.method(RqMethod.java:124)
        at org.takes.facets.fallback.TkFallback.error(TkFallback.java:239)
        at org.takes.facets.fallback.TkFallback.fallback(TkFallback.java:143)
        at org.takes.facets.fallback.TkFallback.route(TkFallback.java:93)
        at org.takes.facets.fallback.TkFallback.access$000(TkFallback.java:57)
        at org.takes.facets.fallback.TkFallback$1.act(TkFallback.java:69)
        at org.takes.tk.TkWrap.act(TkWrap.java:58)
        at org.takes.http.BkBasic.print(BkBasic.java:127)
        at org.takes.http.BkBasic.accept(BkBasic.java:103)
        at org.takes.http.BkSafe$1.accept(BkSafe.java:49)
        at org.takes.http.BkWrap.accept(BkWrap.java:51)
        at org.takes.http.FtBasic.loop(FtBasic.java:114)
        at org.takes.http.FtBasic.start(FtBasic.java:100)

@EugenDueck
Copy link
Contributor

I've stripped the problem down a bit further, while still being able to reproduce the above stack trace.
When I remove the TkFallback, I still get an exception after attempting a sufficient number of requests, so I believe it is due to the same root cause, even though the exception in that case is:

org.takes.HttpException: 404
        at org.takes.facets.fork.TkFork.act(TkFork.java:104)
        at org.takes.http.BkBasic.print(BkBasic.java:127)
        at org.takes.http.BkBasic.accept(BkBasic.java:103)
        at org.takes.http.BkSafe$1.accept(BkSafe.java:49)
        at org.takes.http.BkWrap.accept(BkWrap.java:51)
        at org.takes.http.FtBasic.loop(FtBasic.java:114)
        at org.takes.http.FtBasic.start(FtBasic.java:100)

This is the code that reproduces the above error, and the takes version is 1.19:

public class Main {
    private static final DateTimeFormatter FORMATTER = DateTimeFormatter.ofPattern("HH:mm:ss.SSS");
    private static volatile long lastLogTime = System.nanoTime();
    private static final AtomicLong postCount = new AtomicLong(0);
    private static final Collection<Fork> CONTROLLERS = List.of(
            new FkRegex("/a", new TkFork(new FkMethods("POST", req -> {
                long now = System.nanoTime();
                long postCount = Main.postCount.incrementAndGet();
                if (now - lastLogTime > 1_000_000_000) {
                    System.out.println(LocalTime.now().format(FORMATTER) + " " + postCount + " POST requests");
                    lastLogTime = now;
                }
                return new RsText("ok");
            })))
    );

    public static void main(String[] args) throws IOException {
        new FtBasic(new TkFork(CONTROLLERS), 8100).start(Exit.NEVER);
    }

}

The curl command I use (fish shell) is this:

while curl --fail-with-body -sX POST 'http://192.168.1.21:8100/a'; end

@yegor256
Copy link
Owner

yegor256 commented May 2, 2024

@pnatashap maybe you can help with this?

@yegor256 yegor256 added the bug label May 2, 2024
@EugenDueck
Copy link
Contributor

Meanwhile I have tried once more to replicate this stripped down version with Linux, but I wasn't able to. I tried > 1.3M times with OpenJDK 17.0.1, and >1M times with 11.0.22, and actually this time around I did it concurrently, due to reasons of patience, but I just cannot seem to get it to replicate on Linux (Ubuntu 22.04, 5.15.0-101-lowlatency #111-Ubuntu SMP PREEMPT)

@EugenDueck
Copy link
Contributor

EugenDueck commented May 2, 2024

Another difference I should mention: The (Windows) machines I could replicate this on are both virtual machines. Production is on an AWS EC2, the other Windows machine runs on VirtualBox on a Linux host. The machines I were not able to replicate it on are all physical (x64 in the case of Linux and arm64 (Apple M2) in the case of Mac). Not sure this fact is relevant in this case, but some hypervisors show e.g. clock issues in guests, so TSC time can jump backwards, which is but one thing differentiating virtual from physical machines.

@EugenDueck
Copy link
Contributor

EugenDueck commented May 2, 2024

I just replicated the issue with the latest stable takes 1.24.4, on the same Windows machine: Once after 36k requests, another time after 14k requests, and once it took 193k requests!

@EugenDueck
Copy link
Contributor

EugenDueck commented May 2, 2024

Here's a really short version that still replicates the problem (again on Windows, using takes 1.24.4; this time around, it took 35k attempts, in 237 seconds):

    public static void main(String[] args) throws IOException {
        new FtBasic(new TkFork(new FkRegex("/a", "k")), 8100).start(Exit.NEVER);
    }

The exception:

org.takes.HttpException: 404
        at org.takes.facets.fork.TkFork.act(TkFork.java:102)
        at org.takes.http.BkBasic.print(BkBasic.java:123)
        at org.takes.http.BkBasic.accept(BkBasic.java:99)
        at org.takes.http.BkSafe.lambda$new$0(BkSafe.java:46)
        at org.takes.http.BkWrap.accept(BkWrap.java:51)
        at org.takes.http.FtBasic.loop(FtBasic.java:113)
        at org.takes.http.FtBasic.start(FtBasic.java:99)

@EugenDueck
Copy link
Contributor

EugenDueck commented May 2, 2024

@yegor256
I still could only reproduce the bug in Windows, but if you use e.g. 6, 7 loops invoking curl in parallel, it always reproduces within 2, 3 seconds, which makes it much, much easier to test (although I guess a http load generator like wrk2 would be simpler and still faster, even when used with a concurrency of 1; but I haven't tried). After applying the PR, I cannot not reproduce it any longer.

@EugenDueck
Copy link
Contributor

@yegor256 I guess there won't be an "official" hotfix for 1.19? (This is the version we are using in production)

@yegor256
Copy link
Owner

yegor256 commented May 2, 2024

@EugenDueck yes, we don't do backporting in this project. We'll most probably fix this issue and then release 1.24.5. Is it a problem?

@EugenDueck
Copy link
Contributor

@yegor256 Totally understand that.
The old version does not build on a recent JDK (I'm currently using 17 or newer), but I will get me an older JDK (8 or 11) and with that I'm pretty sure I'll get it to build, so I can create a hotfix myself. But thanks for asking!

@EugenDueck
Copy link
Contributor

EugenDueck commented May 2, 2024

@yegor256 I have just added a regression test to the PR, which replicates the problem in an unfixed version of takes.

@EugenDueck
Copy link
Contributor

@baudoliver7 On what OS did this issue occur for you? Also, what JDK version? If you remember.

@baudoliver7
Copy link
Contributor Author

@EugenDueck It occurs on Windows with JDK 8

EugenDueck added a commit to EugenDueck/takes that referenced this issue May 24, 2024
(cherry picked from commit a3fd77e)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

3 participants