jersey
jersey copied to clipboard
eclipse-ee4j
Server 500 Error COnn Close, Jersey 200 OK
Continuously and absolute randomly receiving Internal server erro 500 while all code executing perfectly, logs show that method called was proper, all code executed and results returned in desired manner.
On top of all after going through Jersey "Monitoring Statistics as MBeans" the last method return code is 200 but Rest client always show 500.
Noticeable thing is that unlimited times first time 500 error come and then every thing goes fine on second time, and usually always 500 error come until i make some irrelevant change in code and redeploy.
Environment
Windows 7 Local Machine, Linux on AWS Virtual Server Tomcat 8.0.36, Tomcat 9.0, Jetty 9.3.11.v20160721
Affected Versions
[2.23]
- Issue Imported From: https://github.com/jersey/jersey/issues/3428
- Original Issue Raised By:@glassfishrobot
- Original Issue Assigned To: @mpotociar
@glassfishrobot Commented @pavelbucek said: I'm pretty sure there is some exception logged on the server side. Can you please add it to your report?
Also, reproducible testcase is always appreciated. (you can state that it is reproducible on one of our samples, if you are able to verify that).
@glassfishrobot Commented khurram_kk said: Not a single exception, Below is the server side log, I also enabled Jersey logging
INFO: Server startup in 17087 ms
Aug 22, 2016 10:56:05 AM org.glassfish.jersey.filter.LoggingFilter log
INFO: 1 * Server has received a request on thread http-nio-8080-exec-2
1 > POST http://localhost:8080/core/v1/auth/loginVendor 1 > accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
1 > accept-encoding: gzip, deflate
1 > accept-language: null
1 > connection: keep-alive
1 > content-length: 81
1 > content-type: application/json
1 > host: localhost:8080
1 > user-agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:47.0) Gecko/20100101 Firefox/47.0
10:56:05.759 [http-nio-8080-exec-2] DEBUG com.stepSolar.web.rest.auth.filter.GlobalRsRequestAuthFilter - Token recieved from headers : null
10:56:05.764 [http-nio-8080-exec-2] DEBUG com.stepSolar.web.rest.auth.filter.GlobalRsRequestAuthFilter - In Auth filter loginOrSignupReq : true - request.getRequestURL() : http://localhost:8080/core/v1/auth/loginVendor 10:56:05.764 [http-nio-8080-exec-2] DEBUG com.stepSolar.web.rest.auth.filter.GlobalRsRequestAuthFilter - uri : /core/v1/auth/loginVendor
10:56:06.037 [http-nio-8080-exec-2] DEBUG com.stepSolar.web.rest.auth.filter.GlobalAuthorizationFilter - here . . .
10:56:06.040 [http-nio-8080-exec-2] DEBUG com.stepSolar.web.rest.auth.filter.GlobalAuthorizationFilter - npe : null
10:56:06.040 [http-nio-8080-exec-2] DEBUG com.stepSolar.web.rest.auth.filter.GlobalAuthorizationFilter - In isLoginOrSignupReq : true
10:56:07.243 [http-nio-8080-exec-2] INFO com.stepSolar.web.rest.auth.AuthRS - login request starts.
Aug 22, 2016 10:56:09 AM com.mongodb.diagnostics.logging.JULLogger log
INFO: Cluster created with settings {hosts=[127.0.0.1:27017], mode=MULTIPLE, requiredClusterType=UNKNOWN, serverSelectionTimeout='30000 ms', maxWaitQueueSize=500}
Aug 22, 2016 10:56:09 AM com.mongodb.diagnostics.logging.JULLogger log
INFO: Adding discovered server 127.0.0.1:27017 to client view of cluster
Aug 22, 2016 10:56:09 AM com.mongodb.diagnostics.logging.JULLogger log
INFO: No server chosen by ReadPreferenceServerSelector{readPreference=primary} from cluster description ClusterDescription{type=UNKNOWN, connectionMode=MULTIPLE, all=[ServerDescription{address=127.0.0.1:27017, type=UNKNOWN, state=CONNECTING}]}. Waiting for 30000 ms before timing out
Aug 22, 2016 10:56:09 AM com.mongodb.diagnostics.logging.JULLogger log
INFO: Opened connection [connectionId{localValue:1, serverValue:1}] to 127.0.0.1:27017
Aug 22, 2016 10:56:09 AM com.mongodb.diagnostics.logging.JULLogger log
INFO: Monitor thread successfully connected to server with description ServerDescription{address=127.0.0.1:27017, type=STANDALONE, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 2, 1]}, minWireVersion=0, maxWireVersion=4, maxDocumentSize=16777216, roundTripTimeNanos=8650665}
Aug 22, 2016 10:56:09 AM com.mongodb.diagnostics.logging.JULLogger log
INFO: Discovered cluster type of STANDALONE
Aug 22, 2016 10:56:09 AM com.mongodb.diagnostics.logging.JULLogger log
INFO: Opened connection [connectionId{localValue:2, serverValue:2}] to 127.0.0.1:27017
10:56:10.866 [http-nio-8080-exec-2] WARN org.hibernate.ogm.id.impl.OgmSequenceGenerator - OGM000060: Sequence id generator used for entity 'InstallerPackaging' is not supported by grid dialect org.hibernate.ogm.datastore.mongodb.MongoDBDialect, falling back to table-based id generation. Consider to use @TableGenerator rather than @SequenceGenerator.
10:56:10.875 [http-nio-8080-exec-2] WARN org.hibernate.ogm.id.impl.OgmSequenceGenerator - OGM000060: Sequence id generator used for entity 'Currency' is not supported by grid dialect org.hibernate.ogm.datastore.mongodb.MongoDBDialect, falling back to table-based id generation. Consider to use @TableGenerator rather than @SequenceGenerator.
10:56:10.876 [http-nio-8080-exec-2] WARN org.hibernate.ogm.id.impl.OgmSequenceGenerator - OGM000060: Sequence id generator used for entity 'UserRole' is not supported by grid dialect org.hibernate.ogm.datastore.mongodb.MongoDBDialect, falling back to table-based id generation. Consider to use @TableGenerator rather than @SequenceGenerator.
10:56:10.876 [http-nio-8080-exec-2] WARN org.hibernate.ogm.id.impl.OgmSequenceGenerator - OGM000060: Sequence id generator used for entity 'Installer' is not supported by grid dialect org.hibernate.ogm.datastore.mongodb.MongoDBDialect, falling back to table-based id generation. Consider to use @TableGenerator rather than @SequenceGenerator.
10:56:10.876 [http-nio-8080-exec-2] WARN org.hibernate.ogm.id.impl.OgmSequenceGenerator - OGM000060: Sequence id generator used for entity 'InstallerSize' is not supported by grid dialect org.hibernate.ogm.datastore.mongodb.MongoDBDialect, falling back to table-based id generation. Consider to use @TableGenerator rather than @SequenceGenerator.
10:56:11.883 [http-nio-8080-exec-2] WARN org.hibernate.ogm.datastore.mongodb.impl.MongoDBEntityMappingValidator - OGM001218: Cannot use primary key column name 'sequence_name' for id generator, going to use '_id' instead
10:56:11.883 [http-nio-8080-exec-2] WARN org.hibernate.ogm.datastore.mongodb.impl.MongoDBEntityMappingValidator - OGM001218: Cannot use primary key column name 'sequence_name' for id generator, going to use '_id' instead
10:56:12.103 [http-nio-8080-exec-2] INFO com.stepSolar.web.ogm.dao.UsersDao - Validate user call against user : khokhar
10:56:12.319 [http-nio-8080-exec-2] DEBUG com.stepSolar.web.ogm.dao.UsersDao - Query : {"userName":"khokhar","userPassword":"password","userRoles": {$regex : '.*vendor.*'}}
10:56:13.351 [http-nio-8080-exec-2] INFO com.stepSolar.web.ogm.dao.UsersDao - Validate user call ended against user : 1
10:56:13.355 [http-nio-8080-exec-2] DEBUG com.stepSolar.web.bl.auth.AuthBL - About to check token from cache/db if not expired and already present.
10:56:13.355 [http-nio-8080-exec-2] DEBUG com.stepSolar.web.bl.auth.AuthBL - token from cache null so about to get from db.
10:56:13.355 [http-nio-8080-exec-2] INFO com.stepSolar.web.ogm.dao.UsersDao - fetchTokenFromDbUsingUserName call against user : khokhar(id:null) - userRole : vendor - tokenID : null
10:56:14.619 [http-nio-8080-exec-2] DEBUG com.stepSolar.web.ogm.dao.UsersDao - tokenFromDb : 57a991f0fd87bf0c5c6b1800
10:56:14.646 [http-nio-8080-exec-2] INFO com.stepSolar.web.ogm.dao.UsersDao - AddReplace token call ended against user : null
10:56:14.646 [http-nio-8080-exec-2] DEBUG com.stepSolar.web.bl.auth.AuthBL - token from db OK.
10:56:14.646 [http-nio-8080-exec-2] DEBUG com.stepSolar.web.bl.auth.AuthBL - token found from cache or db so now checking expiry.
10:56:14.647 [http-nio-8080-exec-2] DEBUG com.stepSolar.web.bl.auth.AuthBL - about to check token from db for expiry.
10:56:14.743 [http-nio-8080-exec-2] DEBUG com.stepSolar.web.bl.auth.AuthBL - Token from db is unexpired.
10:56:14.744 [http-nio-8080-exec-2] DEBUG com.stepSolar.web.bl.auth.AuthBL - Setting return token to token found
10:56:14.748 [http-nio-8080-exec-2] DEBUG com.stepSolar.web.rest.auth.AuthRS - returnMessage.getData() : {"userId":"1","userName":"khokhar","userRole":"vendor","tokenExpiryStr":"2016-09-08T08:18:55.204","tokenString":"a2hva2hhcnwyMDE2LTA5LTA4VDA4OjE4OjU1LjIwNHx2ZW5kb3J8MQ==|1|vendor"}
10:56:14.748 [http-nio-8080-exec-2] INFO com.stepSolar.web.rest.auth.AuthRS - login request Ends.
Aug 22, 2016 10:56:14 AM org.glassfish.jersey.filter.LoggingFilter log
INFO: 1 * Server responded with a response on thread http-nio-8080-exec-2
1 < 200
1 < Access-Control-Allow-Headers: Content-Type, USER-TOKEN
1 < Access-Control-Allow-Methods: GET, POST, DELETE, PUT
1 < Access-Control-Allow-Origin: http://localhost:9000 1 < Content-Type: application/json
@glassfishrobot Commented khurram_kk said: I can also attach the picture for JCOnsole, where Jersey is showing 200 in LastResponseCode for the method, but cant find any link to upload pics
@glassfishrobot Commented khurram_kk said:
@POST
@Path(LOGIN_VENDOR_REQ_PATH)
@Produces(MediaType.APPLICATION_JSON)
@Consumes(MediaType.APPLICATION_JSON)
//@StepRoboticsAuthConf(rolesAllowed={UserRolesValues.VENDOR_USER,UserRolesValues.INSTALLER_USER,UserRolesValues.SALESREP_USER}) public RsRespMessageNoDb loginVendorUser(VendorUser loginReq) throws Exception {
RsRespMessageNoDb returnMessage = null;
logger.info("login request starts.");
AuthBL authBL = new AuthBL();
returnMessage = authBL.loginVendorUser(loginReq);
logger.debug("returnMessage.getData() : " + returnMessage.getData());
logger.info("login request Ends.");
return returnMessage;
}
This is the method, the returned data is even logged succesfully so for sure every thing went fine but server returning 500. I tried with fresh server installation 3 times and tried it on 3 diff tomcat and 2 diff jetty versions.
@glassfishrobot Commented khurram_kk said: Honestly I haven't tried it on any of Jersey Sample.
@glassfishrobot Commented @pavelbucek said: The problem here is that there is still not much we can do, since the code you presented doesn't seem to be reproducible anywhere else. HTTP 500 is usually produced when there is some not handled exception and it is thrown to the container. Put the processing into `try
{ .. }
catch` block and log everything which might be caught. Also, see your resource method signature - you are declaring that you are throwing an exception (maybe that is ok, if you have an exception mapper registered, but we cannot tell from what you presented).
Also, I noticed this line:
10:56:06.040 [http-nio-8080-exec-2] DEBUG com.stepSolar.web.rest.auth.filter.GlobalAuthorizationFilter - npe : null
Seems like a NPE to me.
@glassfishrobot Commented khurram_kk said: Though I have exception mapper in place but would you suggest me to check it again without throwing exception?
for the line
10:56:06.040 [http-nio-8080-exec-2] DEBUG com.stepSolar.web.rest.auth.filter.GlobalAuthorizationFilter - npe : null
This is properly handled exception, no problem at all for this line
try
{ methodRolesAllowed = resourceInfo.getResourceMethod().getAnnotation(StepRoboticsAuthConf.class) .rolesAllowed(); }
catch (NullPointerException npe)
{ logger.debug("npe : " + npe.getMessage()); methodRolesAllowed = new String[1]; methodRolesAllowed[0] = "......."; }
@glassfishrobot Commented khurram_kk said: I tried it with removing exception mapper , first time same issue second time onwards working fine, but let me tell you it usually happens like this, would you suggest me to try some other server as well.
@glassfishrobot Commented @pavelbucek said: All I'm saying is that it seems like your code is producing an unhandled exception, which is then processed by the container and returned to the client as HTTP 500.
I don't see any Jersey issue here and I cannot evaluate this based on your report, since you did not provide reproducible use case.
What I can advice is to put more loggers and see what is being logged - especially around possible exception sources. Also, if you could try to strip down your app to bare minimum, which still reproduces the issue, it might help to understand what is actually wrong.
@glassfishrobot Commented khurram_kk said: Yes I cannot provide reproduce able case in Jersey Sample, but I can provide you this app live URL where you can run and see the error coming and in logs and MOST importantly "JConsole" with help of jersey mbeans is showing jersey results 200.
@glassfishrobot Commented @pavelbucek said: I see the issue with Jersey monitoring reporting 200, but that can still be an issue with the container - that means that Jersey returned Response with HTTP 200, but maybe container wasn't able to process it (the actual cause might be in Jersey, but unfortunately, there are no usable hints in the bug report).
If I were you, I'd start a debugging session (ideally if you can isolate the "500 case"), start somewhere in ApplicationHandler#handle (just to verify the response, code there), go up to container integration code and see what is written to the container. After that, I believe you have more information and the actual root cause.
@glassfishrobot Commented @pavelbucek said: (response is written by ContainerResponseWriter, I guess you are running on top of Servlet, so see (and put a break point into) org.glassfish.jersey.servlet.internal.ResponseWriter#writeResponseStatusAndHeaders )
@glassfishrobot Commented
khurram_kk said:
Ye for sure I forgot to debug, let me debug, will come back with results
@glassfishrobot Commented khurram_kk said: break point on org.glassfish.jersey.servlet.internal.ResponseWriter#writeResponseStatusAndHeaders
LINE 169 : final String reasonPhrase = responseContext.getStatusInfo().getReasonPhrase();
at the point the the variables are below
this ResponseWriter (id=82)
contentLength 280
responseContext ContainerResponse (id=87)
closed true
mappedFromException false
messageContext OutboundMessageContext (id=86)
requestContext ContainerRequest (id=102)
status Response$Status (id=104)
code 200
family Response$Status$Family (id=115)
name "OK" (id=117)
ordinal 0
reason "OK" (id=117)
headers HeaderUtils$3 (id=93)
In rest client getting
Status Code: 500 Internal Server Error
Connection: close
Date: Mon, 22 Aug 2016 11:05:47 GMT
Server: Apache-Coyote/1.1
@glassfishrobot Commented khurram_kk said: In variables the header variable having value
{Content-Type=[application/json], Access-Control-Allow-Origin=[http://localhost:9000 ], Access-Control-Allow-Methods=[GET, POST, DELETE, PUT], Access-Control-Allow-Headers=[Content-Type, USER-TOKEN], X-Jersey-Tracing-000=[START [ ---- / ---- ms | ---- %] baseUri=[http://localhost:8080/core/] requestUri=[http://localhost:8080/core/v1/auth/signupVendor] method=[POST] authScheme=[n/a] accept=[text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8] accept-encoding=[gzip, deflate] accept-charset=n/a accept-language=[null] content-type=[application/json] content-length=[946] ], X-Jersey-Tracing-001=[START [ ---- / 0.14 ms | ---- %] Other request headers: host=[localhost:8080] user-agent=[Mozilla/5.0 (Windows NT 6.1; WOW64; rv:47.0) Gecko/20100101 Firefox/47.0] connection=[keep-alive] ], X-Jersey-Tracing-002=[PRE-MATCH [ 1.95 / 8.45 ms | 3.63 %] Filter by [org.glassfish.jersey.filter.LoggingFilter @1e3cc0ea #-2147483648]], X-Jersey-Tracing-003=[PRE-MATCH [ 3.34 / 11.87 ms | 6.22 %] Filter by [com.stepSolar.web.rest.auth.filter.GlobalRsRequestAuthFilter @290f4bcc]], X-Jersey-Tracing-004=[PRE-MATCH [ 5.48 / 11.94 ms | 10.21 %] PreMatchRequest summary: 2 filters], X-Jersey-Tracing-005=[MATCH [ ---- / 12.02 ms | ---- %] Matching path [/v1/auth/signupVendor]], X-Jersey-Tracing-006=[MATCH [ ---- / 12.08 ms | ---- %] Pattern [/application\.wadl(/)?] is NOT matched], X-Jersey-Tracing-007=[MATCH [ ---- / 12.11 ms | ---- %] Pattern [/application\.wadl(/.*)?] is NOT matched], X-Jersey-Tracing-008=[MATCH [ ---- / 12.14 ms | ---- %] Pattern [/v1/systemOffer(/.*)?] is NOT matched], X-Jersey-Tracing-009=[MATCH [ ---- / 12.16 ms | ---- %] Pattern [/v1/installer(/.*)?] is NOT matched], X-Jersey-Tracing-010=[MATCH [ ---- / 12.18 ms | ---- %] Pattern [/v1/dashboard(/.*)?] is NOT matched], X-Jersey-Tracing-011=[MATCH [ ---- / 12.22 ms | ---- %] Pattern [/v1/location(/.*)?] is NOT matched], X-Jersey-Tracing-012=[MATCH [ ---- / 12.24 ms | ---- %] Pattern [/v1/product(/.*)?] is NOT matched], X-Jersey-Tracing-013=[MATCH [ ---- / 12.27 ms | ---- %] Pattern [/v1/vendor(/.*)?] is NOT matched], X-Jersey-Tracing-014=[MATCH [ ---- / 12.29 ms | ---- %] Pattern [/v1/user(/.*)?] is NOT matched], X-Jersey-Tracing-015=[MATCH [ ---- / 12.40 ms | ---- %] Pattern [/v1/auth(/.*)?] IS selected], X-Jersey-Tracing-016=[MATCH [ ---- / 12.45 ms | ---- %] Matching path [/signupVendor]], X-Jersey-Tracing-017=[MATCH [ ---- / 12.48 ms | ---- %] Pattern [/updateVendorUser(/)?] is NOT matched], X-Jersey-Tracing-018=[MATCH [ ---- / 12.51 ms | ---- %] Pattern [/loadVendorUser/([^/]+)(/)?] is NOT matched], X-Jersey-Tracing-019=[MATCH [ ---- / 12.60 ms | ---- %] Pattern [/signupVendor(/)?] IS selected], X-Jersey-Tracing-020=[MATCH [ ---- / 12.63 ms | ---- %] Pattern [/loginVendor(/)?] is skipped], X-Jersey-Tracing-021=[MATCH [ ---- / 12.65 ms | ---- %] Pattern [/tokenauth(/)?] is skipped], X-Jersey-Tracing-022=[MATCH [ ---- / 12.67 ms | ---- %] Pattern [/logout(/)?] is skipped], X-Jersey-Tracing-023=[MATCH [ ---- / 12.69 ms | ---- %] Pattern [/qTest(/)?] is skipped], X-Jersey-Tracing-024=[MATCH [ 1.34 / 13.33 ms | 2.50 %] RequestMatching summary], X-Jersey-Tracing-025=[REQ-FILTER [ 5.06 / 18.50 ms | 9.42 %] Filter by [com.stepSolar.web.rest.auth.filter.GlobalAuthorizationFilter @785f9259]], X-Jersey-Tracing-026=[REQ-FILTER [ 5.18 / 18.60 ms | 9.64 %] Request summary: 1 filters], X-Jersey-Tracing-027=[RI [ 0.01 / 19.14 ms | 0.02 %] [org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor @bc6bef4 #10] BEFORE context.proceed()], X-Jersey-Tracing-028=[MBR [ ---- / 19.22 ms | ---- %] Find MBR for type=[com.stepSolar.web.ogm.entities.VendorUser] genericType=[com.stepSolar.web.ogm.entities.VendorUser] mediaType=[application/json] annotations=[]], X-Jersey-Tracing-029=[MBR [ ---- / 19.37 ms | ---- %] [com.fasterxml.jackson.jaxrs.json.JacksonJaxbJsonProvider @24a28bf8] IS readable], X-Jersey-Tracing-030=[MBR [ ---- / 19.41 ms | ---- %] [org.glassfish.jersey.jaxb.internal.XmlCollectionJaxbProvider$General @7a203532] is skipped], X-Jersey-Tracing-031=[MBR [ ---- / 19.44 ms | ---- %] [org.glassfish.jersey.jaxb.internal.XmlRootElementJaxbProvider$General @3db538e6] is skipped], X-Jersey-Tracing-032=[MBR [ ---- / 19.47 ms | ---- %] [org.glassfish.jersey.jaxb.internal.XmlRootObjectJaxbProvider$General @5f01bb17] is skipped], X-Jersey-Tracing-033=[MBR [ 1.48 / 20.99 ms | 2.75 %] ReadFrom by [com.fasterxml.jackson.jaxrs.json.JacksonJaxbJsonProvider @24a28bf8]], X-Jersey-Tracing-034=[RI [ 0.01 / 21.13 ms | 0.01 %] [org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor @bc6bef4 #10] AFTER context.proceed()], X-Jersey-Tracing-035=[RI [ 2.06 / 21.17 ms | 3.83 %] ReadFrom summary: 1 interceptors], X-Jersey-Tracing-036=[INVOKE [29.53 / 50.77 ms | 54.99 %] Resource [com.stepSolar.web.rest.auth.AuthRS @73b98e6a] method=[public com.stepSolar.web.messages.RsRespMessageNoDb com.stepSolar.web.rest.auth.AuthRS.addVendorUser(com.stepSolar.web.ogm.entities.VendorUser)]], X-Jersey-Tracing-037=[INVOKE [ ---- / 50.91 ms | ---- %] Response: [org.glassfish.jersey.message.internal.OutboundJaxrsResponse @1b726952 <200/SUCCESSFUL|OK|com.stepSolar.web.messages.RsRespMessageNoDb @434962c>]], X-Jersey-Tracing-038=[RESP-FILTER [ 0.03 / 51.08 ms | 0.06 %] Filter by [com.stepSolar.web.rest.auth.filter.ServerHeaderCustomizer @27bae976]], X-Jersey-Tracing-039=[RESP-FILTER [ 0.81 / 51.93 ms | 1.51 %] Filter by [org.glassfish.jersey.filter.LoggingFilter @499fcecf #-2147483648]], X-Jersey-Tracing-040=[RESP-FILTER [ 0.94 / 51.98 ms | 1.76 %] Response summary: 2 filters], X-Jersey-Tracing-041=[WI [ 0.03 / 52.18 ms | 0.06 %] [org.glassfish.jersey.filter.LoggingFilter @76aff752 #-2147483648] BEFORE context.proceed()], X-Jersey-Tracing-042=[WI [ 0.01 / 52.22 ms | 0.01 %] [org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor @bc6bef4 #10] BEFORE context.proceed()], X-Jersey-Tracing-043=[WI [ 0.02 / 52.27 ms | 0.03 %] [org.glassfish.jersey.server.internal.JsonWithPaddingInterceptor @26961f59 #4100] BEFORE context.proceed()], X-Jersey-Tracing-044=[MBW [ ---- / 52.35 ms | ---- %] Find MBW for type=[com.stepSolar.web.messages.RsRespMessageNoDb] genericType=[com.stepSolar.web.messages.RsRespMessageNoDb] mediaType=[[javax.ws.rs.core.MediaType @744ccfb1]] annotations=[@javax.ws.rs.POST(), @javax.ws.rs.Path(value=/signupVendor), @javax.ws.rs.Produces(value=[application/json]), @javax.ws.rs.Consumes(value=[application/json])]], X-Jersey-Tracing-045=[MBW [ ---- / 52.43 ms | ---- %] [com.fasterxml.jackson.jaxrs.json.JacksonJaxbJsonProvider @1565ff3a] IS writeable], X-Jersey-Tracing-046=[MBW [ ---- / 52.45 ms | ---- %] [org.glassfish.jersey.jaxb.internal.XmlCollectionJaxbProvider$General @7a203532] is skipped], X-Jersey-Tracing-047=[MBW [ ---- / 52.49 ms | ---- %] [org.glassfish.jersey.jaxb.internal.XmlRootElementJaxbProvider$General @3db538e6] is skipped], X-Jersey-Tracing-048=[MBW [ 0.99 / 53.52 ms | 1.85 %] WriteTo by [com.fasterxml.jackson.jaxrs.json.JacksonJaxbJsonProvider @1565ff3a]], X-Jersey-Tracing-049=[WI [ 0.00 / 53.59 ms | 0.01 %] [org.glassfish.jersey.server.internal.JsonWithPaddingInterceptor @26961f59 #4100] AFTER context.proceed()], X-Jersey-Tracing-050=[WI [ 0.00 / 53.62 ms | 0.01 %] [org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor @bc6bef4 #10] AFTER context.proceed()], X-Jersey-Tracing-051=[WI [ 0.00 / 53.65 ms | 0.01 %] [org.glassfish.jersey.filter.LoggingFilter @76aff752 #-2147483648] AFTER context.proceed()], X-Jersey-Tracing-052=[WI [ 1.54 / 53.67 ms | 2.87 %] WriteTo summary: 3 interceptors], X-Jersey-Tracing-053=[FINISHED [ ---- / 53.70 ms | ---- %] Response status: 200/SUCCESSFUL|OK]}
@glassfishrobot Commented @pavelbucek said: Well, that seems like Jersey returned HTTP 200 and the container converted it to something else. (Assuming that you are debugging the right requires/response pair, but I believe you do). Do you have any Servlet Filter or something like that in your application?
Also, you might want to put another breakpoint to "commit" and also continue with debugging further in the #writeResponseStatusAndHeaders method, since your request seem to have an entity and it is not read/written yet (and the error might be coming from some message body writer). #failure and #commit in the same class can be also useful, but I'd check what is happening with the response AFTER Jersey sends it back to the container.
Anyway, it really seems like "not a bug in Jersey", since everything indicates that Jersey does what it is supposed to do.
@glassfishrobot Commented khurram_kk said: I told you same in very start that jersey returning 200, it is with container.
I haven't got any servlet filter but yes there are two "ContainerRequestFilter" one is pre matching and other is defauilt i.e post matching filter.
Right let me debug into commit and failure methods. Will come up with results.
@glassfishrobot Commented khurram_kk said: Break point at Line 194
public void commit() {
try {
callSendError();********
The variables are
this ResponseWriter (id=83)
asyncExt AsyncContextDelegateProviderImpl$ExtensionImpl (id=119)
configSetStatusOverSendError false
requestTimeoutHandler JerseyRequestTimeoutHandler (id=122)
response ResponseFacade (id=124)
response Response (id=133)
appCommitted false
coyoteResponse Response (id=135)
characterEncoding "ISO-8859-1" (id=178)
charsetSet false
commited false
commitTime -1
contentLanguage null
contentLength 281
contentType "application/json" (id=181)
contentWritten 0
errorException null
fireListener false
headers MimeHeaders (id=183)
hook Http11NioProcessor (id=185)
listener null
locale Locale (id=191)
message "OK" (id=103)
nonBlockingStateLock Object (id=194)
notes Object[32] (id=195)
outputBuffer InternalNioOutputBuffer (id=196)
registeredForWrite false
req Request (id=202)
status 200
errorState AtomicInteger (id=137)
facade ResponseFacade (id=124)
format null
included false
isCharacterEncodingSet false
outputBuffer OutputBuffer (id=141)
outputStream CoyoteOutputStream (id=109)
redirectURLCC CharChunk (id=147)
request Request (id=150)
urlEncoder UEncoder (id=155)
usingOutputStream true
usingWriter false
writer CoyoteWriter (id=158)
autoFlush false
error false
formatter null
lineSeparator "\r\n" (id=164)
lock OutputBuffer (id=141)
ob OutputBuffer (id=141)
out OutputBuffer (id=141)
psOut null
trouble false
writeBuffer null
responseContext SettableFuture<V> (id=126)
executionList ExecutionList (id=168)
sync AbstractFuture$Sync<V> (id=170)
useSetStatusOn404 false
and as usual respopnse in client
Status Code: 500 Internal Server Error
Connection: close
Date: Mon, 22 Aug 2016 11:59:23 GMT
Server: Apache-Coyote/1.1
@glassfishrobot Commented khurram_kk said: Added break point on 239
public void failure(final Throwable error) {
try {
if (!response.isCommitted()) {*******
It never reached.
@glassfishrobot Commented khurram_kk said: Oooooops, even if failure is not reching and every thing fine, let me check keepAliveTimeout setting of tomcat ... as first time it takes a bit longer to initialiuze db on my side and may be timing out and second time ok......
@glassfishrobot Commented khurram_kk said: But during debug, it took very long time but connection was not closed .... confusing
@glassfishrobot Commented This issue was imported from java.net JIRA JERSEY-3156
We ran into this as well. In our case, we could track this down to the use of ServerProperties.TRACING and ServerProperties.TRACING_THRESHOLD, which we set for debugging purposes.
In our case, these features were activated in our implementation of ResourceConfig:
@ApplicationPath("/")
public class ApiApplication extends ResourceConfig {
// ...
private ApiApplication() {
// HERE
property(ServerProperties.TRACING, "ALL");
property(ServerProperties.TRACING_THRESHOLD, "TRACE");
}
It's still unclear to us why some POST requests are affected by this bug, while others are not.
Our previous workaround was to return a Reponse.ok(<resultObjectHere>) instead of the actual object, which also seemed unaffected by this bug.
@Dan1ve So you are saying the http status 500 is returned only when you use property(ServerProperties.TRACING, "ALL"); property(ServerProperties.TRACING_THRESHOLD, "TRACE"); ?
What Jersey do you use?
Excactly @jansupol , it's 100% reproducible.
We use the following Jersey packages:
compile 'org.glassfish.jersey.containers:jersey-container-servlet-core:2.28' compile 'org.glassfish.jersey.containers:jersey-container-jetty-http:2.28' compile 'org.glassfish.jersey.inject:jersey-hk2:2.28' compile 'org.glassfish.jersey.ext:jersey-entity-filtering:2.28' compile 'org.glassfish.jersey.media:jersey-media-multipart:2.28'
running with a Jetty Server (9.4.18.v20190429)
I also just ran into this issue. Further debugging revealed, that the root cause was a BufferOverflowException within Jetty, when trying to write a specific tracing header.
Full stacktrace:
java.nio.BufferOverflowException
at java.base/java.nio.Buffer.nextPutIndex(Buffer.java:722)
at java.base/java.nio.DirectByteBuffer.put(DirectByteBuffer.java:359)
at org.eclipse.jetty.http.HttpGenerator.putSanitisedValue(HttpGenerator.java:872)
at org.eclipse.jetty.http.HttpGenerator.putTo(HttpGenerator.java:894)
at org.eclipse.jetty.http.HttpGenerator.generateHeaders(HttpGenerator.java:595)
at org.eclipse.jetty.http.HttpGenerator.generateResponse(HttpGenerator.java:399)
at org.eclipse.jetty.server.internal.HttpConnection$SendCallback.process(HttpConnection.java:769)
at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:250)
at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:231)
at org.eclipse.jetty.server.internal.HttpConnection$HttpStreamOverHTTP1.send(HttpConnection.java:1416)
at org.eclipse.jetty.server.internal.HttpChannelState$ChannelCallback.succeeded(HttpChannelState.java:1469)
at org.glassfish.jersey.jetty.JettyHttpContainer$ResponseWriter.commit(JettyHttpContainer.java:325)
at org.glassfish.jersey.server.ContainerResponse.close(ContainerResponse.java:404)
at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:179)
at java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:992)
at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509)
at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499)
at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596)
at org.glassfish.jersey.server.ServerRuntime$Responder.release(ServerRuntime.java:774)
at org.glassfish.jersey.server.ServerRuntime$Responder.process(ServerRuntime.java:376)
at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:264)
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:248)
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:244)
at org.glassfish.jersey.internal.Errors.process(Errors.java:292)
at org.glassfish.jersey.internal.Errors.process(Errors.java:274)
at org.glassfish.jersey.internal.Errors.process(Errors.java:244)
at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:265)
at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:240)
at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:697)
at org.glassfish.jersey.jetty.JettyHttpContainer.handle(JettyHttpContainer.java:158)
at org.eclipse.jetty.server.Server.handle(Server.java:179)
at org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:594)
at org.eclipse.jetty.server.internal.HttpConnection.onFillable(HttpConnection.java:424)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:322)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:971)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1201)
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1156)
at java.base/java.lang.Thread.run(Thread.java:840)
The value of the header to be written is very large, as it contains the complete string representation of a io.swagger.v3.oas.annotations.parameters.RequestBody annotation, which is present on the request body parameter:
scratch.txt
I'm now not sure whether this is a jetty or a jersey issue.
Jersey version 3.1.5 Jetty version 12.0.5
