Never pass Request to an asynchronous thread! There is a pit!

Hello wow, I am crooked.

When I was surfing the Internet a few days ago, I saw a technical article. It said that he passed a request request to the thread pool, and then encountered an incredible situation.

He wrote this article to share his exploration of this problem:

"How to correctly use request in asynchronous threads in springboot"
https://www.cnblogs.com/mysgk/p/16470336.html

The article is still quite good, and the problems found and solutions are written very clearly.

However, I feel that the part about exploring the problem is too omitted, so that I don't know what the root cause of the problem is after reading it.

And why am I particularly interested in this article?

Because of this "pit", I remember that I encountered it when I just entered the industry for less than two years. I don't remember how I solved it at the time, but I definitely didn't study it in depth.

Because I encountered problems at that time, I went to the Internet to search with all my heart, and stuck a plan to see if it could be used.

If it can't be used, curse inwardly: Xiao Ke (S) loves (B), and then continue to look for it.

until you find one that works.

As for why?

Whatever it is, research this thing for what.

The main reason was that I felt that exploring this thing was going into the source code, and when it came to the source code, I felt terrified, so I stayed away.

It's different now, and now I feel excited when I see the source code, thinking to myself: What a good material.

Now that I have encountered it again this time, I decided to fill in the pit from a few years ago and try it out.

Make a Demo

Because this phenomenon is too unbelievable, the guy who wrote the article thought this was a bug, and also raised an issue on Spring's github:

https://github.com/spring-projects/spring-framework/issues/28741

Here he attached a reproducible demo, so I used it directly.

It can be reproduced, but in fact, the demo he provided is still a bit bloated and a little confusing, which made me dizzy and made me spend a little time on it.

Let me show you how his Demo looks like.

Mainly two Controller interfaces.

The first interface is getParams of the get request type. The code is very simple. Put it here first and use it later:

The second interface is postTest of the post request type, just a few lines of code:

 @PostMapping("/postTest")
public String postTest(HttpServletRequest request) {
    String age1 = request.getParameter("age");
    String name1 = request.getParameter("name");
    System.out.println("age1=" + age1 + ",name1=" + name1);
    new Thread(new Runnable() {
        @Override
        public void run() {
            String age2 = request.getParameter("age");
            String name2 = request.getParameter("name");
            System.out.println("age2=" + age2 + ",name2=" + name2);
            //模拟业务请求
            try {
                Thread.sleep(200);
            } catch (InterruptedException e) {
                throw new RuntimeException(e);
            }
            age2 = request.getParameter("age");
            name2 = request.getParameter("name");
        }
    }).start();
    return "post success";
}

Mainly, a thread is started inside, and there is an action to obtain parameters from the request in the thread.

This method is accessed like this:

From the output of age2 and name2, although the request is passed into the asynchronous thread, the corresponding parameters can still be obtained from it, and there is nothing wrong with it.

But then, something incredible happened.

Remember our getParams interface from earlier?

I'll bring it over to show you again:

You said, as far as this interface is concerned, I use the following link to access it. In my cognition, it is absolutely impossible to have any problems, right?

http://127.0.0.1:8080/getParams?a=1&b=2

However, this thing really broke my cognition:

After accessing the postTest method, and accessing the getParams method again, the getParams method throws an exception?

The exception thrown is that I did not pass the b parameter when I called it.

But my link clearly has b=2?

Where does this thing make sense?

The above is the main part of the reproducible Demo provided by the old man.

But as I said earlier, this Demo is a bit bloated and a little confusing.

First if I add an output statement, then after a short sleep, age2 and name2 are gone:

Although it still feels a bit magical, it didn't surprise me just like the operation just now.

Because from the result of outputting null, I can at least know that the program has a problem in this place, and the scope of the problem is limited to one request.

The operation just now, good guy, showed that the situation was like this:

• First initiate a post request, which seems to be normal.
• Then initiate a get request, and the get request hangs.
• But there is nothing wrong with this get request from the originating point of view.

If you want to analyze the problem based on the above situation, it will be difficult to find the problem. After all, you need to initiate two unrelated requests to trigger the problem.

Adding a line of output log is equivalent to simplifying the problem a bit.

But what you see is that I just added a line of output log. In fact, by the time I added this line of log, it has been several hours since I got the Demo.

During this period, I always thought that I had to follow this process to reproduce the problem.

That's why I say it's a little confusing.

Okay, now whatever you say.

I'll simplify the Demo a little bit, so that I can continue the analysis. My demo can be simplified to this level:

 @GetMapping("/getTest")
public String getTest(HttpServletRequest request) {
    String age = request.getParameter("age");
    System.out.println("age=" + age);
    new Thread(() -> {
        try {
            Thread.sleep(200);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
        String age1 = request.getParameter("age");
        System.out.println("age1=" + age1);
    }).start();
    return "success";
}

Both get and post requests can be used, but I choose to initiate a get request for convenience.

Then you only need to pass one parameter. The core step is to pass the request to the asynchronous thread, and call getParameter to get the corresponding input parameter again.

You can paste the above code to your local, run the project, and then call the following link once:

http://127.0.0.1:8080/getTest?age=18

From the console you can see output like this:

Here, the problem mentioned above is reproduced.

But don't worry, you call again, you will see the console output like this:

How is it, isn't it amazing and confusing?

In order to make you more intuitive, I will give you a moving picture and make two calls, mainly focusing on the output of the console:

Well, now, you go make a cup of tea, light a cigarette, and slowly wonder if this thing is a paranormal phenomenon.

explore

In fact, I was not particularly shocked when I saw this phenomenon. After all, in the past few years of writing this article, I have encountered all kinds of strange phenomena.

So I just smiled contemptuously, looked at my arsenal for troubleshooting, and soon saw something handy: turn on the Debug log.

If it was in the past, I followed the problem of not throwing an exception. Since there is no exception stack, I must be eager to Debug and follow the source code, dig into the source code, and frantically flip through it, looking left and right.

But the result is often that after diving in, you get lost quickly, and it takes several hours to climb out of the source code, and when you come out, you basically get nothing.

But I won't be so impatient now, I'm a lot more mature now. When encountering such problems, you will not rush to volume the source code first, but will dig a little more from the log first.

So my first reaction to this problem was to adjust the log level to Debug:

logging.level.root=debug

The observation log is a little trick I shared in the previous article.

When the log is adjusted to the Debug level, two calls are made again to reproduce the problem, and the log is taken out for comparison.

The overall situation of the Debug log of the two requests is as follows, the left is the first request, and the right is the second request:

You can see that the first request has more logs than the second request.

Explain what the problem is?

Does it explain the method called by the first request a little more?

Why a little more, and which methods are only called once?

I don't know either, but I can sort it out from the Debug log.

For example, the following picture is the log of the first request for multiple printing that has been sorted out:

Soon I saw something in the Debug log that I thought was suspicious:

Start processing with input [age=18]

This line of log is only printed when the first request is made. From the meaning of the log, it is the age=18 in the processing request.

Why doesn't it print the second time?

I don't know either, but I know where the first critical breakpoint is.

The global search keyword "Start processing with input" can find "parameters.bytes" in the configuration file.

Then search for "parameters.bytes" globally, and you can find the output in the Parameters.java file:

That is this place:

org.apache.tomcat.util.http.Parameters#processParameters(byte[], int, int, java.nio.charset.Charset)

When you find the first breakpoint, you find a breakthrough. As long as you hold it well, things will basically go smoothly after that.

First, restart the project, make the call, and look at the call stack at the breakpoint:

What's the next thought?

It's just that I'm going to find something from the stack.

You think, the first request goes to this place, and the second request does not go to this place, so there must be a logic similar to this:

 if(满足某个条件){
    走processParameters方法
}

So, just need to go back five call stacks, I found this method:

org.apache.catalina.connector.Request#getParameter

At this time, you can see that the parametersParsed parameter next to it is true. It stands to reason that true should not enter the if branch?

Because here we are looking back from the stack information at the breakpoint, between the parseParameters method and the processParameters method, there must be a place to modify the value of the parametersParsed parameter to true.

This can also be seen from the initial value of parametersParsed being false:

Therefore, I decided to hit the second breakpoint in the getParameter method:

Restart the service again, initiate a call, parametersParsed is false, and start executing the parseParameters() method to parse the parameters:

One of the purposes of parsing the parameters is to put my age=18 in the paramHashValues Map container:

org.apache.tomcat.util.http.Parameters#addParameter

After the parseParameters() method is executed, the 18 corresponding to age is returned from the previous paramHashValues container:

But, friends, notice the place marked ① in the picture above:

This method is also called in the parseParameters method:

org.apache.tomcat.util.http.Parameters#handleQueryParameters

All right, get up and listen to me now.

The handleQueryParameters method is the method that actually parses the parameters. In order to prevent repeated parsing, it adds the following logic:

didQueryParameters is initially false and then set to true.

This is easy to understand. The input parameter is parsed once, and the parsed product is a Map, and then the value corresponding to the parameter needs to be obtained from the Map.

For example, I modified the input parameters to this:

http://127.0.0.1:8080/getTest?a=1&b=2&c=3&d=4

Then after parsing, the Map becomes like this:

After the previous tossing, I now found a way to parse the input parameters.

Then the key point of the full text is the change of the parameter didQueryParameters.

Only when it is false will the input parameters be parsed.

Then my next troubleshooting idea is to observe the changes of the didQueryParameters parameters, so put a breakpoint on the field, restart the project, and continue debugging:

When entering this method for the first time, didQueryParameters is false, and the input parameter is age=18:

The reason for entering this method for the first time, as I said before, is because the logic of parseParameters is triggered:

The second time you enter this method, didQueryParameters becomes true, so you don't need to parse it again:

So what is the reason for entering this method for the second time?

As mentioned earlier, the first line of the getParameter method is the logic that triggers the parsing:

Next, the breakpoint stops at this place:

org.apache.tomcat.util.http.Parameters#recycle

The method is called recycle, which indicates that it is recycling, in which the Map that stores the parameters will be emptied, and didQueryParameters will be set to false again.

And when you use the same method to observe the parametersParsed parameter, which is this parameter:

You will find that it also has a recycle method:

org.apache.catalina.connector.Request#recycle

The annotation on this method also has a particularly eye-catching word: reuse.

The annotation comes like this: release all object references and initialize instance variables in preparation for reusing the object.

There are various indications that the request is recycled in tomcat.

Although I also knew that it was recycled before this, but seeing it is better than seeing it. This time I saw it with my own eyes when I was debugging.

Another small detail.

Since we also triggered the getParameter method once in the asynchronous thread:

However, the getTest method has completed the response, and the Request may have completed recycling at this time.

Note that I said "maybe", because at this time, the recycling action of the Request and the asynchronous thread are not necessarily the first.

This also explains the phenomenon:

Although the request is passed into the asynchronous thread, the corresponding parameters can still be obtained from it.

Because the recovery action of the request has not been completed at this time, you can continue to obtain parameters.

In order to avoid this "possible", I adjusted the sleep time to 5s to ensure that the request completes the recovery.

Then continue to debug in this asynchronous thread, and then the magic will start.

When handleQueryParameters is triggered again, didQueryParameters becomes false because it is recycle.

Then execute the parsing logic and set didQueryParameters to true.

However, we can see that the content of the query is gone at this time, it is null:

This is easy to understand, it must be recycle with the end of the call:

So, here I can answer why the output in the asynchronous thread is null.

queryMB is the age=18 passed in when I called it.

Through Debug, it is found that there is no queryMB when calling getParameter in the asynchronous thread, so the Map will not be parsed.

Without Map, the output inside an asynchronous thread is definitely null.

Why no queryMB?

Because the current request has been returned, and recycle related operations have been performed, queryMB is not available at this time.

So why does this magical phenomenon occur when the call is made again?

Very simple, because didQueryParameters is set to true when calling getParameter in the asynchronous thread.

However, the call in the asynchronous thread exceeds the life cycle of the request, so the recycle related operation of the request will not be triggered again, so didQueryParameters is still true when the request is reused.

Therefore, from the Debug point of view, although queryMB is valuable, it is useless, didQueryParameters is true, the program returns directly, and will not parse your input parameters:

Questions answered.

At this point, let's go back to the original method:

Do you think about why there is an exception when this method is called?

It's still the same reason, because the request is multiplexed, although you pass in the parameter b, but because the previous request called the getParameter method in the asynchronous thread, and set didQueryParameters to true, the program will not parse the input I pass in. of a=1&b=2.

From the point of view of the calling link, although we are calling this link:

http://127.0.0.1:8080/getParams?a=1&b=2

But for programs it is equivalent to this link:

http://127.0.0.1:8080/getParams

Since the input parameter b is of type int, isn't that throwing this exception:

This exception means: buddy, you either make b of type Integer, and I will assign null to you if you don't pass a value. Either pass me a value.

Now you use int to accept, and you don't give me the value, I can't handle it?

Can I give you a default value of 0?

Of course not, 0 and null are not the same meaning, what if your program goes wrong, what should I do?

Forget it, I'll throw an exception, it's the safest.

So you see, if you look for the answer from this place where the exception is thrown, you might find it, but it's a bit further down the road.

Because this place is not the root cause of the problem.

At this point, you should know exactly what happened to this bug.

request life cycle

In the process of exploring this problem, I also thought of another question:

What is the life cycle of a request request?

I remember me reciting this question a few years ago, and I can't really remember it now, but I know where to look for the answer.

Java Servlet Specification, which is a specification, the answer is hidden in this specification:

https://javaee.github.io/servlet-spec/downloads/servlet-4.0/servlet-4_0_FINAL.pdf

In section 3.13, regarding the life cycle of the request object, the specification says:

These few words are very important, so I will disassemble them sentence by sentence for you to see.

Each request object is valid only within the scope of a servlet's service method, or within the scope of a filter's doFilter method, unless the asynchronous processing is enabled for the component and the startAsync method is invoked on the request object.

It's a long sentence at first, but don't panic at all.

You know, my English level is always OK.

Break the long sentences into shorter ones first, I can only translate the part before unless.

The previous section said: Each request object is only valid within the scope of the servlet's service method, or within the scope of the filter's doFilter method.

Then it comes with an unless, which means a turning point, similar to but.

We mainly focus on the sentence after unless:

the asynchronous processing is enabled for the component and the startAsync method is invoked on the request object.

The component's asynchronous processing is enabled, and the startAsync method is called on the request.

That is to say, the life cycle of the request is a bit special when it encounters asynchrony, but this asynchrony is not the kind of asynchrony I demonstrated earlier.

Regarding asynchrony, the specification mentions that there is a method in the request: startAsync.

I took a look and it turned out to be:

The return value is something called AsyncContext.

But I pressed the table first, and then went down to translate.

In the case where asynchronous processing occurs, the request object remains valid until complete is invoked on the AsyncContext.

In the case of asynchronous processing, the life cycle of the request object continues until the complete method is called on the AsyncContext.

Here is another complete method, which is invoked on the AsyncContext.

What is AsyncContext?

Isn't it the return value of the request.startAsync() method?

Sure enough, there is a complete method in AsyncContext:

Don't panic, continue to press the watch, it will be recovered in a while, and then look down.

Containers commonly recycle request objects in order to avoid the performance overhead of request object creation.

Containers typically recycle request objects to avoid the performance overhead of creating request objects.

When we see this recycle, we are very familiar. The original specification recommends that when implementing requests in containers, try to reuse them instead of recycling them, in order to save performance.

This stuff is a windfall.

The last sentence is this:

The developer must be aware that maintaining references to request objects for which startAsync has not been called outside the scope described above is not recommended as it may have indeterminate results.

This sentence is to say: Programmer friends must be aware that I do not recommend maintaining a reference to request outside the above scope, because it may produce indeterminate results.

I'm happy to see this "indeterminate result" because I've demonstrated it before and it does produce inexplicable results.

But the specification adds a qualifier before "scope": startAsync has not been called.

On the other hand, it means that if you have a request that calls the startAsync method, you can also operate the request outside the above scope, and there will be no problem.

Throughout this entire passage, we have distilled two key approaches:

• request's startAsync method
• The complete method of AsyncContext

According to the specification, these two methods are the correct way to open request asynchronous programming.

the correct way to open

Until then, assume you don't know the startAsync and complete methods at all.

But after reading the description in the specification, I can guess that the code should be written like this, and then make multiple calls without any problems:

This is the correct way to open.

Phenomenally speaking, after the getTest request returns, the request thread is not recycled by calling the recycle method.

Why is it possible to realize the asynchrony of the request by writing this way?

If you think about it with your toes, you can think that there must be such a judgment logic:

 if(调用过request的startAsync方法){
    先不回收
}

So, using the previous method, break the point on the recycle method, and look back, you can quickly find this method:

Then, about the complete method of AsyncContext, I also noticed that it has such a description:

That is to say, the response stream will not be closed until the complete method is called, so the interesting thing is:

I can operate not only the request but also the response in the asynchronous thread.

But on second thought, since it is all asynchronous programming, the significance of operating the response must be greater than the significance of operating the request.

There is still a lot to explore about Tomcat's support for asynchronous requests, so let's play it slowly.

When I wrote this, I found that the title was wrong. The title was: Never pass Request to an asynchronous thread! There is a pit!

The correct statement should be:

Don't just pass the Request to an asynchronous thread! There is a pit! You can't handle it, you have to use the startAsync method.

Well, that's it, this article is almost done here.

This article mainly shares the strange phenomenon and troubleshooting method after the request is placed in the asynchronous thread, and finally gives the correct opening method.

I hope you can master such a problem-solving method, don't be afraid of the problem, and try to do it.

Then, in fact, compared with BUG troubleshooting, knowledge about asynchronous programming of requests is more important. This article is just a small introduction. If this knowledge is blank for you, I hope you are interested and study it yourself. Very valuable.

Finally, what I want to say is a message about the previous article:

From seeing this phenomenon to writing this article, I have been debugging the program continuously, restarting the service nearly 100 times at least, and making hundreds of requests. I also took some detours in the source code, and finally I saw the root cause of this problem.

So, my experience in troubleshooting is one word:

Welcome to the public account [why technology], the article will be published on the whole network.