You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@wink.apache.org by "Jason Dillon (JIRA)" <ji...@apache.org> on 2010/06/22 18:34:54 UTC
[jira] Created: (WINK-296) DEBUG -> TRACE logging reform
DEBUG -> TRACE logging reform
-----------------------------
Key: WINK-296
URL: https://issues.apache.org/jira/browse/WINK-296
Project: Wink
Issue Type: Improvement
Components: Common
Affects Versions: 1.1.1
Reporter: Jason Dillon
In general, Wink DEBUG logging is entirely too verbose and should be revisited to show the basic details when DEBUG is enabled and use TRACE for the full gory details which may be needed by a Wink developer to debug a problem. DEBUG should be left more for Wink users who are trying to debug their application and how its integrating with Wink.
Perhaps you guys might also want to look at using org.slf4j.Marker's so that you can distinguish between internal and user logging events. As I know that developers of Wink might think that all of the above is DEBUG, but for a user its really TRACE. This way you can mark DEBUG or TRACE logs with an "INTERNAL" marker for the gory internals.
I'd also like to see the wire log in DEBUG, perhaps with a system property to flip it on off. So by default maybe it doesn't show up in DEBUG, but if I set wink.wirelog.enable=true, then it will?
----
Looks like the logging format is better, though wink still logs way to much at DEBUG IMO. For example, this looks more like TRACE logging to me:
{noformat}
jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning jobs
jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) encoded path parameters are: [jobs]
jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [jobs]
{noformat}
Also the PrivodersRegister logging is still *insane* IMO.
I think most of the DEBUG logging that is going on should really be TRACE logging. For just one simple GET, with DEBUG enabled for org.apache.wink, this gets spat out:
{noformat}
jvm 1 | DEBUG [qtp1721336021-23] c.s.b.r.s.i.w.RestServlet - Processing: GET /rest/status (http://localhost:8080/rest/status) [client=0.1-SNAPSHOT;model=0.1-SNAPSHOT;id=a74c4a57-97d7-4ef6-9676-469db4b09d75]
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Retrieving request processor org.apache.wink.server.internal.RequestProcessor@6128453c using attribute name org.apache.wink.server.internal.RequestProcessor in servlet context ServletContext@6063f5af{/,file:/Users/jason/ws/sonatype/benson/target/benson-0.1-SNAPSHOT/runtime/apps/benson/webapps/benson/}
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath is: /rest/status
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath normalized is: /rest/status
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath after context path removed: /rest/status
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath isServlet: true
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath after servlet path removed: /status
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath returning requestPath: status
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - HttpServletRequest.getHeaders(Content-Type) returned [] so putting into headers cache
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Set message context and starting request handlers chain: Method: GET, Path: status, MediaType: null
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.SearchResultHandler
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.OptionsMethodHandler
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.HeadMethodHandler
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FindRootResourceHandler
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) encoded path parameters are: [status]
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [status]
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Getting URI Info path segments: [status]
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Getting stripped path from segments: status
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Found resource instances: [ResourceRecord: Path: status; ClassMetadata: Class: class com.sonatype.benson.rest.api.status.StatusResource; UriTemplateMatcher: Parent: status; URI: status; Matcher: java.util.regex.Matcher[pattern=(\Qstatus\E)((?:/.*)?) region=0,6 lastmatch=status]; Matches: true]
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [status]
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Using SearchResult: Found: false, Resource: null, Method: null, Error: null
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FindResourceMethodHandler
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindResourceMethodHandler - Root resource @Path matches exactly so finding root resource method in com.sonatype.benson.rest.api.status.StatusResource
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) called
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) query string is: null
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) encoded query parameters are: []
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) returning []
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - alternateParameter is null
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - HttpServletRequest.getHeaders(Accept) returned [application/xml] so putting into headers cache
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Accept) returning [application/xml]
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeader(Accept) returns [application/xml]
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - Accept header is: application/xml
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptHeader() returns application/xml
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindResourceMethodHandler - Found root resource method to invoke: MethodMetadata [[consumes=[], paths=[], produces=[]]formalParameters=[], httpMethod=GET, parent=Class: class com.sonatype.benson.rest.api.status.StatusResource, reflectionMethod=public javax.ws.rs.core.Response com.sonatype.benson.rest.api.status.StatusResource.getStatus()]
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.CreateInvocationParametersHandler
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.CreateInvocationParametersHandler - Formal Injectable parameters list is: []
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.CreateInvocationParametersHandler - Actual parameters list to inject is: null
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.InvokeMethodHandler
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.InvokeMethodHandler - Invoking method getStatus of declaring class com.sonatype.benson.rest.api.status.StatusResource on the instance of a class com.sonatype.benson.rest.api.status.StatusResource@ab14733 with parameters []
jvm 1 | DEBUG [qtp1721336021-23] c.s.b.r.a.s.StatusResource - Returning status
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Finished request handlers chain and starting response handlers chain: Method: GET, Path: status, MediaType: null
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.PopulateResponseStatusHandler
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.PopulateResponseMediaTypeHandler
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Determining Content-Type from @Produces on method: [application/json, application/xml]
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/json
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/xml
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - MediaType compatible so using candidate type application/xml
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Candidate application/xml has q value null so adding to possible candidates
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - No previous best candidate so using candidate application/xml
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Response Content-Type will be set to application/xml
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FlushResultHandler
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Response status code set to: 200
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting MessageBodyWriter for class type class com.sonatype.benson.rest.model.Status, genericType class com.sonatype.benson.rest.model.Status, annotations [@javax.ws.rs.GET()], and media type application/xml
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting providers by media type by calling getProvidersByMediaType(application/xml, class com.sonatype.benson.rest.model.Status)
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Get media type to providers cache for media type application/xml resulted in [OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@4df2a9da], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a]]
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Found possible MessageBodyWriter ObjectFactories [OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@4df2a9da], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a]]
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Calling org.apache.wink.common.internal.providers.entity.xml.JAXBCollectionXmlProvider@9a303d3.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml )
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Calling org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml )
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml ) returned true
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Serialization using provider org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.getSize(com.sonatype.benson.rest.model.Status@7cb96ac0, class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml) returned -1
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.writeTo(com.sonatype.benson.rest.model.Status@7cb96ac0, class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml, CaseInsensitiveMultivaluedMap [map=[]], org.apache.wink.server.internal.handlers.FlushResultHandler$FlushHeadersOutputStream@39a4eb85) being called
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - setDefaultCharsetOnMediaTypeHeader(CaseInsensitiveMultivaluedMap [map=[]], application/xml) entry
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - No default charset was applied to the response Content-Type header due to deployment configuration directive.
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - setDefaultCharsetOnMediaTypeHeader() exit returning application/xml
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting ContextResolver for class javax.xml.bind.JAXBContext which has @Produces compatible with application/xml
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - ContextResolvers MediaTypeMap was empty so returning null
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.p.e.x.AbstractJAXBProvider - Marshaller obtained [from pool]
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.u.ProviderUtils - getCharset(application/xml, null)
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.u.ProviderUtils - getCharset() returning UTF-8 since requestHeaders was null
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting ContextResolver for class org.apache.wink.common.model.XmlFormattingOptions which has @Produces compatible with application/xml
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - ContextResolvers MediaTypeMap was empty so returning null
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Set response Content-Type to: application/xml
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.MediaTypeMapper - Did not find a mapping record so returning original response media type: application/xml
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Flushing headers: CaseInsensitiveMultivaluedMap [map=[]]
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.p.e.x.AbstractJAXBProvider - Marshaller placed back into pool
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Flushing headers if not written
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.HeadMethodHandler
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Attempting to release resource instance
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Releasing resource instance
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Finished response handlers chain
{noformat}
Its overwhelming. What happened to the wire logging? Is that TRACE?
Personally I think that Wink should consider using DEBUG for minimal-verbosity describing what is going on, what URI, what params, which resource was selected... I kinda think that the wire stuff should be in there too, and thats it.
I don't personally care how mediatypes are compared or selected, ie:
{noformat}
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/json
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/xml
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - MediaType compatible so using candidate type application/xml
{noformat}
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Resolved: (WINK-296) DEBUG -> TRACE logging reform
Posted by "Mike Rheinheimer (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/WINK-296?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Mike Rheinheimer resolved WINK-296.
-----------------------------------
Fix Version/s: 1.1.2
Resolution: Fixed
Committed in SVN rev 961830
> DEBUG -> TRACE logging reform
> -----------------------------
>
> Key: WINK-296
> URL: https://issues.apache.org/jira/browse/WINK-296
> Project: Wink
> Issue Type: Improvement
> Components: Common
> Affects Versions: 1.1.2
> Reporter: Jason Dillon
> Assignee: Mike Rheinheimer
> Fix For: 1.1.2
>
> Attachments: WINK-296.patch
>
>
> In general, Wink DEBUG logging is entirely too verbose and should be revisited to show the basic details when DEBUG is enabled and use TRACE for the full gory details which may be needed by a Wink developer to debug a problem. DEBUG should be left more for Wink users who are trying to debug their application and how its integrating with Wink.
> Perhaps you guys might also want to look at using org.slf4j.Marker's so that you can distinguish between internal and user logging events. As I know that developers of Wink might think that all of the above is DEBUG, but for a user its really TRACE. This way you can mark DEBUG or TRACE logs with an "INTERNAL" marker for the gory internals.
> I'd also like to see the wire log in DEBUG, perhaps with a system property to flip it on off. So by default maybe it doesn't show up in DEBUG, but if I set wink.wirelog.enable=true, then it will?
> ----
> Looks like the logging format is better, though wink still logs way to much at DEBUG IMO. For example, this looks more like TRACE logging to me:
> {noformat}
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning jobs
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) encoded path parameters are: [jobs]
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [jobs]
> {noformat}
> Also the PrivodersRegister logging is still *insane* IMO.
> I think most of the DEBUG logging that is going on should really be TRACE logging. For just one simple GET, with DEBUG enabled for org.apache.wink, this gets spat out:
> {noformat}
> jvm 1 | DEBUG [qtp1721336021-23] c.s.b.r.s.i.w.RestServlet - Processing: GET /rest/status (http://localhost:8080/rest/status) [client=0.1-SNAPSHOT;model=0.1-SNAPSHOT;id=a74c4a57-97d7-4ef6-9676-469db4b09d75]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Retrieving request processor org.apache.wink.server.internal.RequestProcessor@6128453c using attribute name org.apache.wink.server.internal.RequestProcessor in servlet context ServletContext@6063f5af{/,file:/Users/jason/ws/sonatype/benson/target/benson-0.1-SNAPSHOT/runtime/apps/benson/webapps/benson/}
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath is: /rest/status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath normalized is: /rest/status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath after context path removed: /rest/status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath isServlet: true
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath after servlet path removed: /status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath returning requestPath: status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - HttpServletRequest.getHeaders(Content-Type) returned [] so putting into headers cache
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Set message context and starting request handlers chain: Method: GET, Path: status, MediaType: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.SearchResultHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.OptionsMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.HeadMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FindRootResourceHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) encoded path parameters are: [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Getting URI Info path segments: [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Getting stripped path from segments: status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Found resource instances: [ResourceRecord: Path: status; ClassMetadata: Class: class com.sonatype.benson.rest.api.status.StatusResource; UriTemplateMatcher: Parent: status; URI: status; Matcher: java.util.regex.Matcher[pattern=(\Qstatus\E)((?:/.*)?) region=0,6 lastmatch=status]; Matches: true]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Using SearchResult: Found: false, Resource: null, Method: null, Error: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FindResourceMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindResourceMethodHandler - Root resource @Path matches exactly so finding root resource method in com.sonatype.benson.rest.api.status.StatusResource
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) query string is: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) encoded query parameters are: []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - alternateParameter is null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - HttpServletRequest.getHeaders(Accept) returned [application/xml] so putting into headers cache
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Accept) returning [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeader(Accept) returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - Accept header is: application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptHeader() returns application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindResourceMethodHandler - Found root resource method to invoke: MethodMetadata [[consumes=[], paths=[], produces=[]]formalParameters=[], httpMethod=GET, parent=Class: class com.sonatype.benson.rest.api.status.StatusResource, reflectionMethod=public javax.ws.rs.core.Response com.sonatype.benson.rest.api.status.StatusResource.getStatus()]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.CreateInvocationParametersHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.CreateInvocationParametersHandler - Formal Injectable parameters list is: []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.CreateInvocationParametersHandler - Actual parameters list to inject is: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.InvokeMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.InvokeMethodHandler - Invoking method getStatus of declaring class com.sonatype.benson.rest.api.status.StatusResource on the instance of a class com.sonatype.benson.rest.api.status.StatusResource@ab14733 with parameters []
> jvm 1 | DEBUG [qtp1721336021-23] c.s.b.r.a.s.StatusResource - Returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Finished request handlers chain and starting response handlers chain: Method: GET, Path: status, MediaType: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.PopulateResponseStatusHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.PopulateResponseMediaTypeHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Determining Content-Type from @Produces on method: [application/json, application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/json
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - MediaType compatible so using candidate type application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Candidate application/xml has q value null so adding to possible candidates
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - No previous best candidate so using candidate application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Response Content-Type will be set to application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FlushResultHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Response status code set to: 200
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting MessageBodyWriter for class type class com.sonatype.benson.rest.model.Status, genericType class com.sonatype.benson.rest.model.Status, annotations [@javax.ws.rs.GET()], and media type application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting providers by media type by calling getProvidersByMediaType(application/xml, class com.sonatype.benson.rest.model.Status)
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Get media type to providers cache for media type application/xml resulted in [OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@4df2a9da], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a]]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Found possible MessageBodyWriter ObjectFactories [OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@4df2a9da], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a]]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Calling org.apache.wink.common.internal.providers.entity.xml.JAXBCollectionXmlProvider@9a303d3.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml )
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Calling org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml )
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml ) returned true
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Serialization using provider org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.getSize(com.sonatype.benson.rest.model.Status@7cb96ac0, class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml) returned -1
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.writeTo(com.sonatype.benson.rest.model.Status@7cb96ac0, class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml, CaseInsensitiveMultivaluedMap [map=[]], org.apache.wink.server.internal.handlers.FlushResultHandler$FlushHeadersOutputStream@39a4eb85) being called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - setDefaultCharsetOnMediaTypeHeader(CaseInsensitiveMultivaluedMap [map=[]], application/xml) entry
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - No default charset was applied to the response Content-Type header due to deployment configuration directive.
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - setDefaultCharsetOnMediaTypeHeader() exit returning application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting ContextResolver for class javax.xml.bind.JAXBContext which has @Produces compatible with application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - ContextResolvers MediaTypeMap was empty so returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.p.e.x.AbstractJAXBProvider - Marshaller obtained [from pool]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.u.ProviderUtils - getCharset(application/xml, null)
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.u.ProviderUtils - getCharset() returning UTF-8 since requestHeaders was null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting ContextResolver for class org.apache.wink.common.model.XmlFormattingOptions which has @Produces compatible with application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - ContextResolvers MediaTypeMap was empty so returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Set response Content-Type to: application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.MediaTypeMapper - Did not find a mapping record so returning original response media type: application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Flushing headers: CaseInsensitiveMultivaluedMap [map=[]]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.p.e.x.AbstractJAXBProvider - Marshaller placed back into pool
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Flushing headers if not written
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.HeadMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Attempting to release resource instance
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Releasing resource instance
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Finished response handlers chain
> {noformat}
> Its overwhelming. What happened to the wire logging? Is that TRACE?
> Personally I think that Wink should consider using DEBUG for minimal-verbosity describing what is going on, what URI, what params, which resource was selected... I kinda think that the wire stuff should be in there too, and thats it.
> I don't personally care how mediatypes are compared or selected, ie:
> {noformat}
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/json
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - MediaType compatible so using candidate type application/xml
> {noformat}
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (WINK-296) DEBUG -> TRACE logging reform
Posted by "Hudson (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/WINK-296?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12886509#action_12886509 ]
Hudson commented on WINK-296:
-----------------------------
Integrated in Wink-Trunk-JDK1.5 #366 (See [http://hudson.zones.apache.org/hudson/job/Wink-Trunk-JDK1.5/366/])
WINK-296: change debug calls to trace calls where appropriate, add wire trace, change MessagesTest to accommodate change
> DEBUG -> TRACE logging reform
> -----------------------------
>
> Key: WINK-296
> URL: https://issues.apache.org/jira/browse/WINK-296
> Project: Wink
> Issue Type: Improvement
> Components: Common
> Affects Versions: 1.1.2
> Reporter: Jason Dillon
> Assignee: Mike Rheinheimer
> Fix For: 1.1.2
>
> Attachments: WINK-296.patch
>
>
> In general, Wink DEBUG logging is entirely too verbose and should be revisited to show the basic details when DEBUG is enabled and use TRACE for the full gory details which may be needed by a Wink developer to debug a problem. DEBUG should be left more for Wink users who are trying to debug their application and how its integrating with Wink.
> Perhaps you guys might also want to look at using org.slf4j.Marker's so that you can distinguish between internal and user logging events. As I know that developers of Wink might think that all of the above is DEBUG, but for a user its really TRACE. This way you can mark DEBUG or TRACE logs with an "INTERNAL" marker for the gory internals.
> I'd also like to see the wire log in DEBUG, perhaps with a system property to flip it on off. So by default maybe it doesn't show up in DEBUG, but if I set wink.wirelog.enable=true, then it will?
> ----
> Looks like the logging format is better, though wink still logs way to much at DEBUG IMO. For example, this looks more like TRACE logging to me:
> {noformat}
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning jobs
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) encoded path parameters are: [jobs]
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [jobs]
> {noformat}
> Also the PrivodersRegister logging is still *insane* IMO.
> I think most of the DEBUG logging that is going on should really be TRACE logging. For just one simple GET, with DEBUG enabled for org.apache.wink, this gets spat out:
> {noformat}
> jvm 1 | DEBUG [qtp1721336021-23] c.s.b.r.s.i.w.RestServlet - Processing: GET /rest/status (http://localhost:8080/rest/status) [client=0.1-SNAPSHOT;model=0.1-SNAPSHOT;id=a74c4a57-97d7-4ef6-9676-469db4b09d75]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Retrieving request processor org.apache.wink.server.internal.RequestProcessor@6128453c using attribute name org.apache.wink.server.internal.RequestProcessor in servlet context ServletContext@6063f5af{/,file:/Users/jason/ws/sonatype/benson/target/benson-0.1-SNAPSHOT/runtime/apps/benson/webapps/benson/}
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath is: /rest/status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath normalized is: /rest/status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath after context path removed: /rest/status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath isServlet: true
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath after servlet path removed: /status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath returning requestPath: status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - HttpServletRequest.getHeaders(Content-Type) returned [] so putting into headers cache
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Set message context and starting request handlers chain: Method: GET, Path: status, MediaType: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.SearchResultHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.OptionsMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.HeadMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FindRootResourceHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) encoded path parameters are: [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Getting URI Info path segments: [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Getting stripped path from segments: status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Found resource instances: [ResourceRecord: Path: status; ClassMetadata: Class: class com.sonatype.benson.rest.api.status.StatusResource; UriTemplateMatcher: Parent: status; URI: status; Matcher: java.util.regex.Matcher[pattern=(\Qstatus\E)((?:/.*)?) region=0,6 lastmatch=status]; Matches: true]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Using SearchResult: Found: false, Resource: null, Method: null, Error: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FindResourceMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindResourceMethodHandler - Root resource @Path matches exactly so finding root resource method in com.sonatype.benson.rest.api.status.StatusResource
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) query string is: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) encoded query parameters are: []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - alternateParameter is null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - HttpServletRequest.getHeaders(Accept) returned [application/xml] so putting into headers cache
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Accept) returning [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeader(Accept) returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - Accept header is: application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptHeader() returns application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindResourceMethodHandler - Found root resource method to invoke: MethodMetadata [[consumes=[], paths=[], produces=[]]formalParameters=[], httpMethod=GET, parent=Class: class com.sonatype.benson.rest.api.status.StatusResource, reflectionMethod=public javax.ws.rs.core.Response com.sonatype.benson.rest.api.status.StatusResource.getStatus()]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.CreateInvocationParametersHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.CreateInvocationParametersHandler - Formal Injectable parameters list is: []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.CreateInvocationParametersHandler - Actual parameters list to inject is: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.InvokeMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.InvokeMethodHandler - Invoking method getStatus of declaring class com.sonatype.benson.rest.api.status.StatusResource on the instance of a class com.sonatype.benson.rest.api.status.StatusResource@ab14733 with parameters []
> jvm 1 | DEBUG [qtp1721336021-23] c.s.b.r.a.s.StatusResource - Returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Finished request handlers chain and starting response handlers chain: Method: GET, Path: status, MediaType: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.PopulateResponseStatusHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.PopulateResponseMediaTypeHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Determining Content-Type from @Produces on method: [application/json, application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/json
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - MediaType compatible so using candidate type application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Candidate application/xml has q value null so adding to possible candidates
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - No previous best candidate so using candidate application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Response Content-Type will be set to application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FlushResultHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Response status code set to: 200
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting MessageBodyWriter for class type class com.sonatype.benson.rest.model.Status, genericType class com.sonatype.benson.rest.model.Status, annotations [@javax.ws.rs.GET()], and media type application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting providers by media type by calling getProvidersByMediaType(application/xml, class com.sonatype.benson.rest.model.Status)
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Get media type to providers cache for media type application/xml resulted in [OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@4df2a9da], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a]]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Found possible MessageBodyWriter ObjectFactories [OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@4df2a9da], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a]]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Calling org.apache.wink.common.internal.providers.entity.xml.JAXBCollectionXmlProvider@9a303d3.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml )
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Calling org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml )
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml ) returned true
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Serialization using provider org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.getSize(com.sonatype.benson.rest.model.Status@7cb96ac0, class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml) returned -1
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.writeTo(com.sonatype.benson.rest.model.Status@7cb96ac0, class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml, CaseInsensitiveMultivaluedMap [map=[]], org.apache.wink.server.internal.handlers.FlushResultHandler$FlushHeadersOutputStream@39a4eb85) being called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - setDefaultCharsetOnMediaTypeHeader(CaseInsensitiveMultivaluedMap [map=[]], application/xml) entry
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - No default charset was applied to the response Content-Type header due to deployment configuration directive.
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - setDefaultCharsetOnMediaTypeHeader() exit returning application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting ContextResolver for class javax.xml.bind.JAXBContext which has @Produces compatible with application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - ContextResolvers MediaTypeMap was empty so returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.p.e.x.AbstractJAXBProvider - Marshaller obtained [from pool]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.u.ProviderUtils - getCharset(application/xml, null)
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.u.ProviderUtils - getCharset() returning UTF-8 since requestHeaders was null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting ContextResolver for class org.apache.wink.common.model.XmlFormattingOptions which has @Produces compatible with application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - ContextResolvers MediaTypeMap was empty so returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Set response Content-Type to: application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.MediaTypeMapper - Did not find a mapping record so returning original response media type: application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Flushing headers: CaseInsensitiveMultivaluedMap [map=[]]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.p.e.x.AbstractJAXBProvider - Marshaller placed back into pool
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Flushing headers if not written
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.HeadMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Attempting to release resource instance
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Releasing resource instance
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Finished response handlers chain
> {noformat}
> Its overwhelming. What happened to the wire logging? Is that TRACE?
> Personally I think that Wink should consider using DEBUG for minimal-verbosity describing what is going on, what URI, what params, which resource was selected... I kinda think that the wire stuff should be in there too, and thats it.
> I don't personally care how mediatypes are compared or selected, ie:
> {noformat}
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/json
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - MediaType compatible so using candidate type application/xml
> {noformat}
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (WINK-296) DEBUG -> TRACE logging reform
Posted by "Jesse Ramos (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/WINK-296?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Jesse Ramos updated WINK-296:
-----------------------------
Affects Version/s: 1.1.2
(was: 1.1.1)
> DEBUG -> TRACE logging reform
> -----------------------------
>
> Key: WINK-296
> URL: https://issues.apache.org/jira/browse/WINK-296
> Project: Wink
> Issue Type: Improvement
> Components: Common
> Affects Versions: 1.1.2
> Reporter: Jason Dillon
>
> In general, Wink DEBUG logging is entirely too verbose and should be revisited to show the basic details when DEBUG is enabled and use TRACE for the full gory details which may be needed by a Wink developer to debug a problem. DEBUG should be left more for Wink users who are trying to debug their application and how its integrating with Wink.
> Perhaps you guys might also want to look at using org.slf4j.Marker's so that you can distinguish between internal and user logging events. As I know that developers of Wink might think that all of the above is DEBUG, but for a user its really TRACE. This way you can mark DEBUG or TRACE logs with an "INTERNAL" marker for the gory internals.
> I'd also like to see the wire log in DEBUG, perhaps with a system property to flip it on off. So by default maybe it doesn't show up in DEBUG, but if I set wink.wirelog.enable=true, then it will?
> ----
> Looks like the logging format is better, though wink still logs way to much at DEBUG IMO. For example, this looks more like TRACE logging to me:
> {noformat}
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning jobs
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) encoded path parameters are: [jobs]
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [jobs]
> {noformat}
> Also the PrivodersRegister logging is still *insane* IMO.
> I think most of the DEBUG logging that is going on should really be TRACE logging. For just one simple GET, with DEBUG enabled for org.apache.wink, this gets spat out:
> {noformat}
> jvm 1 | DEBUG [qtp1721336021-23] c.s.b.r.s.i.w.RestServlet - Processing: GET /rest/status (http://localhost:8080/rest/status) [client=0.1-SNAPSHOT;model=0.1-SNAPSHOT;id=a74c4a57-97d7-4ef6-9676-469db4b09d75]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Retrieving request processor org.apache.wink.server.internal.RequestProcessor@6128453c using attribute name org.apache.wink.server.internal.RequestProcessor in servlet context ServletContext@6063f5af{/,file:/Users/jason/ws/sonatype/benson/target/benson-0.1-SNAPSHOT/runtime/apps/benson/webapps/benson/}
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath is: /rest/status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath normalized is: /rest/status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath after context path removed: /rest/status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath isServlet: true
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath after servlet path removed: /status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath returning requestPath: status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - HttpServletRequest.getHeaders(Content-Type) returned [] so putting into headers cache
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Set message context and starting request handlers chain: Method: GET, Path: status, MediaType: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.SearchResultHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.OptionsMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.HeadMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FindRootResourceHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) encoded path parameters are: [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Getting URI Info path segments: [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Getting stripped path from segments: status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Found resource instances: [ResourceRecord: Path: status; ClassMetadata: Class: class com.sonatype.benson.rest.api.status.StatusResource; UriTemplateMatcher: Parent: status; URI: status; Matcher: java.util.regex.Matcher[pattern=(\Qstatus\E)((?:/.*)?) region=0,6 lastmatch=status]; Matches: true]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Using SearchResult: Found: false, Resource: null, Method: null, Error: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FindResourceMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindResourceMethodHandler - Root resource @Path matches exactly so finding root resource method in com.sonatype.benson.rest.api.status.StatusResource
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) query string is: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) encoded query parameters are: []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - alternateParameter is null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - HttpServletRequest.getHeaders(Accept) returned [application/xml] so putting into headers cache
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Accept) returning [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeader(Accept) returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - Accept header is: application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptHeader() returns application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindResourceMethodHandler - Found root resource method to invoke: MethodMetadata [[consumes=[], paths=[], produces=[]]formalParameters=[], httpMethod=GET, parent=Class: class com.sonatype.benson.rest.api.status.StatusResource, reflectionMethod=public javax.ws.rs.core.Response com.sonatype.benson.rest.api.status.StatusResource.getStatus()]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.CreateInvocationParametersHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.CreateInvocationParametersHandler - Formal Injectable parameters list is: []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.CreateInvocationParametersHandler - Actual parameters list to inject is: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.InvokeMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.InvokeMethodHandler - Invoking method getStatus of declaring class com.sonatype.benson.rest.api.status.StatusResource on the instance of a class com.sonatype.benson.rest.api.status.StatusResource@ab14733 with parameters []
> jvm 1 | DEBUG [qtp1721336021-23] c.s.b.r.a.s.StatusResource - Returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Finished request handlers chain and starting response handlers chain: Method: GET, Path: status, MediaType: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.PopulateResponseStatusHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.PopulateResponseMediaTypeHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Determining Content-Type from @Produces on method: [application/json, application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/json
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - MediaType compatible so using candidate type application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Candidate application/xml has q value null so adding to possible candidates
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - No previous best candidate so using candidate application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Response Content-Type will be set to application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FlushResultHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Response status code set to: 200
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting MessageBodyWriter for class type class com.sonatype.benson.rest.model.Status, genericType class com.sonatype.benson.rest.model.Status, annotations [@javax.ws.rs.GET()], and media type application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting providers by media type by calling getProvidersByMediaType(application/xml, class com.sonatype.benson.rest.model.Status)
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Get media type to providers cache for media type application/xml resulted in [OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@4df2a9da], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a]]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Found possible MessageBodyWriter ObjectFactories [OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@4df2a9da], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a]]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Calling org.apache.wink.common.internal.providers.entity.xml.JAXBCollectionXmlProvider@9a303d3.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml )
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Calling org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml )
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml ) returned true
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Serialization using provider org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.getSize(com.sonatype.benson.rest.model.Status@7cb96ac0, class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml) returned -1
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.writeTo(com.sonatype.benson.rest.model.Status@7cb96ac0, class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml, CaseInsensitiveMultivaluedMap [map=[]], org.apache.wink.server.internal.handlers.FlushResultHandler$FlushHeadersOutputStream@39a4eb85) being called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - setDefaultCharsetOnMediaTypeHeader(CaseInsensitiveMultivaluedMap [map=[]], application/xml) entry
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - No default charset was applied to the response Content-Type header due to deployment configuration directive.
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - setDefaultCharsetOnMediaTypeHeader() exit returning application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting ContextResolver for class javax.xml.bind.JAXBContext which has @Produces compatible with application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - ContextResolvers MediaTypeMap was empty so returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.p.e.x.AbstractJAXBProvider - Marshaller obtained [from pool]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.u.ProviderUtils - getCharset(application/xml, null)
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.u.ProviderUtils - getCharset() returning UTF-8 since requestHeaders was null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting ContextResolver for class org.apache.wink.common.model.XmlFormattingOptions which has @Produces compatible with application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - ContextResolvers MediaTypeMap was empty so returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Set response Content-Type to: application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.MediaTypeMapper - Did not find a mapping record so returning original response media type: application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Flushing headers: CaseInsensitiveMultivaluedMap [map=[]]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.p.e.x.AbstractJAXBProvider - Marshaller placed back into pool
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Flushing headers if not written
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.HeadMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Attempting to release resource instance
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Releasing resource instance
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Finished response handlers chain
> {noformat}
> Its overwhelming. What happened to the wire logging? Is that TRACE?
> Personally I think that Wink should consider using DEBUG for minimal-verbosity describing what is going on, what URI, what params, which resource was selected... I kinda think that the wire stuff should be in there too, and thats it.
> I don't personally care how mediatypes are compared or selected, ie:
> {noformat}
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/json
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - MediaType compatible so using candidate type application/xml
> {noformat}
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (WINK-296) DEBUG -> TRACE logging reform
Posted by "Mike Rheinheimer (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/WINK-296?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Mike Rheinheimer updated WINK-296:
----------------------------------
Attachment: WINK-296.patch
Jason, please take a look at the attached patch. See if, at first glance, it looks like what you might expect. I left some things under debug that I thought made sense to stay under debug, and added one wire trace to indicate the method and URI of the inbound request currently being processed.
I'm guessing more trace + debug will be needed, and I don't expect to get it perfect the first time through, but would like to come close!
> DEBUG -> TRACE logging reform
> -----------------------------
>
> Key: WINK-296
> URL: https://issues.apache.org/jira/browse/WINK-296
> Project: Wink
> Issue Type: Improvement
> Components: Common
> Affects Versions: 1.1.2
> Reporter: Jason Dillon
> Assignee: Mike Rheinheimer
> Attachments: WINK-296.patch
>
>
> In general, Wink DEBUG logging is entirely too verbose and should be revisited to show the basic details when DEBUG is enabled and use TRACE for the full gory details which may be needed by a Wink developer to debug a problem. DEBUG should be left more for Wink users who are trying to debug their application and how its integrating with Wink.
> Perhaps you guys might also want to look at using org.slf4j.Marker's so that you can distinguish between internal and user logging events. As I know that developers of Wink might think that all of the above is DEBUG, but for a user its really TRACE. This way you can mark DEBUG or TRACE logs with an "INTERNAL" marker for the gory internals.
> I'd also like to see the wire log in DEBUG, perhaps with a system property to flip it on off. So by default maybe it doesn't show up in DEBUG, but if I set wink.wirelog.enable=true, then it will?
> ----
> Looks like the logging format is better, though wink still logs way to much at DEBUG IMO. For example, this looks more like TRACE logging to me:
> {noformat}
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning jobs
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) encoded path parameters are: [jobs]
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [jobs]
> {noformat}
> Also the PrivodersRegister logging is still *insane* IMO.
> I think most of the DEBUG logging that is going on should really be TRACE logging. For just one simple GET, with DEBUG enabled for org.apache.wink, this gets spat out:
> {noformat}
> jvm 1 | DEBUG [qtp1721336021-23] c.s.b.r.s.i.w.RestServlet - Processing: GET /rest/status (http://localhost:8080/rest/status) [client=0.1-SNAPSHOT;model=0.1-SNAPSHOT;id=a74c4a57-97d7-4ef6-9676-469db4b09d75]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Retrieving request processor org.apache.wink.server.internal.RequestProcessor@6128453c using attribute name org.apache.wink.server.internal.RequestProcessor in servlet context ServletContext@6063f5af{/,file:/Users/jason/ws/sonatype/benson/target/benson-0.1-SNAPSHOT/runtime/apps/benson/webapps/benson/}
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath is: /rest/status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath normalized is: /rest/status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath after context path removed: /rest/status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath isServlet: true
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath after servlet path removed: /status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath returning requestPath: status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - HttpServletRequest.getHeaders(Content-Type) returned [] so putting into headers cache
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Set message context and starting request handlers chain: Method: GET, Path: status, MediaType: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.SearchResultHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.OptionsMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.HeadMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FindRootResourceHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) encoded path parameters are: [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Getting URI Info path segments: [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Getting stripped path from segments: status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Found resource instances: [ResourceRecord: Path: status; ClassMetadata: Class: class com.sonatype.benson.rest.api.status.StatusResource; UriTemplateMatcher: Parent: status; URI: status; Matcher: java.util.regex.Matcher[pattern=(\Qstatus\E)((?:/.*)?) region=0,6 lastmatch=status]; Matches: true]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Using SearchResult: Found: false, Resource: null, Method: null, Error: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FindResourceMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindResourceMethodHandler - Root resource @Path matches exactly so finding root resource method in com.sonatype.benson.rest.api.status.StatusResource
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) query string is: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) encoded query parameters are: []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - alternateParameter is null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - HttpServletRequest.getHeaders(Accept) returned [application/xml] so putting into headers cache
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Accept) returning [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeader(Accept) returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - Accept header is: application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptHeader() returns application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindResourceMethodHandler - Found root resource method to invoke: MethodMetadata [[consumes=[], paths=[], produces=[]]formalParameters=[], httpMethod=GET, parent=Class: class com.sonatype.benson.rest.api.status.StatusResource, reflectionMethod=public javax.ws.rs.core.Response com.sonatype.benson.rest.api.status.StatusResource.getStatus()]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.CreateInvocationParametersHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.CreateInvocationParametersHandler - Formal Injectable parameters list is: []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.CreateInvocationParametersHandler - Actual parameters list to inject is: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.InvokeMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.InvokeMethodHandler - Invoking method getStatus of declaring class com.sonatype.benson.rest.api.status.StatusResource on the instance of a class com.sonatype.benson.rest.api.status.StatusResource@ab14733 with parameters []
> jvm 1 | DEBUG [qtp1721336021-23] c.s.b.r.a.s.StatusResource - Returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Finished request handlers chain and starting response handlers chain: Method: GET, Path: status, MediaType: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.PopulateResponseStatusHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.PopulateResponseMediaTypeHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Determining Content-Type from @Produces on method: [application/json, application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/json
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - MediaType compatible so using candidate type application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Candidate application/xml has q value null so adding to possible candidates
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - No previous best candidate so using candidate application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Response Content-Type will be set to application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FlushResultHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Response status code set to: 200
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting MessageBodyWriter for class type class com.sonatype.benson.rest.model.Status, genericType class com.sonatype.benson.rest.model.Status, annotations [@javax.ws.rs.GET()], and media type application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting providers by media type by calling getProvidersByMediaType(application/xml, class com.sonatype.benson.rest.model.Status)
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Get media type to providers cache for media type application/xml resulted in [OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@4df2a9da], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a]]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Found possible MessageBodyWriter ObjectFactories [OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@4df2a9da], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a]]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Calling org.apache.wink.common.internal.providers.entity.xml.JAXBCollectionXmlProvider@9a303d3.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml )
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Calling org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml )
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml ) returned true
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Serialization using provider org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.getSize(com.sonatype.benson.rest.model.Status@7cb96ac0, class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml) returned -1
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.writeTo(com.sonatype.benson.rest.model.Status@7cb96ac0, class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml, CaseInsensitiveMultivaluedMap [map=[]], org.apache.wink.server.internal.handlers.FlushResultHandler$FlushHeadersOutputStream@39a4eb85) being called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - setDefaultCharsetOnMediaTypeHeader(CaseInsensitiveMultivaluedMap [map=[]], application/xml) entry
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - No default charset was applied to the response Content-Type header due to deployment configuration directive.
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - setDefaultCharsetOnMediaTypeHeader() exit returning application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting ContextResolver for class javax.xml.bind.JAXBContext which has @Produces compatible with application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - ContextResolvers MediaTypeMap was empty so returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.p.e.x.AbstractJAXBProvider - Marshaller obtained [from pool]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.u.ProviderUtils - getCharset(application/xml, null)
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.u.ProviderUtils - getCharset() returning UTF-8 since requestHeaders was null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting ContextResolver for class org.apache.wink.common.model.XmlFormattingOptions which has @Produces compatible with application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - ContextResolvers MediaTypeMap was empty so returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Set response Content-Type to: application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.MediaTypeMapper - Did not find a mapping record so returning original response media type: application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Flushing headers: CaseInsensitiveMultivaluedMap [map=[]]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.p.e.x.AbstractJAXBProvider - Marshaller placed back into pool
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Flushing headers if not written
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.HeadMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Attempting to release resource instance
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Releasing resource instance
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Finished response handlers chain
> {noformat}
> Its overwhelming. What happened to the wire logging? Is that TRACE?
> Personally I think that Wink should consider using DEBUG for minimal-verbosity describing what is going on, what URI, what params, which resource was selected... I kinda think that the wire stuff should be in there too, and thats it.
> I don't personally care how mediatypes are compared or selected, ie:
> {noformat}
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/json
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - MediaType compatible so using candidate type application/xml
> {noformat}
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Assigned: (WINK-296) DEBUG -> TRACE logging reform
Posted by "Mike Rheinheimer (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/WINK-296?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Mike Rheinheimer reassigned WINK-296:
-------------------------------------
Assignee: Mike Rheinheimer
> DEBUG -> TRACE logging reform
> -----------------------------
>
> Key: WINK-296
> URL: https://issues.apache.org/jira/browse/WINK-296
> Project: Wink
> Issue Type: Improvement
> Components: Common
> Affects Versions: 1.1.2
> Reporter: Jason Dillon
> Assignee: Mike Rheinheimer
>
> In general, Wink DEBUG logging is entirely too verbose and should be revisited to show the basic details when DEBUG is enabled and use TRACE for the full gory details which may be needed by a Wink developer to debug a problem. DEBUG should be left more for Wink users who are trying to debug their application and how its integrating with Wink.
> Perhaps you guys might also want to look at using org.slf4j.Marker's so that you can distinguish between internal and user logging events. As I know that developers of Wink might think that all of the above is DEBUG, but for a user its really TRACE. This way you can mark DEBUG or TRACE logs with an "INTERNAL" marker for the gory internals.
> I'd also like to see the wire log in DEBUG, perhaps with a system property to flip it on off. So by default maybe it doesn't show up in DEBUG, but if I set wink.wirelog.enable=true, then it will?
> ----
> Looks like the logging format is better, though wink still logs way to much at DEBUG IMO. For example, this looks more like TRACE logging to me:
> {noformat}
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning jobs
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) encoded path parameters are: [jobs]
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [jobs]
> {noformat}
> Also the PrivodersRegister logging is still *insane* IMO.
> I think most of the DEBUG logging that is going on should really be TRACE logging. For just one simple GET, with DEBUG enabled for org.apache.wink, this gets spat out:
> {noformat}
> jvm 1 | DEBUG [qtp1721336021-23] c.s.b.r.s.i.w.RestServlet - Processing: GET /rest/status (http://localhost:8080/rest/status) [client=0.1-SNAPSHOT;model=0.1-SNAPSHOT;id=a74c4a57-97d7-4ef6-9676-469db4b09d75]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Retrieving request processor org.apache.wink.server.internal.RequestProcessor@6128453c using attribute name org.apache.wink.server.internal.RequestProcessor in servlet context ServletContext@6063f5af{/,file:/Users/jason/ws/sonatype/benson/target/benson-0.1-SNAPSHOT/runtime/apps/benson/webapps/benson/}
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath is: /rest/status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath normalized is: /rest/status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath after context path removed: /rest/status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath isServlet: true
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath after servlet path removed: /status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath returning requestPath: status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - HttpServletRequest.getHeaders(Content-Type) returned [] so putting into headers cache
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Set message context and starting request handlers chain: Method: GET, Path: status, MediaType: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.SearchResultHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.OptionsMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.HeadMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FindRootResourceHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) encoded path parameters are: [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Getting URI Info path segments: [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Getting stripped path from segments: status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Found resource instances: [ResourceRecord: Path: status; ClassMetadata: Class: class com.sonatype.benson.rest.api.status.StatusResource; UriTemplateMatcher: Parent: status; URI: status; Matcher: java.util.regex.Matcher[pattern=(\Qstatus\E)((?:/.*)?) region=0,6 lastmatch=status]; Matches: true]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Using SearchResult: Found: false, Resource: null, Method: null, Error: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FindResourceMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindResourceMethodHandler - Root resource @Path matches exactly so finding root resource method in com.sonatype.benson.rest.api.status.StatusResource
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) query string is: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) encoded query parameters are: []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - alternateParameter is null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - HttpServletRequest.getHeaders(Accept) returned [application/xml] so putting into headers cache
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Accept) returning [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeader(Accept) returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - Accept header is: application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptHeader() returns application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindResourceMethodHandler - Found root resource method to invoke: MethodMetadata [[consumes=[], paths=[], produces=[]]formalParameters=[], httpMethod=GET, parent=Class: class com.sonatype.benson.rest.api.status.StatusResource, reflectionMethod=public javax.ws.rs.core.Response com.sonatype.benson.rest.api.status.StatusResource.getStatus()]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.CreateInvocationParametersHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.CreateInvocationParametersHandler - Formal Injectable parameters list is: []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.CreateInvocationParametersHandler - Actual parameters list to inject is: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.InvokeMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.InvokeMethodHandler - Invoking method getStatus of declaring class com.sonatype.benson.rest.api.status.StatusResource on the instance of a class com.sonatype.benson.rest.api.status.StatusResource@ab14733 with parameters []
> jvm 1 | DEBUG [qtp1721336021-23] c.s.b.r.a.s.StatusResource - Returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Finished request handlers chain and starting response handlers chain: Method: GET, Path: status, MediaType: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.PopulateResponseStatusHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.PopulateResponseMediaTypeHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Determining Content-Type from @Produces on method: [application/json, application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/json
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - MediaType compatible so using candidate type application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Candidate application/xml has q value null so adding to possible candidates
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - No previous best candidate so using candidate application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Response Content-Type will be set to application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FlushResultHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Response status code set to: 200
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting MessageBodyWriter for class type class com.sonatype.benson.rest.model.Status, genericType class com.sonatype.benson.rest.model.Status, annotations [@javax.ws.rs.GET()], and media type application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting providers by media type by calling getProvidersByMediaType(application/xml, class com.sonatype.benson.rest.model.Status)
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Get media type to providers cache for media type application/xml resulted in [OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@4df2a9da], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a]]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Found possible MessageBodyWriter ObjectFactories [OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@4df2a9da], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a]]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Calling org.apache.wink.common.internal.providers.entity.xml.JAXBCollectionXmlProvider@9a303d3.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml )
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Calling org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml )
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml ) returned true
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Serialization using provider org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.getSize(com.sonatype.benson.rest.model.Status@7cb96ac0, class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml) returned -1
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.writeTo(com.sonatype.benson.rest.model.Status@7cb96ac0, class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml, CaseInsensitiveMultivaluedMap [map=[]], org.apache.wink.server.internal.handlers.FlushResultHandler$FlushHeadersOutputStream@39a4eb85) being called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - setDefaultCharsetOnMediaTypeHeader(CaseInsensitiveMultivaluedMap [map=[]], application/xml) entry
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - No default charset was applied to the response Content-Type header due to deployment configuration directive.
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - setDefaultCharsetOnMediaTypeHeader() exit returning application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting ContextResolver for class javax.xml.bind.JAXBContext which has @Produces compatible with application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - ContextResolvers MediaTypeMap was empty so returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.p.e.x.AbstractJAXBProvider - Marshaller obtained [from pool]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.u.ProviderUtils - getCharset(application/xml, null)
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.u.ProviderUtils - getCharset() returning UTF-8 since requestHeaders was null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting ContextResolver for class org.apache.wink.common.model.XmlFormattingOptions which has @Produces compatible with application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - ContextResolvers MediaTypeMap was empty so returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Set response Content-Type to: application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.MediaTypeMapper - Did not find a mapping record so returning original response media type: application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Flushing headers: CaseInsensitiveMultivaluedMap [map=[]]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.p.e.x.AbstractJAXBProvider - Marshaller placed back into pool
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Flushing headers if not written
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.HeadMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Attempting to release resource instance
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Releasing resource instance
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Finished response handlers chain
> {noformat}
> Its overwhelming. What happened to the wire logging? Is that TRACE?
> Personally I think that Wink should consider using DEBUG for minimal-verbosity describing what is going on, what URI, what params, which resource was selected... I kinda think that the wire stuff should be in there too, and thats it.
> I don't personally care how mediatypes are compared or selected, ie:
> {noformat}
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/json
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - MediaType compatible so using candidate type application/xml
> {noformat}
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (WINK-296) DEBUG -> TRACE logging reform
Posted by "Jason Dillon (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/WINK-296?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12886109#action_12886109 ]
Jason Dillon commented on WINK-296:
-----------------------------------
YES!!! So much better!
> DEBUG -> TRACE logging reform
> -----------------------------
>
> Key: WINK-296
> URL: https://issues.apache.org/jira/browse/WINK-296
> Project: Wink
> Issue Type: Improvement
> Components: Common
> Affects Versions: 1.1.2
> Reporter: Jason Dillon
> Assignee: Mike Rheinheimer
> Attachments: WINK-296.patch
>
>
> In general, Wink DEBUG logging is entirely too verbose and should be revisited to show the basic details when DEBUG is enabled and use TRACE for the full gory details which may be needed by a Wink developer to debug a problem. DEBUG should be left more for Wink users who are trying to debug their application and how its integrating with Wink.
> Perhaps you guys might also want to look at using org.slf4j.Marker's so that you can distinguish between internal and user logging events. As I know that developers of Wink might think that all of the above is DEBUG, but for a user its really TRACE. This way you can mark DEBUG or TRACE logs with an "INTERNAL" marker for the gory internals.
> I'd also like to see the wire log in DEBUG, perhaps with a system property to flip it on off. So by default maybe it doesn't show up in DEBUG, but if I set wink.wirelog.enable=true, then it will?
> ----
> Looks like the logging format is better, though wink still logs way to much at DEBUG IMO. For example, this looks more like TRACE logging to me:
> {noformat}
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning jobs
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) encoded path parameters are: [jobs]
> jvm 1 | DEBUG [qtp1721336021-24] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [jobs]
> {noformat}
> Also the PrivodersRegister logging is still *insane* IMO.
> I think most of the DEBUG logging that is going on should really be TRACE logging. For just one simple GET, with DEBUG enabled for org.apache.wink, this gets spat out:
> {noformat}
> jvm 1 | DEBUG [qtp1721336021-23] c.s.b.r.s.i.w.RestServlet - Processing: GET /rest/status (http://localhost:8080/rest/status) [client=0.1-SNAPSHOT;model=0.1-SNAPSHOT;id=a74c4a57-97d7-4ef6-9676-469db4b09d75]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Retrieving request processor org.apache.wink.server.internal.RequestProcessor@6128453c using attribute name org.apache.wink.server.internal.RequestProcessor in servlet context ServletContext@6063f5af{/,file:/Users/jason/ws/sonatype/benson/target/benson-0.1-SNAPSHOT/runtime/apps/benson/webapps/benson/}
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath is: /rest/status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath normalized is: /rest/status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath after context path removed: /rest/status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath isServlet: true
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath requestPath after servlet path removed: /status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - buildRequestPath returning requestPath: status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - HttpServletRequest.getHeaders(Content-Type) returned [] so putting into headers cache
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Set message context and starting request handlers chain: Method: GET, Path: status, MediaType: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.SearchResultHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.OptionsMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.HeadMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FindRootResourceHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) encoded path parameters are: [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Getting URI Info path segments: [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Getting stripped path from segments: status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Found resource instances: [ResourceRecord: Path: status; ClassMetadata: Class: class com.sonatype.benson.rest.api.status.StatusResource; UriTemplateMatcher: Parent: status; URI: status; Matcher: java.util.regex.Matcher[pattern=(\Qstatus\E)((?:/.*)?) region=0,6 lastmatch=status]; Matches: true]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPathSegments(false) returning [status]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindRootResourceHandler - Using SearchResult: Found: false, Resource: null, Method: null, Error: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FindResourceMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindResourceMethodHandler - Root resource @Path matches exactly so finding root resource method in com.sonatype.benson.rest.api.status.StatusResource
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) query string is: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) encoded query parameters are: []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getQueryParameters(true) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - alternateParameter is null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - HttpServletRequest.getHeaders(Accept) returned [application/xml] so putting into headers cache
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Accept) returning [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeader(Accept) returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - Accept header is: application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptHeader() returns application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FindResourceMethodHandler - Found root resource method to invoke: MethodMetadata [[consumes=[], paths=[], produces=[]]formalParameters=[], httpMethod=GET, parent=Class: class com.sonatype.benson.rest.api.status.StatusResource, reflectionMethod=public javax.ws.rs.core.Response com.sonatype.benson.rest.api.status.StatusResource.getStatus()]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.CreateInvocationParametersHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.CreateInvocationParametersHandler - Formal Injectable parameters list is: []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.CreateInvocationParametersHandler - Actual parameters list to inject is: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.InvokeMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.InvokeMethodHandler - Invoking method getStatus of declaring class com.sonatype.benson.rest.api.status.StatusResource on the instance of a class com.sonatype.benson.rest.api.status.StatusResource@ab14733 with parameters []
> jvm 1 | DEBUG [qtp1721336021-23] c.s.b.r.a.s.StatusResource - Returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.UriInfoImpl - getPath(false) returning status
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getRequestHeaderInternal(Content-Type) returning []
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getMediaType() returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Finished request handlers chain and starting response handlers chain: Method: GET, Path: status, MediaType: null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.PopulateResponseStatusHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.PopulateResponseMediaTypeHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Determining Content-Type from @Produces on method: [application/json, application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.HttpHeadersImpl - getAcceptableMediaTypes() returns [application/xml]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/json
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - MediaType compatible so using candidate type application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Candidate application/xml has q value null so adding to possible candidates
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - No previous best candidate so using candidate application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Response Content-Type will be set to application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.FlushResultHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Response status code set to: 200
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting MessageBodyWriter for class type class com.sonatype.benson.rest.model.Status, genericType class com.sonatype.benson.rest.model.Status, annotations [@javax.ws.rs.GET()], and media type application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting providers by media type by calling getProvidersByMediaType(application/xml, class com.sonatype.benson.rest.model.Status)
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Get media type to providers cache for media type application/xml resulted in [OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@4df2a9da], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a]]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Found possible MessageBodyWriter ObjectFactories [OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=application/xml, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@4df2a9da], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@561140db], OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority: 0.100000, ObjectFactory: org.apache.wink.guice.server.internal.lifecycle.GuiceInjectorLifeCycleManager$GuiceSingletonObjectFactory@531a700a]]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Calling org.apache.wink.common.internal.providers.entity.xml.JAXBCollectionXmlProvider@9a303d3.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml )
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Calling org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml )
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.isWriteable( class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml ) returned true
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Serialization using provider org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.getSize(com.sonatype.benson.rest.model.Status@7cb96ac0, class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml) returned -1
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - org.apache.wink.common.internal.providers.entity.xml.JAXBXmlProvider@14dd18cc.writeTo(com.sonatype.benson.rest.model.Status@7cb96ac0, class com.sonatype.benson.rest.model.Status, class com.sonatype.benson.rest.model.Status, [@javax.ws.rs.GET()], application/xml, CaseInsensitiveMultivaluedMap [map=[]], org.apache.wink.server.internal.handlers.FlushResultHandler$FlushHeadersOutputStream@39a4eb85) being called
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - setDefaultCharsetOnMediaTypeHeader(CaseInsensitiveMultivaluedMap [map=[]], application/xml) entry
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - No default charset was applied to the response Content-Type header due to deployment configuration directive.
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.c.ServerMediaTypeCharsetAdjuster - setDefaultCharsetOnMediaTypeHeader() exit returning application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting ContextResolver for class javax.xml.bind.JAXBContext which has @Produces compatible with application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - ContextResolvers MediaTypeMap was empty so returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.p.e.x.AbstractJAXBProvider - Marshaller obtained [from pool]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.u.ProviderUtils - getCharset(application/xml, null)
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.u.ProviderUtils - getCharset() returning UTF-8 since requestHeaders was null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Getting ContextResolver for class org.apache.wink.common.model.XmlFormattingOptions which has @Produces compatible with application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - ContextResolvers MediaTypeMap was empty so returning null
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Set response Content-Type to: application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.MediaTypeMapper - Did not find a mapping record so returning original response media type: application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Flushing headers: CaseInsensitiveMultivaluedMap [map=[]]
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.p.e.x.AbstractJAXBProvider - Marshaller placed back into pool
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler - Flushing headers if not written
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.h.AbstractHandlersChain - Invoking handler: org.apache.wink.server.internal.handlers.HeadMethodHandler
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Attempting to release resource instance
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Releasing resource instance
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.RequestProcessor - Finished response handlers chain
> {noformat}
> Its overwhelming. What happened to the wire logging? Is that TRACE?
> Personally I think that Wink should consider using DEBUG for minimal-verbosity describing what is going on, what URI, what params, which resource was selected... I kinda think that the wire stuff should be in there too, and thats it.
> I don't personally care how mediatypes are compared or selected, ie:
> {noformat}
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/json
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - Comparing application/xml to application/xml
> jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.PopulateResponseMediaTypeHandler - MediaType compatible so using candidate type application/xml
> {noformat}
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.