search

payara / Payara

Payara Server is an open source middleware platform that supports reliable and secure deployments of Java EE (Jakarta EE) and MicroProfile applications in any environment: on premise, in the cloud or hybrid.
http://www.payara.fish
Other
883 stars 306 forks source link

Bug Report: HTTP Access Logging using SSE broadcaster prints warnings / FISH-6294 #5745

Open marcreichman opened 2 years ago

marcreichman commented 2 years ago

Description

When using an SSE broadcaster, with an @ApplicationScoped JAX-RS resource, as is needed to maintain the broadcaster state, warnings show up in the log only if access logging is enabled.

This appears to be similar to #2261. However, that fix does not seem to affect this.

Expected Outcome

It's expected that warnings are not logged in a way that differs only if access logging is turned on.

Current Outcome

With access logging on, the following shows in the log:

.....

'payara-sse-access-log-issue' REST Endpoints:
GET /payara-sse-access-log-issue/api/application.wadl
GET /payara-sse-access-log-issue/api/sse
POST    /payara-sse-access-log-issue/api/sse

[2022-05-10T11:56:36.795-0500] [] [INFO] [] [PayaraMicro] [tid: _ThreadID=1 _ThreadName=main] [timeMillis: 1652201796795] [levelValue: 800] Payara Micro  5.2022.2 #badassmicrofish (build 306) ready in 15,742 (ms)

[2022-05-10T11:56:52.218-0500] [] [WARN] [] [org.jboss.weld.Servlet] [tid: _ThreadID=88 _ThreadName=http-thread-pool::http-listener(2)] [timeMillis: 1652201812218] [levelValue: 900] WELD-000714: HttpContextLifecycle guard leak detected. The Servlet container is not fully compliant. The value was 1

[2022-05-10T11:56:52.219-0500] [] [WARN] [] [org.jboss.weld.Context] [tid: _ThreadID=88 _ThreadName=http-thread-pool::http-listener(2)] [timeMillis: 1652201812219] [levelValue: 900] WELD-000225: Bean store leak detected during org.jboss.weld.module.web.context.http.HttpRequestContextImpl association: org.apache.catalina.connector.RequestFacade@23de2e01

[2022-05-10T11:56:52.219-0500] [] [WARN] [] [org.jboss.weld.Context] [tid: _ThreadID=88 _ThreadName=http-thread-pool::http-listener(2)] [timeMillis: 1652201812219] [levelValue: 900] WELD-000225: Bean store leak detected during org.jboss.weld.module.web.context.http.HttpSessionContextImpl association: org.apache.catalina.connector.RequestFacade@23de2e01

[2022-05-10T11:56:52.223-0500] [] [WARN] [] [org.jboss.weld.Conversation] [tid: _ThreadID=88 _ThreadName=http-thread-pool::http-listener(2)] [timeMillis: 1652201812223] [levelValue: 900] WELD-000335: Conversation context is already active, most likely it was not cleaned up properly during previous request processing: org.apache.catalina.connector.RequestFacade@23de2e01

With access logging off, the latter lines do not show up.

Steps to reproduce

Here is a sample project which can reproduce this easily. I have tested with Payara Micro Community 5.2022.2 but this has shown up in Payara Server as well, including a previous version 5.201.

https://gitlab.com/mreichman/payara-sse-access-log-issue

The README.md file shows the different command lines and reproduction steps once built.

Environment

JamesHillyard commented 2 years ago

Hi @marcreichman,

I am able to successfully reproduce this issue, thank you very much for your detailed reproducer. I have raised an internal issue FISH-6294 to address this bug. We always encourage you to contribute, so if you wish you can submit a PR with a fix and we will gladly review it. Otherwise, we will pick up the issue at some point in the future.

Thanks, James

marcreichman commented 2 years ago

Appreciate the attention. I am not qualified enough to work on a fix!

saikumar1607 commented 1 year ago

I tried using @Singleton annotation instead of @ApplicationScoped. No WELD warnings and application worked the same way as with @ApplicationScoped

rdelaplante commented 2 months ago

I am still able to reproduce this issue on Payara 6.2024.8 on JDK 17.0.12+7 in September of 2024. I logged into the Payara web admin GUI, navigated to Configurations --> server-config --> HTTP Service, then checked the "Enabled" checkbox beside "Access Logging" and saved. It doesn't matter if I test my application before or after restarting Payara Server, I see the following warnings when access logging is enabled:

[2024-09-03T09:52:58.808-0400] [Payara 6.2024.8] [WARN] [] [org.jboss.weld.Servlet] [tid: _ThreadID=2183 _ThreadName=glassfish-web-async-thread-1] [timeMillis: 1725371578808] [levelValue: 900] [[
  WELD-000715: HttpContextLifecycle guard not set. The Servlet container is not fully compliant.]]

[2024-09-03T09:52:59.213-0400] [Payara 6.2024.8] [WARN] [] [org.jboss.weld.Servlet] [tid: _ThreadID=137 _ThreadName=http-thread-pool::http-listener-2(1)] [timeMillis: 1725371579213] [levelValue: 900] [[
  WELD-000714: HttpContextLifecycle guard leak detected. The Servlet container is not fully compliant. The value was 1]]

[2024-09-03T09:52:59.214-0400] [Payara 6.2024.8] [WARN] [] [org.jboss.weld.Context] [tid: _ThreadID=137 _ThreadName=http-thread-pool::http-listener-2(1)] [timeMillis: 1725371579214] [levelValue: 900] [[
  WELD-000225: Bean store leak detected during org.jboss.weld.module.web.context.http.HttpRequestContextImpl association: org.apache.catalina.connector.RequestFacade@1bbd309d]]

[2024-09-03T09:52:59.214-0400] [Payara 6.2024.8] [WARN] [] [org.jboss.weld.Context] [tid: _ThreadID=137 _ThreadName=http-thread-pool::http-listener-2(1)] [timeMillis: 1725371579214] [levelValue: 900] [[
  WELD-000225: Bean store leak detected during org.jboss.weld.module.web.context.http.HttpSessionContextImpl association: org.apache.catalina.connector.RequestFacade@1bbd309d]]

[2024-09-03T09:52:59.214-0400] [Payara 6.2024.8] [WARN] [] [org.jboss.weld.Conversation] [tid: _ThreadID=137 _ThreadName=http-thread-pool::http-listener-2(1)] [timeMillis: 1725371579214] [levelValue: 900] [[
  WELD-000335: Conversation context is already active, most likely it was not cleaned up properly during previous request processing: org.apache.catalina.connector.RequestFacade@1bbd309d]]
rdelaplante commented 2 months ago

The description says this happens when using an @ApplicationScoped JAX-RS resource. My application exposes a JSON API using JAX-RS, but I was able to cause these log messages just by clicking around JSF web pages. The application does use CDI.

marcreichman-pfi commented 2 months ago

Hi @rdelaplante thanks for finding another way to reproduce this.

My original case involved using SSE broadcaster resources which implies async. It's possible the JSF path uses similar kinds of logic.

I think they were also able to reproduce this but more paths into the same bug always helps them I'm sure.