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.requestproces...@6128453c
using attribute name org.apache.wink.server.internal.RequestProcessor in
servlet context
servletcont...@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.statusresou...@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
[[email protected]()], 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$guicesingletonobjectfact...@561140db],
OFHolder [genericType=class java.lang.Object, mediaType=application/xml,
of=Priority: 0.100000, ObjectFactory:
org.apache.wink.guice.server.internal.lifecycle.guiceinjectorlifecyclemanager$guicesingletonobjectfact...@531a700a],
OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority:
0.100000, ObjectFactory:
org.apache.wink.guice.server.internal.lifecycle.guiceinjectorlifecyclemanager$guicesingletonobjectfact...@4df2a9da],
OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority:
0.100000, ObjectFactory:
org.apache.wink.guice.server.internal.lifecycle.guiceinjectorlifecyclemanager$guicesingletonobjectfact...@561140db],
OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority:
0.100000, ObjectFactory:
org.apache.wink.guice.server.internal.lifecycle.guiceinjectorlifecyclemanager$guicesingletonobjectfact...@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$guicesingletonobjectfact...@561140db],
OFHolder [genericType=class java.lang.Object, mediaType=application/xml,
of=Priority: 0.100000, ObjectFactory:
org.apache.wink.guice.server.internal.lifecycle.guiceinjectorlifecyclemanager$guicesingletonobjectfact...@531a700a],
OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority:
0.100000, ObjectFactory:
org.apache.wink.guice.server.internal.lifecycle.guiceinjectorlifecyclemanager$guicesingletonobjectfact...@4df2a9da],
OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority:
0.100000, ObjectFactory:
org.apache.wink.guice.server.internal.lifecycle.guiceinjectorlifecyclemanager$guicesingletonobjectfact...@561140db],
OFHolder [genericType=class java.lang.Object, mediaType=*/*, of=Priority:
0.100000, ObjectFactory:
org.apache.wink.guice.server.internal.lifecycle.guiceinjectorlifecyclemanager$guicesingletonobjectfact...@531a700a]]
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Calling
org.apache.wink.common.internal.providers.entity.xml.jaxbcollectionxmlprovi...@9a303d3.iswriteable(
class com.sonatype.benson.rest.model.Status, class
com.sonatype.benson.rest.model.Status, [[email protected]()], application/xml
)
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry - Calling
org.apache.wink.common.internal.providers.entity.xml.jaxbxmlprovi...@14dd18cc.iswriteable(
class com.sonatype.benson.rest.model.Status, class
com.sonatype.benson.rest.model.Status, [[email protected]()], application/xml
)
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.c.i.r.ProvidersRegistry -
org.apache.wink.common.internal.providers.entity.xml.jaxbxmlprovi...@14dd18cc.iswriteable(
class com.sonatype.benson.rest.model.Status, class
com.sonatype.benson.rest.model.Status, [[email protected]()], 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.jaxbxmlprovi...@14dd18cc.getsize(com.sonatype.benson.rest.model.sta...@7cb96ac0,
class com.sonatype.benson.rest.model.Status, class
com.sonatype.benson.rest.model.Status, [[email protected]()],
application/xml) returned -1
jvm 1 | DEBUG [qtp1721336021-23] o.a.w.s.i.h.FlushResultHandler -
org.apache.wink.common.internal.providers.entity.xml.jaxbxmlprovi...@14dd18cc.writeto(com.sonatype.benson.rest.model.sta...@7cb96ac0,
class com.sonatype.benson.rest.model.Status, class
com.sonatype.benson.rest.model.Status, [[email protected]()],
application/xml, CaseInsensitiveMultivaluedMap [map=[]],
org.apache.wink.server.internal.handlers.flushresulthandler$flushheadersoutputstr...@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.
