[jboss-jira] [JBoss JIRA] (WFLY-10904) Lower logging level of messages for OpenTracing

[Jan Stourac (JIRA)]

    [ https://issues.jboss.org/browse/WFLY-10904?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13623773#comment-13623773 ] 

Jan Stourac commented on WFLY-10904:
------------------------------------

[~juraci.costa], thank you for the update.

I've briefly tried how the logging looks like with current master ({{3c8d65218a7e64126f86708e56c0a21bbf281a97}}). The {{Initialized tracer}} info message is shorter indeed and doesn't pollute the log too much anymore. As I stated before, I still think there is too much information on INFO level. Although, I don't consider this part as a blocker anymore. Just one thing - I noticed that it looks like same information is logged on both INFO and DEBUG level. When I increased logging to debug and deployed jax-rs application, I can see following messages in the server.log:
{code}
10:52:11,446 DEBUG [io.undertow.session] (ServerService Thread Pool -- 72) Setting default session timeout to 1800
10:52:11,462 DEBUG [io.undertow.session] (ServerService Thread Pool -- 72) Registered session listener io.undertow.servlet.core.SessionListenerBridge at 235e513c
10:52:11,488 DEBUG [io.jaegertracing.thrift.internal.senders.ThriftSenderFactory] (ServerService Thread Pool -- 72) Using the UDP Sender to send spans to the agent.
10:52:11,502 DEBUG [io.jaegertracing.internal.senders.SenderResolver] (ServerService Thread Pool -- 72) Using sender UdpSender()
10:52:11,703 INFO  [io.jaegertracing.Configuration] (ServerService Thread Pool -- 72) Initialized tracer=JaegerTracer(version=Java-0.30.6, serviceName=helloworld-rs.war, reporter=RemoteReporter(sender=UdpSender(), closeEnqueueTimeout=1000), sampler=RemoteControlledSampler(maxOperations=2000, manager=HttpSamplingManager(hostPort=localhost:5778), sampler=ProbabilisticSampler(tags={sampler.type=probabilistic, sampler.param=0.001})), tags={hostname=dhcp-10-40-5-80.brq.redhat.com, jaeger.version=Java-0.30.6, ip=10.40.5.80}, zipkinSharedRpcSpan=false, expandExceptionLogs=false)
10:52:11,706 DEBUG [org.wildfly.microprofile.opentracing.smallrye] (ServerService Thread Pool -- 72) WFLYTRAC0004: Registering io.jaegertracing.internal.JaegerTracer as the OpenTracing Tracer
10:52:11,714 DEBUG [org.wildfly.microprofile.opentracing.smallrye] (ServerService Thread Pool -- 72) WFLYTRAC0001: Tracer initialized: JaegerTracer(version=Java-0.30.6, serviceName=helloworld-rs.war, reporter=RemoteReporter(sender=UdpSender(), closeEnqueueTimeout=1000), sampler=RemoteControlledSampler(maxOperations=2000, manager=HttpSamplingManager(hostPort=localhost:5778), sampler=ProbabilisticSampler(tags={sampler.type=probabilistic, sampler.param=0.001})), tags={hostname=dhcp-10-40-5-80.brq.redhat.com, jaeger.version=Java-0.30.6, ip=10.40.5.80}, zipkinSharedRpcSpan=false, expandExceptionLogs=false)
10:52:11,779 INFO  [org.wildfly.extension.undertow] (ServerService Thread Pool -- 72) WFLYUT0021: Registered web context: '/helloworld-rs' for server 'default-server'
10:52:11,903 INFO  [org.jboss.as.server] (management-handler-thread - 1) WFLYSRV0010: Deployed "helloworld-rs.war" (runtime-name : "helloworld-rs.war")
10:52:11,904 DEBUG [org.jboss.as.server.deployment.scanner] (ServerService Thread Pool -- 72) Updating status after deployment notification for helloworld-rs.war
{code}
Notice the '{{JaegerTracer(version=Java-0.30.6}}...' part - the same information is logged on both INFO and DEBUG level. I think this is what we don't want. We should either remove the INFO level at all in this case or just provide very brief info like:
{code}
10:52:11,703 INFO  \[io.jaegertracing.Configuration\] (ServerService Thread Pool -- 72) Initialized tracer for service helloworld-rs.war
{code}

> Lower logging level of messages for OpenTracing
> -----------------------------------------------
>
>                 Key: WFLY-10904
>                 URL: https://issues.jboss.org/browse/WFLY-10904
>             Project: WildFly
>          Issue Type: Bug
>          Components: MP OpenTracing
>    Affects Versions: 14.0.0.Beta2
>            Reporter: Jan Stourac
>            Assignee: Juraci Paixão Kröhling
>            Priority: Blocker
>             Fix For: 14.0.0.CR1
>
>
> Current logging for OpenTracing is quite verbose logging long messages in INFO level, e.g.:
> {code}
> 17:38:45,359 INFO  [io.jaegertracing.internal.senders.SenderResolver] (ServerService Thread Pool -- 28) Using sender UdpSender(udpTransport=ThriftUdpTransport(socket=java.net.DatagramSocket at 3e9a2205, receiveBuf=null, receiveOffSet=-1, receiveLength=0))
> 17:38:45,395 INFO  [io.jaegertracing.Configuration] (ServerService Thread Pool -- 28) Initialized tracer=JaegerTracer(version=Java-0.30.4, serviceName=deployment.war, reporter=RemoteReporter(queueProcessor=RemoteReporter.QueueProcessor(open=true), sender=UdpSender(udpTransport=ThriftUdpTransport(socket=java.net.DatagramSocket at 3e9a2205, receiveBuf=null, receiveOffSet=-1, receiveLength=0)), closeEnqueueTimeout=1000), sampler=RemoteControlledSampler(maxOperations=2000, serviceName=deployment.war, manager=HttpSamplingManager(gson={serializeNulls:false,factories:[Factory[typeHierarchy=com.google.gson.JsonElement,adapter=com.google.gson.internal.bind.TypeAdapters$29 at 5795d61d], com.google.gson.internal.bind.ObjectTypeAdapter$1 at 7286f924, com.google.gson.internal.Excluder at 10bd7673, Factory[type=java.lang.String,adapter=com.google.gson.internal.bind.TypeAdapters$16 at 56577ab9], Factory[type=java.lang.Integer+int,adapter=com.google.gson.internal.bind.TypeAdapters$7 at 2f0b6b50], Factory[type=java.lang.Boolean+boolean,adapter=com.google.gson.internal.bind.TypeAdapters$3 at 6a01f84c], Factory[type=java.lang.Byte+byte,adapter=com.google.gson.internal.bind.TypeAdapters$5 at 11f41591], Factory[type=java.lang.Short+short,adapter=com.google.gson.internal.bind.TypeAdapters$6 at 7c9b37a4], Factory[type=java.lang.Long+long,adapter=com.google.gson.internal.bind.TypeAdapters$11 at 8be828c], Factory[type=java.lang.Double+double,adapter=com.google.gson.Gson$1 at 6d18d84f], Factory[type=java.lang.Float+float,adapter=com.google.gson.Gson$2 at 5c7110e0], Factory[type=java.lang.Number,adapter=com.google.gson.internal.bind.TypeAdapters$14 at 79f22add], Factory[type=java.util.concurrent.atomic.AtomicInteger,adapter=com.google.gson.TypeAdapter$1 at 5a47d8d], Factory[type=java.util.concurrent.atomic.AtomicBoolean,adapter=com.google.gson.TypeAdapter$1 at 2ed507d6], Factory[type=java.util.concurrent.atomic.AtomicLong,adapter=com.google.gson.TypeAdapter$1 at 7af7f4fc], Factory[type=java.util.concurrent.atomic.AtomicLongArray,adapter=com.google.gson.TypeAdapter$1 at 123b9dbd], Factory[type=java.util.concurrent.atomic.AtomicIntegerArray,adapter=com.google.gson.TypeAdapter$1 at 3455c262], Factory[type=java.lang.Character+char,adapter=com.google.gson.internal.bind.TypeAdapters$15 at 32b89889], Factory[type=java.lang.StringBuilder,adapter=com.google.gson.internal.bind.TypeAdapters$19 at 772dda36], Factory[type=java.lang.StringBuffer,adapter=com.google.gson.internal.bind.TypeAdapters$20 at 3935671b], Factory[type=java.math.BigDecimal,adapter=com.google.gson.internal.bind.TypeAdapters$17 at 23e9f48d], Factory[type=java.math.BigInteger,adapter=com.google.gson.internal.bind.TypeAdapters$18 at 55634ca9], Factory[type=java.net.URL,adapter=com.google.gson.internal.bind.TypeAdapters$21 at 4c06d059], Factory[type=java.net.URI,adapter=com.google.gson.internal.bind.TypeAdapters$22 at 5e997b7d], Factory[type=java.util.UUID,adapter=com.google.gson.internal.bind.TypeAdapters$24 at 3238a1bf], Factory[type=java.util.Currency,adapter=com.google.gson.TypeAdapter$1 at 7d71b555], Factory[type=java.util.Locale,adapter=com.google.gson.internal.bind.TypeAdapters$28 at 70f36ba], Factory[typeHierarchy=java.net.InetAddress,adapter=com.google.gson.internal.bind.TypeAdapters$23 at 12d8e7b5], Factory[type=java.util.BitSet,adapter=com.google.gson.TypeAdapter$1 at 659a9908], com.google.gson.internal.bind.DateTypeAdapter$1 at 153143f3, Factory[type=java.util.Calendar+java.util.GregorianCalendar,adapter=com.google.gson.internal.bind.TypeAdapters$27 at 6bf50d09], com.google.gson.internal.bind.TimeTypeAdapter$1 at 3e45ba8d, com.google.gson.internal.bind.SqlDateTypeAdapter$1 at f262694, com.google.gson.internal.bind.TypeAdapters$26 at 1017c258, com.google.gson.internal.bind.ArrayTypeAdapter$1 at 53c90816, Factory[type=java.lang.Class,adapter=com.google.gson.TypeAdapter$1 at 40cb5130], com.google.gson.internal.bind.CollectionTypeAdapterFactory at 7e67cd3b, com.google.gson.internal.bind.MapTypeAdapterFactory at 504cd5ad, com.google.gson.internal.bind.JsonAdapterAnnotationTypeAdapterFactory at 4b5efe0a, com.google.gson.internal.bind.TypeAdapters$30 at 51066480, com.google.gson.internal.bind.ReflectiveTypeAdapterFactory at 11c8758e],instanceCreators:{}}, hostPort=localhost:5778), metrics=io.jaegertracing.internal.metrics.Metrics at 279f3ba7, sampler=ProbabilisticSampler(positiveSamplingBoundary=9223372036854776, negativeSamplingBoundary=-9223372036854776, samplingRate=0.001, tags={sampler.type=probabilistic, sampler.param=0.001})), ipv4=2130706433, tags={hostname=rhel7-large-74052, jaeger.version=Java-0.30.4, ip=127.0.0.1}, zipkinSharedRpcSpan=false, baggageSetter=io.jaegertracing.internal.baggage.BaggageSetter at 1b8d3ff0, expandExceptionLogs=false)
> {code}
> I think these messages are not useful on INFO level and should be lowered to either DEBUG or TRACE level.



--
This message was sent by Atlassian JIRA
(v7.5.0#75005)