Form fields are null in the Request object in Jetty 12.0.15

[keenuser]

Jetty version(s)
Jetty 12.0.15

Jetty Environment
EE8

Java version/vendor (use: java -version)
OpenJDK 21.0.2

OS type/version
Windows Server 2016

Description
I am using a custom request logger (MyJettyRequestLogger) to log some custom attributes into Jetty request logs. Things were working fine with Jetty 10.x, but broken in Jetty 12.0.15 for me. Here is the simplified implementation (changed a few things according to Jetty 12, earlier I was directly using HttpServletRequest objects in MyJettyRequestLogger class):

import java.util.Set;

import org.eclipse.jetty.http.HttpURI;
import org.eclipse.jetty.server.CustomRequestLog;
import org.eclipse.jetty.server.Request;
import org.eclipse.jetty.server.Response;
import org.eclipse.jetty.util.Fields;

public class MyJettyRequestLogger extends CustomRequestLog
{
   private static final Set<String> auditUrls = Set.of("/system/web/controller/platform/common/search/getcustomersearchresult.jsp");

   public MyJettyRequestLogger(Writer writer, String logStr)
   {
      super(writer, logStr);
   }

   @Override
   public void log(Request request, Response response)
   {
      setCustomAttributesToLog(request, response);
      super.log(request, response);
   }

   private void setCustomAttributesToLog(Request request, Response response)
   {
      String requestURI = HttpURI.build(request.getHttpURI()).getPath();
      String auditParams = setAuditAttributes(request, requestURI);
      if (!auditParams.isEmpty())
         request.setAttribute("auditParams", auditParams);

   }

   private String setAuditAttributes(Request request, String requestURI)
   {
      StringBuilder logBuffer = new StringBuilder();
      if ("post".equalsIgnoreCase(request.getMethod()) && auditUrls.contains(requestURI))
      {
         try
         {
            Fields params = Request.getParameters(request); // PROBLEM HERE
            if (params != null)
            {
               boolean first = true;
               logBuffer.append("[Params:");
               for (Fields.Field param : params)
               {
                  if (first)
                     first = false;
                  else
                     logBuffer.append("&");
                  logBuffer.append(param.getName()).append("=").append(String.join(",", param.getValues()));
               }
               logBuffer.append("] ");
            }
         }
         catch (Exception e)
         {
            throw new RuntimeException(e);
         }
      }
      return logBuffer.toString();
   }
}

In the above code Request.getParameters(request) is giving me query parameters but not the form field parameters in the POST request. After debugging it into Jetty's code, I came to know that form field parameters are returned as NULL from the following method from org.eclipse.jetty.server.Request

static CompletableFuture<Fields> getParametersAsync(Request request)
{
    Fields queryFields = Request.extractQueryParameters(request);
    CompletableFuture<Fields> contentFields = FormFields.from(request);
    return contentFields.thenApply(formFields -> Fields.combine(queryFields, formFields));
}

Note that I am using EE8 for deploying my war. What am I doing wrong here?

Thanks in advance for any help.

Here is the request block as I captured using chrome developer tool:

"request": {
          "method": "POST",
          "url": "https://eg5590ain.mydev.net/system/web/controller/platform/common/search/getcustomersearchresult.jsp?_dc=1735640244596&__token__=8b83dcc7-43c2-4e33-a27b-02f8793ecb83",
          "httpVersion": "http/2.0",
          "headers": [
            {
              "name": ":authority",
              "value": "eg5590ain.mydev.net"
            },
            {
              "name": ":method",
              "value": "POST"
            },
            {
              "name": ":path",
              "value": "/system/web/controller/platform/common/search/getcustomersearchresult.jsp?_dc=1735640244596&__token__=8b83dcc7-43c2-4e33-a27b-02f8793ecb83"
            },
            {
              "name": ":scheme",
              "value": "https"
            },
            {
              "name": "accept",
              "value": "application/json"
            },
            {
              "name": "accept-encoding",
              "value": "gzip, deflate, br, zstd"
            },
            {
              "name": "accept-language",
              "value": "en-us"
            },
            {
              "name": "content-length",
              "value": "556"
            },
            {
              "name": "content-type",
              "value": "application/x-www-form-urlencoded; charset=UTF-8"
            },
            {
              "name": "origin",
              "value": "https://eg5590ain.mydev.net"
            },
            {
              "name": "priority",
              "value": "u=1, i"
            },
            {
              "name": "referer",
              "value": "https://eg5590ain.mydev.net/system/web/apps/agent/"
            },
            {
              "name": "sec-ch-ua",
              "value": "\"Google Chrome\";v=\"131\", \"Chromium\";v=\"131\", \"Not_A Brand\";v=\"24\""
            },
            {
              "name": "sec-ch-ua-mobile",
              "value": "?0"
            },
            {
              "name": "sec-ch-ua-platform",
              "value": "\"Windows\""
            },
            {
              "name": "sec-fetch-dest",
              "value": "empty"
            },
            {
              "name": "sec-fetch-mode",
              "value": "cors"
            },
            {
              "name": "sec-fetch-site",
              "value": "same-origin"
            },
            {
              "name": "user-agent",
              "value": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/131.0.0.0 Safari/537.36"
            },
            {
              "name": "x-requested-with",
              "value": "XMLHttpRequest"
            }
          ],
          "queryString": [
            {
              "name": "_dc",
              "value": "1735640244596"
            },
            {
              "name": "__token__",
              "value": "8b83dcc7-43c2-4e33-a27b-02f8793ecb83"
            }
          ],
          "cookies": [],
          "headersSize": -1,
          "bodySize": 556,
          "postData": {
            "mimeType": "application/x-www-form-urlencoded; charset=UTF-8",
            "text": "customer.customer_type%231=casemgmt%3A%3Acustomer_search_data%23%253D%253D%23and%23false%23false%23-1%23i%231%231&id=-1&type=customer&language=en&country=us&fromIndex=0&sortCol=1&pageSize=50&ascending=false&__time__=1735640244591&page=1&start=0&limit=25&language=en&country=us",
            "params": [
              {
                "name": "customer.customer_type%231",
                "value": "casemgmt%3A%3Acustomer_search_data%23%253D%253D%23and%23false%23false%23-1%23i%231%231"
              },
              {
                "name": "type",
                "value": "customer"
              },
              {
                "name": "language",
                "value": "en"
              },
              {
                "name": "country",
                "value": "us"
              },
              {
                "name": "fromIndex",
                "value": "0"
              },
              {
                "name": "sortCol",
                "value": "1"
              },
              {
                "name": "pageSize",
                "value": "50"
              },
              {
                "name": "ascending",
                "value": "false"
              },
              {
                "name": "__time__",
                "value": "1735640244591"
              },
              {
                "name": "page",
                "value": "1"
              },
              {
                "name": "start",
                "value": "0"
              },
              {
                "name": "limit",
                "value": "25"
              },
              {
                "name": "language",
                "value": "en"
              },
              {
                "name": "country",
                "value": "us"
              }
            ]
          }
        }

[joakime]

Did any code access the request body before the MyJettyRequestLogger kicked in?

[joakime]

Also, use 12.0.16, as Request.getParametersAsync(Request request) is now deprecated.
That code path is different now.

[keenuser]

Did any code access the request body before the MyJettyRequestLogger kicked in?

Probably yes (there are bunch of filters so need some time to figure out). Does it matter?

Also, use 12.0.16, as Request.getParametersAsync(Request request) is now deprecated. That code path is different now.

Will give it a try. Thanks.

[joakime]

Did any code access the request body before the MyJettyRequestLogger kicked in?

Probably yes (there are bunch of filters so need some time to figure out). Does it matter?

Yes, it matters.

If nothing accessed the Request body content, and then you reach the RequestLog the Request & Response are complete, there's no longer an opportunity to read the request at that point in time.

If nothing read the body for the request parameters, then there's no content left at RequestLog time to read the request parameters.

[keenuser]

Also, use 12.0.16, as Request.getParametersAsync(Request request) is now deprecated. That code path is different now.

This did not work, same issue as 12.0.15.

Did any code access the request body before the MyJettyRequestLogger kicked in?

Probably yes (there are bunch of filters so need some time to figure out). Does it matter?

Yes, it matters.

If nothing accessed the Request body content, and then you reach the RequestLog the Request & Response are complete, there's no longer an opportunity to read the request at that point in time.

If nothing read the body for the request parameters, then there's no content left at RequestLog time to read the request parameters.

Is there any change in Jetty 12.0.15 as compared to Jetty 10.0.24 in this regard? The exact same code works in Jetty 10.

[joakime]

Is there any change in Jetty 12.0.15 as compared to Jetty 10.0.24 in this regard? The exact same code works in Jetty 10.

That shouldn't have worked in Jetty 10 either.
The same rules have applied since Jetty 9.4.0.

We've even submitted PRs / fixes to other projects that did the same thing.

• Fixing behavior of logback-access in the modern era qos-ch/logback#532

To state this as simply as possible.

"You cannot cause HTTP I/O during RequestLog."

Using a features like Request.getParameters() will cause I/O if not read before.

If you follow the 12.0.x source for that method, you'll see that it will access the Request Attributes to find previously parsed FormFields, that's the only case which is guaranteed to work during RequestLog.

Same is true for Jetty 10.0.x, see the _contentParamsExtracted field on org.eclipse.jetty.server.Request object.

[keenuser]

Apologies for the late reply.

If I debug through my code, I could get all the form parameters using httpServletRequest.getParameterMap() in the servlet filters at multiple places, which are getting called before MyJettyRequestLogger. So as you are saying, I think the request body stream is already read so org.eclipse.jetty.server.Request doesn't find anything in the form fields.

This was working in Jetty 10 because org.eclipse.jetty.server.Request was extending HttpServletRequest which could give the parameters read beforehand. If I could find a way to to access HttpServletRequest object through org.eclipse.jetty.server.Request object, I think it would solve my problem.

Is there any way to do that? I just need the parameters and nothing else from request body, so it's fine if I could store the parameters from HttpServletRequest somewhere and access it later in org.eclipse.jetty.server.Request object.

[gregw]

If the request params have been read correctly at any stage, then they should always be available as request attributes. So the params from HttpServletRequest should already be stored for you.

So have a look at request attribute org.eclipse.jetty.server.FormFields and see if they are there.

You can access this directly or via some of the static methods on FormFields

[joakime]

@keenuser check the example project at https://github.com/jetty/jetty-examples/tree/12.0.x/embedded/requestlog

The files you want to pay attention to are ...

• examples/ParamRequestLogDemo.java - the setup of the server, a few handlers where some read the parameters, and some don't, along with the addition of the ParamRequestLog to the server.
• examples/ParamRequestLog.java - the implementation of RequestLog that logs parameters (both query and request body form-fields)
• examples/ParamRequestLogDemoTest.java - the test cases, some that cause a parameter read, others that don't. pay attention to the logging output.

[keenuser]

If the request params have been read correctly at any stage, then they should always be available as request attributes. So the params from HttpServletRequest should already be stored for you.

So have a look at request attribute org.eclipse.jetty.server.FormFields and see if they are there.

You can access this directly or via some of the static methods on FormFields

I am getting FormFields as null in both Jetty 12.0.15 and 12.0.16.

@keenuser check the example project at https://github.com/jetty/jetty-examples/tree/12.0.x/embedded/requestlog

The files you want to pay attention to are ...

• examples/ParamRequestLogDemo.java - the setup of the server, a few handlers where some read the parameters, and some don't, along with the addition of the ParamRequestLog to the server.
• examples/ParamRequestLog.java - the implementation of RequestLog that logs parameters (both query and request body form-fields)
• examples/ParamRequestLogDemoTest.java - the test cases, some that cause a parameter read, others that don't. pay attention to the logging output.

Thanks for this. But I am getting null in Object attr in the below method, when I use it in MyJettyRequestLogger :

private Fields getRequestFormFields(Request request)
	{
		Object attr = request.getAttribute(FormFields.class.getName());
		if (attr instanceof FormFields futureFormFields)
		{
			try
			{
				return futureFormFields.get();
			}
			catch (InterruptedException | ExecutionException e)
			{
				return null;
			}
		}
		else if (attr instanceof Fields fields)
		{
			return fields;
		}
		return null;
	}

[joakime]

Thanks for this. But I am getting null in Object attr in the below method, when I use it in MyJettyRequestLogger

That is what happens if no endpoint read request form data.
See the test cases and the tests against the endpoint /no-read/ to see the behavior.

The tests against /read/ do read the parameters and request form data.
And those will work as intended.

In short, this is expected behavior, there is no I/O during RequestLog.