pinpoint-apm / pinpoint

APM, (Application Performance Management) tool for large-scale distributed systems.
https://pinpoint-apm.gitbook.io/
Apache License 2.0
13.42k stars 3.75k forks source link

Pinpoint is not tracking HTTP errors #4146

Closed ing-arriola closed 6 years ago

ing-arriola commented 6 years ago

Description

Recently I have done extensive tests with Pinpoint to verify the way it shows the errors, that is to say if it is more comfortable for a developer to have access to the errors from Pinpoint instead of having to check the WAS Weblogic Log where I have I have unfortunately found that Pinpoint is not able to classify an HTTP 500 error precisely as an error, when reviewing the call tree I realized that the error transaction was actually received by Pinpoint but it is not marked as an error ... Why is this happening?

In my case I have thought about three hyposthesis I mention them:

  1. The Pinpoint sampling rate was lower than the speed at which the transactions occurred ... for me this is false given that the transactions with error were in the Call Tree.

  2. The error codes were not correctly configured ... this is also false given that you check the Pinpoint.config file and have the following line configured: profiler.http.status.code.errors = 5xx

  3. I do not know if the alteration of the Log4J file in the route: Agent / lib / log4J.xml has some weight in the matter ....

The only thing that is clear to me is that Pinpoint does not classify HTTP 500 errors as such, but rather only as transactions without any particular feature.

By the way i am wondering... What Pinpoint sees as an "error"???

I attach the WebLogic Log to support what I said; any help will be happily received and in advance thank you very much.

Please compare the attached image with the Log in the part where I have highlighted in order to verify that effectively when WebLogic detects an error, Pinpoint does not see it as an HTTP error.

Psdt: The test application is a small calculator that performs the basic operations.

2018-05-21 10:36:26 INFO profiler.weblogic.enable=true 2018-05-21 10:36:26 INFO profiler.weblogic.excludeurl= 2018-05-21 10:36:26 INFO profiler.weblogic.tracerequestparam=true <May 21, 2018 10:36:26 AM CST> <May 21, 2018 10:36:26 AM CST> <May 21, 2018 10:36:27 AM CST> <May 21, 2018 10:36:27 AM CST> <May 21, 2018 10:36:27 AM CST> <May 21, 2018 10:36:57 AM CST> <May 21, 2018 10:36:57 AM CST> <May 21, 2018 10:36:57 AM CST> <Starting "async" replication service with remote cluster address "null"> <May 21, 2018 10:36:57 AM CST> <Channel "Default" is now listening on 172.23.112.192:7004 for protocols iiop, t3, CLUSTER-BROADCAST, ldap, snmp, http.> <May 21, 2018 10:36:57 AM CST> <Started WebLogic Managed Server "test3" for domain "my_domain" running in Production Mode> <May 21, 2018 10:36:58 AM CST> <May 21, 2018 10:36:58 AM CST> <May 21, 2018 10:37:51 AM CST> <[ServletContext@1128068367[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception java.lang.NumberFormatException: For input string: "13161387Y" at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043) at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110) at java.lang.Double.parseDouble(Double.java:538) at jsp_servlet.__controlador._jspService(__controlador.java:75) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) Truncated. see log file for complete stacktrace

<May 21, 2018 10:38:09 AM CST> <[ServletContext@1128068367[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception java.lang.NumberFormatException: For input string: "13161387Y" at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043) at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110) at java.lang.Double.parseDouble(Double.java:538) at jsp_servlet.__controlador._jspService(__controlador.java:75) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) Truncated. see log file for complete stacktrace

<May 21, 2018 10:38:11 AM CST> <[ServletContext@1128068367[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception java.lang.NumberFormatException: For input string: "13161387Y" at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043) at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110) at java.lang.Double.parseDouble(Double.java:538) at jsp_servlet.__controlador._jspService(__controlador.java:75) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) Truncated. see log file for complete stacktrace

<May 21, 2018 10:38:19 AM CST> <[ServletContext@1128068367[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception java.lang.NumberFormatException: For input string: "13161387Y" at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043) at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110) at java.lang.Double.parseDouble(Double.java:538) at jsp_servlet.__controlador._jspService(__controlador.java:75) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) Truncated. see log file for complete stacktrace

<May 21, 2018 10:38:20 AM CST> <[ServletContext@1128068367[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception java.lang.NumberFormatException: For input string: "13161387Y" at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043) at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110) at java.lang.Double.parseDouble(Double.java:538) at jsp_servlet.__controlador._jspService(__controlador.java:75) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) Truncated. see log file for complete stacktrace

<May 21, 2018 10:38:22 AM CST> <[ServletContext@1128068367[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception java.lang.NumberFormatException: For input string: "13161387Y" at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043) at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110) at java.lang.Double.parseDouble(Double.java:538) at jsp_servlet.__controlador._jspService(__controlador.java:75) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) Truncated. see log file for complete stacktrace

<May 21, 2018 10:38:24 AM CST> <[ServletContext@1128068367[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception java.lang.NumberFormatException: For input string: "13161387Y" at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043) at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110) at java.lang.Double.parseDouble(Double.java:538) at jsp_servlet.__controlador._jspService(__controlador.java:75) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) Truncated. see log file for complete stacktrace

<May 21, 2018 10:38:25 AM CST> <[ServletContext@1128068367[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception java.lang.NumberFormatException: For input string: "13161387Y" at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043) at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110) at java.lang.Double.parseDouble(Double.java:538) at jsp_servlet.__controlador._jspService(__controlador.java:75) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) Truncated. see log file for complete stacktrace

<May 21, 2018 10:38:28 AM CST> <[ServletContext@1128068367[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception java.lang.NumberFormatException: For input string: "13161387Y" at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043) at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110) at java.lang.Double.parseDouble(Double.java:538) at jsp_servlet.__controlador._jspService(__controlador.java:75) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) Truncated. see log file for complete stacktrace

<May 21, 2018 10:38:32 AM CST> <[ServletContext@1128068367[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception java.lang.NumberFormatException: For input string: "13161387YJKJKJK" at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043) at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110) at java.lang.Double.parseDouble(Double.java:538) at jsp_servlet.__controlador._jspService(__controlador.java:75) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) Truncated. see log file for complete stacktrace

<May 21, 2018 10:38:36 AM CST> <[ServletContext@1128068367[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception java.lang.NumberFormatException: For input string: "13161387YJKJKJK666" at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043) at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110) at java.lang.Double.parseDouble(Double.java:538) at jsp_servlet.__controlador._jspService(__controlador.java:75) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) Truncated. see log file for complete stacktrace

<May 21, 2018 10:38:40 AM CST> <[ServletContext@1128068367[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception java.lang.NumberFormatException: For input string: "13161387YJKJKJK666" at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043) at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110) at java.lang.Double.parseDouble(Double.java:538) at jsp_servlet.__controlador._jspService(__controlador.java:75) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) Truncated. see log file for complete stacktrace

<May 21, 2018 10:38:48 AM CST> <[ServletContext@1128068367[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception

java.lang.NumberFormatException: For input string: "UU7U7U" at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043) at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110) at java.lang.Double.parseDouble(Double.java:538) at jsp_servlet.__controlador._jspService(__controlador.java:75) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) Truncated. see log file for complete stacktrace

<May 21, 2018 10:38:53 AM CST> <[ServletContext@1128068367[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception java.lang.NumberFormatException: For input string: "UU7U7U" at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043) at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110) at java.lang.Double.parseDouble(Double.java:538) at jsp_servlet.__controlador._jspService(__controlador.java:75) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) Truncated. see log file for complete stacktrace

<May 21, 2018 10:38:58 AM CST> <[ServletContext@1128068367[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception java.lang.NumberFormatException: For input string: "UU7U7U" at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043) at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110) at java.lang.Double.parseDouble(Double.java:538) at jsp_servlet.__controlador._jspService(__controlador.java:75) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) Truncated. see log file for complete stacktrace

capture4

Environment

Additional Info

ing-arriola commented 6 years ago

UPDATE:

I have continued reviewing my test application and likewise other applications with the aim of identifying what happens with this problem of not showing the errors and I have a new assumption with a much stronger foundation: I have reviewed some transactions with errors and for example I have some which show me the detail of being a "Handled Exception", which was done at the time of development .... but the transactions that I know are errors and not the classifies as errors by Pinpoint it turns out that they are "Unhandled Exceptions" ... which are effectively reported in the WebLogic Log as errors ... so I have the slight feeling that Pinpoint can only classify a transaction as one that has an error in the case that the developer has thought in advance to add the controlled exception; for example in the case of an exception of type SQL, Java requires that when using JDBC there are some details such as entering values ​​in a table that must have the "Handled Exception" to allow me to compile. On the other hand there are errors that could happen as the case I gave as an example above where the sum between a number and a letter, where logically I know it will be an error and will be reflected in the WebLogic Log or any other WAS. but the fact that I do not put that operation of sum in a Try ... Catch does not affect the moment of compilation .... the correct thing would be that I as a developer foresee that situation and enter the sum in a Try ... Catch with something like "IllegalArgumentException" ... so it would be a great help to give feedback on this topic; Given that there are other APM that apparently are also trying to observe this issue, I attach a link to this.

In advance thank you very much for the help.

errores222

Xylus commented 6 years ago

Hi @ing-arriola Thank you for the very detailed analysis, really appreciate sharing and it was great following your thoughts regarding this.

The reason why the first NumberFormatException is not identified by pinpoint whereas the second SQLIntegrityConstraintViolationException is, is simple - the second exception has been propagated to a method in which the agent is tracing. For the SQLIntegrityConstraintViolationException, this method is executeUpdate(String), where pinpoint's Oracle driver plugin injects trace code right before and after it's invocation. So when oracle.jdbc.driver.OracleStatementWrapper.executeUpdate(String s) is invoked and a SQLIntegrityConstraintViolationException is thrown inside, the trace code injected to be run after the method invocation receives the exception and records the exception to be shown in the call stack, and marks the transaction as having an exception.

Compare this to the first case regarding NumberFormatException. Nothing is traced inside WebAppServletContext.execute(...) method so even if a NumberFormatException is thrown, there is nowhere that it could have gotten recorded.

Notice however, that both of the call stacks do not have exceptions associated with WebAppServletContext.execute(...) method. We can infer from this that even if an exception is thrown inside it, the exception is handled within (to redirect/generate to a 500 error page and not dump the error to the user) and is not propagated all the way back up. (Just going off by calculated guess as I don't have the source code for WebLogic to verify everything).

Does everything make sense? Please let me know if you have any questions. Thanks.

ing-arriola commented 6 years ago

Hi @Xylus Thank You Very Much!!! From your answer i have the following questions:

  1. If an exception is propagated to a method that is not being traced by the agent, as is the case of the NumberFormatException, then this means that the exception will NOT be classified as such (even if it exists and is shown in the WebLogic Log) and will not be marked in red by PinPoint (To put it simply). This may be true because there is no injection of before and after it's invocation. In this case ... could there be any way to register the exception without modifying the code of the application being monitored?

  2. Is Pinpoint able to trace or show the unhanded exceptions? (Obviously these should be controlled by the developer but I have observed that a project exists several as the NumberFormatException that I mentioned was not controlled)

  3. In the case of the NumberFormatException where that it could have gotten recorded?

By the way I include the Code of the App that i describe in my first post:

**------------------------------------------ JAVA CODE -------------------------------------------------***

package com.operaciones.test1;

public class prueba { public double opera(double a,double b,String operacion) { double total=0;

        switch (operacion) {
            case "SUM":
                total=a+b;
                break;
            case "MINUS":
                total=a-b;
                break;
            case "MULTIPLICATION":
                total=a*b;
                break;
            case "DIV":
                if(b!=0) {
                    total=a/b;
                }else {
                    System.out.println("DIV BY ZERO NOT ALLOWED!!!");
                }
                break;
        }

    return total;
}

}

--------------------------------------------- JSP -------------------------------------------------------

<%@ page import="com.operaciones.test1.*" %>

PAGE OF ANSWER:


<% String k; double a=Double.parseDouble(request.getParameter("dato1")); double b=Double.parseDouble(request.getParameter("dato2")); prueba op=new prueba(); out.println("ANSWER IS: "+op.opera(a, b, request.getParameter("opsel"))); out.println(""); %>
<% out.println("DATA ARE: "+a+"y"+b); %>

------------ SOME CODE OF AN EXCEPTION SIMILAR TO SQL --------

image

jaehong-kim commented 6 years ago

@ing-arriola Not yet applied to weblogic.

profiler.http.status.code.errors = 5xx
Xylus commented 6 years ago

@ing-arriola You could also try adding WebLogic jsp support to our jsp plugin. Although I haven't tried, it could be as simple as injecting HttpJspBaseServiceMethodInterceptor to weblogic.servlet.jsp.JspBase similar to it being injected to org.apache.jasper.runtime.HttpJspBase for those using Jasper engines (see JspPlugin.java).

It'd be great if you could try this out and send us a PR if it works fine :)

ing-arriola commented 6 years ago

Hi @Xylus

From your comment I understood that WebLogic JSP support should be added to the Pinpoint JspPlugin.java ; for such support to be done it must be injected HttpJspBaseServiceMethodInterceptor to the weblogic.servlet.jsp.JspBase and to org.apache.jasper.runtime.HttpJspBase

Then to make such injections ... I understand that I must modify weblogic.servlet.jsp.JspBase but that is a file that resides within the WAS WebLogic .... or not ?. Of being that it can not be modified, on the other hand it is perhaps a method similar to the one of the link is the one that must be created and added to the class JspPlugin.java ???

For example:

weblogic_support

Thanks in advance

Xylus commented 6 years ago

@ing-arriola Yes, that is correct. Since weblogic.servlet.jsp.JspBase is a part of WebLogic jar, it cannot be modified directly, we must add a transformer to the class at load time which is what the code you posted is doing.

ing-arriola commented 6 years ago

Hi @Xylus

I added the change I mentioned earlier and that according to your comment was what was needed for Pinpoint to be able to show me the transaction in error, effectively like that. It happens that as previously I have not modified the application that is executed since it contains an exception not controlled and the final intention is to detect that type of situations and that Pinpoint effectively shows it as an error. On the other hand according to the Logs seems to be working but when I generate the errors using the application and doing something similar to what I commented previously (ie add a letter and a number that is clearly an error) Pinpoint let the transaction pass as if not It was an error.

By the way... If this method would be declared ... Where do I have to put the call to it ??? I did not put the call and I was thinking that that may be affecting ...

In summary what I did was:

1. Modify the JspPlugin.java file which is as follows:

`/*

import com.navercorp.pinpoint.bootstrap.instrument.InstrumentClass; import com.navercorp.pinpoint.bootstrap.instrument.InstrumentException; import com.navercorp.pinpoint.bootstrap.instrument.InstrumentMethod; import com.navercorp.pinpoint.bootstrap.instrument.Instrumentor; import com.navercorp.pinpoint.bootstrap.instrument.transformer.TransformCallback; import com.navercorp.pinpoint.bootstrap.instrument.transformer.TransformTemplate; import com.navercorp.pinpoint.bootstrap.instrument.transformer.TransformTemplateAware; import com.navercorp.pinpoint.bootstrap.logging.PLogger; import com.navercorp.pinpoint.bootstrap.logging.PLoggerFactory; import com.navercorp.pinpoint.bootstrap.plugin.ProfilerPlugin; import com.navercorp.pinpoint.bootstrap.plugin.ProfilerPluginSetupContext;

import java.security.ProtectionDomain;

/**

2. Build Pinpoint using Maven and get the agent, collector and web from there.

3. Display the war of the collector and web on the server that would be the monitor

4. Deploy the agent in WebLogic

5. Start the application in WebLogic and generate the error

6. I have copied the Logs of both the agent and WebLogic expecting them to reflect in detail what is happening.

If you need a Log in more detail I can gladly share them here, at the moment I only leave a part that refers to the moment when I generate the error but Pinpoint does not classify them as an error.

PINPOINT AGENT LOG:

2018-05-28 14:58:12 [DEBUG](c.n.p.p.s.UdpDataSender :154) Data sent. size:275, TSpan(agentId:AGENTEXCEPTIONS, applicationName:WLSPRUEBAEXCEPTIONS, agentStartTime:1527540932105, transactionId:00 01 89 BC A3 C4 BA 2C 09, spanId:286413637141285647, startTime:1527541092091, elapsed:23, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.44, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:22, serviceType:1071, annotations:[TAnnotation(key:41, value:)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0) 2018-05-28 14:58:21 DEBUG BEFORE weblogic.servlet.internal.WebAppServletContext args:(ServletRequestImpl, ServletResponseImpl) 2018-05-28 14:58:21 DEBUG SamplingFlag:null 2018-05-28 14:58:21 [DEBUG](c.n.p.p.c.LoggingBaseTraceFactory :89 ) newTraceObject() 2018-05-28 14:58:21 DEBUG register ActiveTrace key:SampledActiveTrace{traceRoot=DefaultTraceRoot{traceId=DefaultTraceId{agentId='AGENTEXCEPTIONS', agentStartTime=1527540932105, transactionSequence=10, parentSpanId=-1, spanId=8492893450064104230, flags=0}, agentId='AGENTEXCEPTIONS', traceStartTime=1527541101896}} 2018-05-28 14:58:21 DEBUG TraceID not exist. start new trace. requestUrl:/test_linux/controlador.jsp, remoteAddr:172.23.112.44 2018-05-28 14:58:21 DEBUG AFTER weblogic.servlet.internal.WebAppServletContext args:(ServletRequestImpl, ServletResponseImpl) result:null 2018-05-28 14:58:21 [DEBUG](c.n.p.p.s.UdpDataSender :154) Data sent. size:276, TSpan(agentId:AGENTEXCEPTIONS, applicationName:WLSPRUEBAEXCEPTIONS, agentStartTime:1527540932105, transactionId:00 01 89 BC A3 C4 BA 2C 0A, spanId:8492893450064104230, startTime:1527541101896, elapsed:4, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.44, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:3, serviceType:1071, annotations:[TAnnotation(key:41, value:)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0) 2018-05-28 14:58:21 [DEBUG](c.n.p.p.c.s.BufferedStorage :106) [BufferedStorage] Flush span TSpan(agentId:AGENTEXCEPTIONS, applicationName:WLSPRUEBAEXCEPTIONS, agentStartTime:1527540932105, transactionId:00 01 89 BC A3 C4 BA 2C 0A, spanId:8492893450064104230, startTime:1527541101896, elapsed:4, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.44, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:3, serviceType:1071, annotations:[TAnnotation(key:41, value:)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0) 2018-05-28 14:58:21 DEBUG remove ActiveTrace key:DefaultActiveTraceHandle{id=10} 2018-05-28 14:58:27 DEBUG BEFORE weblogic.servlet.internal.WebAppServletContext args:(ServletRequestImpl, ServletResponseImpl) 2018-05-28 14:58:27 DEBUG SamplingFlag:null 2018-05-28 14:58:27 [DEBUG](c.n.p.p.c.LoggingBaseTraceFactory :89 ) newTraceObject() 2018-05-28 14:58:27 DEBUG register ActiveTrace key:SampledActiveTrace{traceRoot=DefaultTraceRoot{traceId=DefaultTraceId{agentId='AGENTEXCEPTIONS', agentStartTime=1527540932105, transactionSequence=11, parentSpanId=-1, spanId=7518114715112000926, flags=0}, agentId='AGENTEXCEPTIONS', traceStartTime=1527541107137}} 2018-05-28 14:58:27 DEBUG TraceID not exist. start new trace. requestUrl:/test_linux/controlador.jsp, remoteAddr:172.23.112.44 2018-05-28 14:58:27 DEBUG AFTER weblogic.servlet.internal.WebAppServletContext args:(ServletRequestImpl, ServletResponseImpl) result:null 2018-05-28 14:58:27 [DEBUG](c.n.p.p.s.UdpDataSender :154) Data sent. size:272, TSpan(agentId:AGENTEXCEPTIONS, applicationName:WLSPRUEBAEXCEPTIONS, agentStartTime:1527540932105, transactionId:00 01 89 BC A3 C4 BA 2C 0B, spanId:7518114715112000926, startTime:1527541107137, elapsed:5, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.44, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:4, serviceType:1071, annotations:[TAnnotation(key:41, value:)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0) 2018-05-28 14:58:27 [DEBUG](c.n.p.p.c.s.BufferedStorage :106) [BufferedStorage] Flush span TSpan(agentId:AGENTEXCEPTIONS, applicationName:WLSPRUEBAEXCEPTIONS, agentStartTime:1527540932105, transactionId:00 01 89 BC A3 C4 BA 2C 0B, spanId:7518114715112000926, startTime:1527541107137, elapsed:5, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.44, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:4, serviceType:1071, annotations:[TAnnotation(key:41, value:)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0) 2018-05-28 14:58:27 DEBUG remove ActiveTrace key:DefaultActiveTraceHandle{id=11}

WEBLOGIC LOG:

2018-05-28 14:58:12 DEBUG BEFORE weblogic.servlet.internal.WebAppServletContext args:(ServletRequestImpl, ServletResponseImpl) 2018-05-28 14:58:12 DEBUG SamplingFlag:null 2018-05-28 14:58:12 [DEBUG](c.n.p.p.c.LoggingBaseTraceFactory :89 ) newTraceObject() 2018-05-28 14:58:12 DEBUG register ActiveTrace key:SampledActiveTrace{traceRoot=DefaultTraceRoot{traceId=DefaultTraceId{agentId='AGENTEXCEPTIONS', agentStartTime=1527540932105, transactionSequence=9, parentSpanId=-1, spanId=286413637141285647, flags=0}, agentId='AGENTEXCEPTIONS', traceStartTime=1527541092091}} 2018-05-28 14:58:12 DEBUG TraceID not exist. start new trace. requestUrl:/test_linux/controlador.jsp, remoteAddr:172.23.112.44 <May 28, 2018 2:58:12 PM CST> <[ServletContext@1251907357[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception java.lang.NumberFormatException: For input string: "23345675g67676442116161684351646134" at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043) at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110) at java.lang.Double.parseDouble(Double.java:538) at jsp_servlet.__controlador._jspService(__controlador.java:75) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) Truncated. see log file for complete stacktrace

2018-05-28 14:58:12 DEBUG AFTER weblogic.servlet.internal.WebAppServletContext args:(ServletRequestImpl, ServletResponseImpl) result:null 2018-05-28 14:58:12 [DEBUG](c.n.p.p.c.s.BufferedStorage :106) [BufferedStorage] Flush span TSpan(agentId:AGENTEXCEPTIONS, applicationName:WLSPRUEBAEXCEPTIONS, agentStartTime:1527540932105, transactionId:00 01 89 BC A3 C4 BA 2C 09, spanId:286413637141285647, startTime:1527541092091, elapsed:23, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.44, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:22, serviceType:1071, annotations:[TAnnotation(key:41, value:)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0) 2018-05-28 14:58:12 DEBUG remove ActiveTrace key:DefaultActiveTraceHandle{id=9} 2018-05-28 14:58:12 [DEBUG](c.n.p.p.s.UdpDataSender :154) Data sent. size:275, TSpan(agentId:AGENTEXCEPTIONS, applicationName:WLSPRUEBAEXCEPTIONS, agentStartTime:1527540932105, transactionId:00 01 89 BC A3 C4 BA 2C 09, spanId:286413637141285647, startTime:1527541092091, elapsed:23, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.44, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:22, serviceType:1071, annotations:[TAnnotation(key:41, value:)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0) <May 28, 2018 2:58:16 PM CST> <Closing socket as no data read from it on 172.23.112.44:61,112 during the configured idle timeout of 5 secs> 2018-05-28 14:58:21 DEBUG BEFORE weblogic.servlet.internal.WebAppServletContext args:(ServletRequestImpl, ServletResponseImpl) 2018-05-28 14:58:21 DEBUG SamplingFlag:null 2018-05-28 14:58:21 [DEBUG](c.n.p.p.c.LoggingBaseTraceFactory :89 ) newTraceObject() 2018-05-28 14:58:21 DEBUG register ActiveTrace key:SampledActiveTrace{traceRoot=DefaultTraceRoot{traceId=DefaultTraceId{agentId='AGENTEXCEPTIONS', agentStartTime=1527540932105, transactionSequence=10, parentSpanId=-1, spanId=8492893450064104230, flags=0}, agentId='AGENTEXCEPTIONS', traceStartTime=1527541101896}} 2018-05-28 14:58:21 DEBUG TraceID not exist. start new trace. requestUrl:/test_linux/controlador.jsp, remoteAddr:172.23.112.44 <May 28, 2018 2:58:21 PM CST> <[ServletContext@1251907357[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception java.lang.NumberFormatException: For input string: "23345675g67676442116161684351646134" at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043) at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110) at java.lang.Double.parseDouble(Double.java:538) at jsp_servlet.__controlador._jspService(__controlador.java:75) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) Truncated. see log file for complete stacktrace

2018-05-28 14:58:21 DEBUG AFTER weblogic.servlet.internal.WebAppServletContext args:(ServletRequestImpl, ServletResponseImpl) result:null 2018-05-28 14:58:21 [DEBUG](c.n.p.p.s.UdpDataSender :154) Data sent. size:276, TSpan(agentId:AGENTEXCEPTIONS, applicationName:WLSPRUEBAEXCEPTIONS, agentStartTime:1527540932105, transactionId:00 01 89 BC A3 C4 BA 2C 0A, spanId:8492893450064104230, startTime:1527541101896, elapsed:4, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.44, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:3, serviceType:1071, annotations:[TAnnotation(key:41, value:)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0) 2018-05-28 14:58:21 [DEBUG](c.n.p.p.c.s.BufferedStorage :106) [BufferedStorage] Flush span TSpan(agentId:AGENTEXCEPTIONS, applicationName:WLSPRUEBAEXCEPTIONS, agentStartTime:1527540932105, transactionId:00 01 89 BC A3 C4 BA 2C 0A, spanId:8492893450064104230, startTime:1527541101896, elapsed:4, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.44, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:3, serviceType:1071, annotations:[TAnnotation(key:41, value:)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0) 2018-05-28 14:58:21 DEBUG remove ActiveTrace key:DefaultActiveTraceHandle{id=10} <May 28, 2018 2:58:26 PM CST> <Closing socket as no data read from it on 172.23.112.44:61,115 during the configured idle timeout of 5 secs> 2018-05-28 14:58:27 DEBUG BEFORE weblogic.servlet.internal.WebAppServletContext args:(ServletRequestImpl, ServletResponseImpl) 2018-05-28 14:58:27 DEBUG SamplingFlag:null 2018-05-28 14:58:27 [DEBUG](c.n.p.p.c.LoggingBaseTraceFactory :89 ) newTraceObject() 2018-05-28 14:58:27 DEBUG register ActiveTrace key:SampledActiveTrace{traceRoot=DefaultTraceRoot{traceId=DefaultTraceId{agentId='AGENTEXCEPTIONS', agentStartTime=1527540932105, transactionSequence=11, parentSpanId=-1, spanId=7518114715112000926, flags=0}, agentId='AGENTEXCEPTIONS', traceStartTime=1527541107137}} 2018-05-28 14:58:27 DEBUG TraceID not exist. start new trace. requestUrl:/test_linux/controlador.jsp, remoteAddr:172.23.112.44 <May 28, 2018 2:58:27 PM CST> <[ServletContext@1251907357[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception java.lang.NumberFormatException: For input string: "23345675g67676442116161684351646134" at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043) at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110) at java.lang.Double.parseDouble(Double.java:538) at jsp_servlet.__controlador._jspService(__controlador.java:75) at weblogic.servlet.jsp.JspBase.service(JspBase.java:34) Truncated. see log file for complete stacktrace

2018-05-28 14:58:27 DEBUG AFTER weblogic.servlet.internal.WebAppServletContext args:(ServletRequestImpl, ServletResponseImpl) result:null

Beforehand thank you very much

Xylus commented 6 years ago

Hi @ing-arriola You have to call addWebLogicJspSupport() inside the setup(ProfilerPluginSetupContext context) method.

ing-arriola commented 6 years ago

Hi @Xylus Make the call to the method as you commented, I will carry out the test and I share my results.

Xylus commented 6 years ago

sounds good :)

ing-arriola commented 6 years ago

Hi @Xylus

I modified the class called JspPlugin.java as you mentioned earlier (that is, I added the method addWebLogicJspSupport () and its respective call inside the setup (ProfilerPluginSetupContext context) method), attach the modification I made. Later I built Pinpoint using Maven and finally deployed the collector and web war ... finally the agent in Weblogic. Once everything was working, the connection was successful but when I entered an error trying to add a number and a letter as I explained earlier that it is an Unhandled exception, nothing new happened. PinPoint continues to pass that transaction as if it did not contain an error .... I do not know why that can happen .... Annex the Logs of:

### WebLogic
2018-05-31 11:07:00 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:97 ) BEFORE weblogic.servlet.internal.WebAppServletContext  args:(ServletRequestImpl, ServletResponseImpl)
2018-05-31 11:07:00 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:285) SamplingFlag:null
2018-05-31 11:07:00 [DEBUG](c.n.p.p.c.LoggingBaseTraceFactory  :89 ) newTraceObject()
2018-05-31 11:07:00 [DEBUG](.p.c.a.DefaultActiveTraceRepository:108) register ActiveTrace key:SampledActiveTrace{traceRoot=DefaultTraceRoot{traceId=DefaultTraceId{agentId='forfirstag', agentStartTime=1527785686715, transactionSequence=20, parentSpanId=-1, spanId=5895972289356128626, flags=0}, agentId='forfirstag', traceStartTime=1527786420956}}
2018-05-31 11:07:00 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:290) TraceID not exist. start new trace. requestUrl:/test_linux/controlador.jsp, remoteAddr:172.23.112.192
### <May 31, 2018 11:07:00 AM CST> <Error> <HTTP> <BEA-101020> <[ServletContext@938511037[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] ### Servlet failed with Exception
### java.lang.NumberFormatException: For input string: "hgfhgh615g"
###     at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043)
###     at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110)
###     at java.lang.Double.parseDouble(Double.java:538)
###     at jsp_servlet.__controlador._jspService(__controlador.java:75)
###     at weblogic.servlet.jsp.JspBase.service(JspBase.java:34)
###     Truncated. see log file for complete stacktrace
### > 
2018-05-31 11:07:00 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:122) AFTER weblogic.servlet.internal.WebAppServletContext  args:(ServletRequestImpl, ServletResponseImpl) result:null
2018-05-31 11:07:00 [DEBUG](c.n.p.p.c.s.BufferedStorage        :106) [BufferedStorage] Flush span TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 14, spanId:5895972289356128626, startTime:1527786420956, elapsed:2, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:0, endElapsed:2, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=DIVISION&dato1=hgfhgh615g&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:07:00 [DEBUG](.p.c.a.DefaultActiveTraceRepository:77 ) remove ActiveTrace key:DefaultActiveTraceHandle{id=20}
2018-05-31 11:07:00 [DEBUG](c.n.p.p.s.UdpDataSender            :154) Data sent. size:213, TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 14, spanId:5895972289356128626, startTime:1527786420956, elapsed:2, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:0, endElapsed:2, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=DIVISION&dato1=hgfhgh615g&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:07:04 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:97 ) BEFORE weblogic.servlet.internal.WebAppServletContext  args:(ServletRequestImpl, ServletResponseImpl)
2018-05-31 11:07:04 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:285) SamplingFlag:null
2018-05-31 11:07:04 [DEBUG](c.n.p.p.c.LoggingBaseTraceFactory  :89 ) newTraceObject()
2018-05-31 11:07:04 [DEBUG](.p.c.a.DefaultActiveTraceRepository:108) register ActiveTrace key:SampledActiveTrace{traceRoot=DefaultTraceRoot{traceId=DefaultTraceId{agentId='forfirstag', agentStartTime=1527785686715, transactionSequence=21, parentSpanId=-1, spanId=-5806343023473299612, flags=0}, agentId='forfirstag', traceStartTime=1527786424427}}
2018-05-31 11:07:04 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:290) TraceID not exist. start new trace. requestUrl:/test_linux/controlador.jsp, remoteAddr:172.23.112.192
<May 31, 2018 11:07:04 AM CST> <Error> <HTTP> <BEA-101020> <[ServletContext@938511037[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception
java.lang.NumberFormatException: For input string: "hgfhgh615g"
    at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043)
    at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110)
    at java.lang.Double.parseDouble(Double.java:538)
    at jsp_servlet.__controlador._jspService(__controlador.java:75)
    at weblogic.servlet.jsp.JspBase.service(JspBase.java:34)
    Truncated. see log file for complete stacktrace
>
2018-05-31 11:07:04 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:122) AFTER weblogic.servlet.internal.WebAppServletContext  args:(ServletRequestImpl, ServletResponseImpl) result:null
2018-05-31 11:07:04 [DEBUG](c.n.p.p.s.UdpDataSender            :154) Data sent. size:209, TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 15, spanId:-5806343023473299612, startTime:1527786424427, elapsed:1, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:0, endElapsed:1, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=SUMA&dato1=hgfhgh615g&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:07:04 [DEBUG](c.n.p.p.c.s.BufferedStorage        :106) [BufferedStorage] Flush span TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 15, spanId:-5806343023473299612, startTime:1527786424427, elapsed:1, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:0, endElapsed:1, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=SUMA&dato1=hgfhgh615g&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:07:04 [DEBUG](.p.c.a.DefaultActiveTraceRepository:77 ) remove ActiveTrace key:DefaultActiveTraceHandle{id=21}
2018-05-31 11:07:08 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:97 ) BEFORE weblogic.servlet.internal.WebAppServletContext  args:(ServletRequestImpl, ServletResponseImpl)
2018-05-31 11:07:08 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:285) SamplingFlag:null
2018-05-31 11:07:08 [DEBUG](c.n.p.p.c.LoggingBaseTraceFactory  :89 ) newTraceObject()
2018-05-31 11:07:08 [DEBUG](.p.c.a.DefaultActiveTraceRepository:108) register ActiveTrace key:SampledActiveTrace{traceRoot=DefaultTraceRoot{traceId=DefaultTraceId{agentId='forfirstag', agentStartTime=1527785686715, transactionSequence=22, parentSpanId=-1, spanId=-5624968436172721513, flags=0}, agentId='forfirstag', traceStartTime=1527786428838}}
2018-05-31 11:07:08 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:290) TraceID not exist. start new trace. requestUrl:/test_linux/controlador.jsp, remoteAddr:172.23.112.192
<May 31, 2018 11:07:08 AM CST> <Error> <HTTP> <BEA-101020> ### <[ServletContext@938511037[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] ### Servlet failed with Exception
### java.lang.NumberFormatException: For input string: "hgfhgh615g"
###     at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043)
###     at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110)
###     at java.lang.Double.parseDouble(Double.java:538)
###     at jsp_servlet.__controlador._jspService(__controlador.java:75)
###     at weblogic.servlet.jsp.JspBase.service(JspBase.java:34)
###     Truncated. see log file for complete stacktrace
### > 
2018-05-31 11:07:08 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:122) AFTER weblogic.servlet.internal.WebAppServletContext  args:(ServletRequestImpl, ServletResponseImpl) result:null
2018-05-31 11:07:08 [DEBUG](c.n.p.p.c.s.BufferedStorage        :106) [BufferedStorage] Flush span TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 16, spanId:-5624968436172721513, startTime:1527786428838, elapsed:2, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:1, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=RESTA&dato1=hgfhgh615g&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:07:08 [DEBUG](.p.c.a.DefaultActiveTraceRepository:77 ) remove ActiveTrace key:DefaultActiveTraceHandle{id=22}
2018-05-31 11:07:08 [DEBUG](c.n.p.p.s.UdpDataSender            :154) Data sent. size:210, TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 16, spanId:-5624968436172721513, startTime:1527786428838, elapsed:2, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:1, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=RESTA&dato1=hgfhgh615g&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:07:15 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:97 ) BEFORE weblogic.servlet.internal.WebAppServletContext  args:(ServletRequestImpl, ServletResponseImpl)
2018-05-31 11:07:15 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:285) SamplingFlag:null
2018-05-31 11:07:15 [DEBUG](c.n.p.p.c.LoggingBaseTraceFactory  :89 ) newTraceObject()
2018-05-31 11:07:15 [DEBUG](.p.c.a.DefaultActiveTraceRepository:108) register ActiveTrace key:SampledActiveTrace{traceRoot=DefaultTraceRoot{traceId=DefaultTraceId{agentId='forfirstag', agentStartTime=1527785686715, transactionSequence=23, parentSpanId=-1, spanId=-2218195174869066778, flags=0}, agentId='forfirstag', traceStartTime=1527786435279}}
2018-05-31 11:07:15 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:290) TraceID not exist. start new trace. requestUrl:/test_linux/controlador.jsp, remoteAddr:172.23.112.192
<May 31, 2018 11:07:15 AM CST> <Error> <HTTP> <BEA-101020> <[ServletContext@938511037[app:test_linux module:test_linux.war path:/test_linux spec-version:2.5]] Servlet failed with Exception
java.lang.NumberFormatException: For input string: "yhgn"
    at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:2043)
    at sun.misc.FloatingDecimal.parseDouble(FloatingDecimal.java:110)
    at java.lang.Double.parseDouble(Double.java:538)
    at jsp_servlet.__controlador._jspService(__controlador.java:76)
    at weblogic.servlet.jsp.JspBase.service(JspBase.java:34)
    Truncated. see log file for complete stacktrace
> 
2018-05-31 11:07:15 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:122) AFTER weblogic.servlet.internal.WebAppServletContext  args:(ServletRequestImpl, ServletResponseImpl) result:null
2018-05-31 11:07:15 [DEBUG](c.n.p.p.s.UdpDataSender            :154) Data sent. size:205, TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 17, spanId:-2218195174869066778, startTime:1527786435279, elapsed:2, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:1, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=RESTA&dato1=454545&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:07:15 [DEBUG](c.n.p.p.c.s.BufferedStorage        :106) [BufferedStorage] Flush span TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 17, spanId:-2218195174869066778, startTime:1527786435279, elapsed:2, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:1, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=RESTA&dato1=454545&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:07:15 [DEBUG](.p.c.a.DefaultActiveTraceRepository:77 ) remove ActiveTrace key:DefaultActiveTraceHandle{id=23}
2018-05-31 11:07:19 [DEBUG](c.n.p.p.s.UdpDataSender            :154) Data sent. size:808, TAgentStatBatch(agentId:forfirstag, startTimestamp:1527785686715, agentStats:[TAgentStat(agentId:forfirstag, startTimestamp:1527785686715, timestamp:1527786414007, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:251875584, jvmMemoryHeapMax:1014497280, jvmMemoryNonHeapUsed:130964872, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:319), cpuLoad:TCpuLoad(jvmCpuLoad:0.003453038674033149, systemCpuLoad:0.23895027624309392), transaction:TTransaction(sampledNewCount:1, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime(avg:1, max:1), fileDescriptor:TFileDescriptor(openFileDescriptorCount:379), directBuffer:TDirectBuffer(directCount:12, directMemoryUsed:113851, mappedCount:0, mappedMemoryUsed:0)), TAgentStat(agentId:forfirstag, startTimestamp:1527785686715, timestamp:1527786419006, collectInterval:4999, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:251875584, jvmMemoryHeapMax:1014497280, jvmMemoryNonHeapUsed:130996008, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:319), cpuLoad:TCpuLoad(jvmCpuLoad:0.0034626038781163434, systemCpuLoad:0.2126038781163435), transaction:TTransaction(sampledNewCount:1, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime(avg:3, max:3), fileDescriptor:TFileDescriptor(openFileDescriptorCount:379), directBuffer:TDirectBuffer(directCount:12, directMemoryUsed:113851, mappedCount:0, mappedMemoryUsed:0)), TAgentStat(agentId:forfirstag, startTimestamp:1527785686715, timestamp:1527786424006, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:251875584, jvmMemoryHeapMax:1014497280, jvmMemoryNonHeapUsed:131005416, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:319), cpuLoad:TCpuLoad(jvmCpuLoad:0.0041841004184100415, systemCpuLoad:0.23291492329149233), transaction:TTransaction(sampledNewCount:1, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime(avg:2, max:2), fileDescriptor:TFileDescriptor(openFileDescriptorCount:379), directBuffer:TDirectBuffer(directCount:12, directMemoryUsed:113851, mappedCount:0, mappedMemoryUsed:0)), TAgentStat(agentId:forfirstag, startTimestamp:1527785686715, timestamp:1527786429007, collectInterval:5001, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:251875584, jvmMemoryHeapMax:1014497280, jvmMemoryNonHeapUsed:131014080, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:319), cpuLoad:TCpuLoad(jvmCpuLoad:0.0034965034965034965, systemCpuLoad:0.22867132867132867), transaction:TTransaction(sampledNewCount:2, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime(avg:1, max:2), fileDescriptor:TFileDescriptor(openFileDescriptorCount:379), directBuffer:TDirectBuffer(directCount:12, directMemoryUsed:113851, mappedCount:0, mappedMemoryUsed:0)), TAgentStat(agentId:forfirstag, startTimestamp:1527785686715, timestamp:1527786434006, collectInterval:4999, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:251875584, jvmMemoryHeapMax:1014497280, jvmMemoryNonHeapUsed:131014080, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:319), cpuLoad:TCpuLoad(jvmCpuLoad:0.00138217000691085, systemCpuLoad:0.1824464409122322), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime(), fileDescriptor:TFileDescriptor(openFileDescriptorCount:379), directBuffer:TDirectBuffer(directCount:12, directMemoryUsed:113851, mappedCount:0, mappedMemoryUsed:0)), TAgentStat(agentId:forfirstag, startTimestamp:1527785686715, timestamp:1527786439007, collectInterval:5001, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:252743896, jvmMemoryHeapMax:1014497280, jvmMemoryNonHeapUsed:131027712, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:319), cpuLoad:TCpuLoad(jvmCpuLoad:0.0027662517289073307, systemCpuLoad:0.20470262793914246), transaction:TTransaction(sampledNewCount:1, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime(avg:2, max:2), fileDescriptor:TFileDescriptor(openFileDescriptorCount:379), directBuffer:TDirectBuffer(directCount:12, directMemoryUsed:113851, mappedCount:0, mappedMemoryUsed:0))])

### Agent

2018-05-31 11:06:57 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:122) AFTER weblogic.servlet.internal.WebAppServletContext  args:(ServletRequestImpl, ServletResponseImpl) result:null
2018-05-31 11:06:57 [DEBUG](c.n.p.p.s.UdpDataSender            :154) Data sent. size:215, TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 13, spanId:-2118578892398011616, startTime:1527786417140, elapsed:3, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:2, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=DIVISION&dato1=168461681615g&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:06:57 [DEBUG](c.n.p.p.c.s.BufferedStorage        :106) [BufferedStorage] Flush span TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 13, spanId:-2118578892398011616, startTime:1527786417140, elapsed:3, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:2, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=DIVISION&dato1=168461681615g&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:06:57 [DEBUG](.p.c.a.DefaultActiveTraceRepository:77 ) remove ActiveTrace key:DefaultActiveTraceHandle{id=19}
**2018-05-31 11:07:00 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:97 ) BEFORE weblogic.servlet.internal.WebAppServletContext  args:(ServletRequestImpl, ServletResponseImpl)
2018-05-31 11:07:00 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:285) SamplingFlag:null
2018-05-31 11:07:00 [DEBUG](c.n.p.p.c.LoggingBaseTraceFactory  :89 ) newTraceObject()
2018-05-31 11:07:00 [DEBUG](.p.c.a.DefaultActiveTraceRepository:108) register ActiveTrace key:SampledActiveTrace{traceRoot=DefaultTraceRoot{traceId=DefaultTraceId{agentId='forfirstag', agentStartTime=1527785686715, transactionSequence=20, parentSpanId=-1, spanId=5895972289356128626, flags=0}, agentId='forfirstag', traceStartTime=1527786420956}}
2018-05-31 11:07:00 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:290) TraceID not exist. start new trace. requestUrl:/test_linux/controlador.jsp, remoteAddr:172.23.112.192
2018-05-31 11:07:00 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:122) AFTER weblogic.servlet.internal.WebAppServletContext  args:(ServletRequestImpl, ServletResponseImpl) result:null
2018-05-31 11:07:00 [DEBUG](c.n.p.p.c.s.BufferedStorage        :106) [BufferedStorage] Flush span TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 14, spanId:5895972289356128626, startTime:1527786420956, elapsed:2, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:0, endElapsed:2, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=DIVISION&dato1=hgfhgh615g&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:07:00 [DEBUG](.p.c.a.DefaultActiveTraceRepository:77 ) remove ActiveTrace key:DefaultActiveTraceHandle{id=20}
2018-05-31 11:07:00 [DEBUG](c.n.p.p.s.UdpDataSender            :154) Data sent. size:213, TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 14, spanId:5895972289356128626, startTime:1527786420956, elapsed:2, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:0, endElapsed:2, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=DIVISION&dato1=hgfhgh615g&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)**
2018-05-31 11:07:04 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:97 ) BEFORE weblogic.servlet.internal.WebAppServletContext  args:(ServletRequestImpl, ServletResponseImpl)
2018-05-31 11:07:04 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:285) SamplingFlag:null
2018-05-31 11:07:04 [DEBUG](c.n.p.p.c.LoggingBaseTraceFactory  :89 ) newTraceObject()
2018-05-31 11:07:04 [DEBUG](.p.c.a.DefaultActiveTraceRepository:108) register ActiveTrace key:SampledActiveTrace{traceRoot=DefaultTraceRoot{traceId=DefaultTraceId{agentId='forfirstag', agentStartTime=1527785686715, transactionSequence=21, parentSpanId=-1, spanId=-5806343023473299612, flags=0}, agentId='forfirstag', traceStartTime=1527786424427}}
2018-05-31 11:07:04 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:290) TraceID not exist. start new trace. requestUrl:/test_linux/controlador.jsp, remoteAddr:172.23.112.192
2018-05-31 11:07:04 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:122) AFTER weblogic.servlet.internal.WebAppServletContext  args:(ServletRequestImpl, ServletResponseImpl) result:null
2018-05-31 11:07:04 [DEBUG](c.n.p.p.s.UdpDataSender            :154) Data sent. size:209, TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 15, spanId:-5806343023473299612, startTime:1527786424427, elapsed:1, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:0, endElapsed:1, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=SUMA&dato1=hgfhgh615g&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:07:04 [DEBUG](c.n.p.p.c.s.BufferedStorage        :106) [BufferedStorage] Flush span TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 15, spanId:-5806343023473299612, startTime:1527786424427, elapsed:1, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:0, endElapsed:1, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=SUMA&dato1=hgfhgh615g&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:07:04 [DEBUG](.p.c.a.DefaultActiveTraceRepository:77 ) remove ActiveTrace key:DefaultActiveTraceHandle{id=21}
2018-05-31 11:07:08 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:97 ) BEFORE weblogic.servlet.internal.WebAppServletContext  args:(ServletRequestImpl, ServletResponseImpl)
2018-05-31 11:07:08 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:285) SamplingFlag:null
2018-05-31 11:07:08 [DEBUG](c.n.p.p.c.LoggingBaseTraceFactory  :89 ) newTraceObject()
2018-05-31 11:07:08 [DEBUG](.p.c.a.DefaultActiveTraceRepository:108) register ActiveTrace key:SampledActiveTrace{traceRoot=DefaultTraceRoot{traceId=DefaultTraceId{agentId='forfirstag', agentStartTime=1527785686715, transactionSequence=22, parentSpanId=-1, spanId=-5624968436172721513, flags=0}, agentId='forfirstag', traceStartTime=1527786428838}}
2018-05-31 11:07:08 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:290) TraceID not exist. start new trace. requestUrl:/test_linux/controlador.jsp, remoteAddr:172.23.112.192
2018-05-31 11:07:08 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:122) AFTER weblogic.servlet.internal.WebAppServletContext  args:(ServletRequestImpl, ServletResponseImpl) result:null
2018-05-31 11:07:08 [DEBUG](c.n.p.p.c.s.BufferedStorage        :106) [BufferedStorage] Flush span TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 16, spanId:-5624968436172721513, startTime:1527786428838, elapsed:2, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:1, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=RESTA&dato1=hgfhgh615g&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:07:08 [DEBUG](.p.c.a.DefaultActiveTraceRepository:77 ) remove ActiveTrace key:DefaultActiveTraceHandle{id=22}
2018-05-31 11:07:08 [DEBUG](c.n.p.p.s.UdpDataSender            :154) Data sent. size:210, TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 16, spanId:-5624968436172721513, startTime:1527786428838, elapsed:2, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:1, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=RESTA&dato1=hgfhgh615g&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:07:15 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:97 ) BEFORE weblogic.servlet.internal.WebAppServletContext  args:(ServletRequestImpl, ServletResponseImpl)
2018-05-31 11:07:15 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:285) SamplingFlag:null
2018-05-31 11:07:15 [DEBUG](c.n.p.p.c.LoggingBaseTraceFactory  :89 ) newTraceObject()
2018-05-31 11:07:15 [DEBUG](.p.c.a.DefaultActiveTraceRepository:108) register ActiveTrace key:SampledActiveTrace{traceRoot=DefaultTraceRoot{traceId=DefaultTraceId{agentId='forfirstag', agentStartTime=1527785686715, transactionSequence=23, parentSpanId=-1, spanId=-2218195174869066778, flags=0}, agentId='forfirstag', traceStartTime=1527786435279}}
2018-05-31 11:07:15 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:290) TraceID not exist. start new trace. requestUrl:/test_linux/controlador.jsp, remoteAddr:172.23.112.192
2018-05-31 11:07:15 [DEBUG](.p.p.w.i.ServletStubImplInterceptor:122) AFTER weblogic.servlet.internal.WebAppServletContext  args:(ServletRequestImpl, ServletResponseImpl) result:null
2018-05-31 11:07:15 [DEBUG](c.n.p.p.s.UdpDataSender            :154) Data sent. size:205, TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 17, spanId:-2218195174869066778, startTime:1527786435279, elapsed:2, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:1, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=RESTA&dato1=454545&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:07:15 [DEBUG](c.n.p.p.c.s.BufferedStorage        :106) [BufferedStorage] Flush span TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 17, spanId:-2218195174869066778, startTime:1527786435279, elapsed:2, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:1, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=RESTA&dato1=454545&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:07:15 [DEBUG](.p.c.a.DefaultActiveTraceRepository:77 ) remove ActiveTrace key:DefaultActiveTraceHandle{id=23}
2018-05-31 11:07:19 [DEBUG](c.n.p.p.s.UdpDataSender            :154) Data sent. size:808, TAgentStatBatch(agentId:forfirstag, startTimestamp:1527785686715, agentStats:[TAgentStat(agentId:forfirstag, startTimestamp:1527785686715, timestamp:1527786414007, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:251875584, jvmMemoryHeapMax:1014497280, jvmMemoryNonHeapUsed:130964872, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:319), cpuLoad:TCpuLoad(jvmCpuLoad:0.003453038674033149, systemCpuLoad:0.23895027624309392), transaction:TTransaction(sampledNewCount:1, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime(avg:1, max:1), fileDescriptor:TFileDescriptor(openFileDescriptorCount:379), directBuffer:TDirectBuffer(directCount:12, directMemoryUsed:113851, mappedCount:0, mappedMemoryUsed:0)), TAgentStat(agentId:forfirstag, startTimestamp:1527785686715, timestamp:1527786419006, collectInterval:4999, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:251875584, jvmMemoryHeapMax:1014497280, jvmMemoryNonHeapUsed:130996008, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:319), cpuLoad:TCpuLoad(jvmCpuLoad:0.0034626038781163434, systemCpuLoad:0.2126038781163435), transaction:TTransaction(sampledNewCount:1, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime(avg:3, max:3), fileDescriptor:TFileDescriptor(openFileDescriptorCount:379), directBuffer:TDirectBuffer(directCount:12, directMemoryUsed:113851, mappedCount:0, mappedMemoryUsed:0)), TAgentStat(agentId:forfirstag, startTimestamp:1527785686715, timestamp:1527786424006, collectInterval:5000, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:251875584, jvmMemoryHeapMax:1014497280, jvmMemoryNonHeapUsed:131005416, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:319), cpuLoad:TCpuLoad(jvmCpuLoad:0.0041841004184100415, systemCpuLoad:0.23291492329149233), transaction:TTransaction(sampledNewCount:1, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime(avg:2, max:2), fileDescriptor:TFileDescriptor(openFileDescriptorCount:379), directBuffer:TDirectBuffer(directCount:12, directMemoryUsed:113851, mappedCount:0, mappedMemoryUsed:0)), TAgentStat(agentId:forfirstag, startTimestamp:1527785686715, timestamp:1527786429007, collectInterval:5001, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:251875584, jvmMemoryHeapMax:1014497280, jvmMemoryNonHeapUsed:131014080, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:319), cpuLoad:TCpuLoad(jvmCpuLoad:0.0034965034965034965, systemCpuLoad:0.22867132867132867), transaction:TTransaction(sampledNewCount:2, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime(avg:1, max:2), fileDescriptor:TFileDescriptor(openFileDescriptorCount:379), directBuffer:TDirectBuffer(directCount:12, directMemoryUsed:113851, mappedCount:0, mappedMemoryUsed:0)), TAgentStat(agentId:forfirstag, startTimestamp:1527785686715, timestamp:1527786434006, collectInterval:4999, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:251875584, jvmMemoryHeapMax:1014497280, jvmMemoryNonHeapUsed:131014080, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:319), cpuLoad:TCpuLoad(jvmCpuLoad:0.00138217000691085, systemCpuLoad:0.1824464409122322), transaction:TTransaction(sampledNewCount:0, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime(), fileDescriptor:TFileDescriptor(openFileDescriptorCount:379), directBuffer:TDirectBuffer(directCount:12, directMemoryUsed:113851, mappedCount:0, mappedMemoryUsed:0)), TAgentStat(agentId:forfirstag, startTimestamp:1527785686715, timestamp:1527786439007, collectInterval:5001, gc:TJvmGc(type:PARALLEL, jvmMemoryHeapUsed:252743896, jvmMemoryHeapMax:1014497280, jvmMemoryNonHeapUsed:131027712, jvmMemoryNonHeapMax:-1, jvmGcOldCount:4, jvmGcOldTime:319), cpuLoad:TCpuLoad(jvmCpuLoad:0.0027662517289073307, systemCpuLoad:0.20470262793914246), transaction:TTransaction(sampledNewCount:1, sampledContinuationCount:0, unsampledNewCount:0, unsampledContinuationCount:0), activeTrace:TActiveTrace(histogram:TActiveTraceHistogram(version:0, histogramSchemaType:2, activeTraceCount:[0, 0, 0, 0])), dataSourceList:TDataSourceList(dataSourceList:[]), responseTime:TResponseTime(avg:2, max:2), fileDescriptor:TFileDescriptor(openFileDescriptorCount:379), directBuffer:TDirectBuffer(directCount:12, directMemoryUsed:113851, mappedCount:0, mappedMemoryUsed:0))])

### Collector (Deployed in a TOMCAT)

**2018-05-31 11:07:02 [DEBUG](c.n.p.c.h.SpanHandler              :76 ) Received SPAN=TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 14, spanId:5895972289356128626, startTime:1527786420956, elapsed:2, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:0, endElapsed:2, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=DIVISION&dato1=hgfhgh615g&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)**
2018-05-31 11:07:02 [DEBUG](p.c.d.h.HbaseMapStatisticsCallerDao:95 ) [Caller] firstappn (USER) forfirstag -> firstappn (WEBLOGIC)[forfirstag]
2018-05-31 11:07:02 [DEBUG](p.c.d.h.HbaseMapStatisticsCalleeDao:95 ) [Callee] firstappn (WEBLOGIC) <- firstappn (USER)[forfirstag]
2018-05-31 11:07:02 [DEBUG](c.n.p.c.d.h.HbaseMapResponseTimeDao:95 ) [Received] firstappn (WEBLOGIC)[forfirstag]
2018-05-31 11:07:02 [DEBUG](c.n.p.c.h.SpanHandler              :165) handle spanEvent size:1
2018-05-31 11:07:02 [DEBUG](p.c.d.h.HbaseMapStatisticsCalleeDao:145) flush HbaseMapStatisticsCalleeDao to [ApplicationMapStatisticsCaller_Ver2] Increment:1
2018-05-31 11:07:02 [DEBUG](p.c.d.h.HbaseMapStatisticsCallerDao:143) flush HbaseMapStatisticsCallerDao to [ApplicationMapStatisticsCallee_Ver2] Increment:1
2018-05-31 11:07:02 [DEBUG](c.n.p.c.d.h.HbaseMapResponseTimeDao:139) flush HbaseMapResponseTimeDao to [ApplicationMapStatisticsSelf_Ver2] Increment:1
2018-05-31 11:07:05 [DEBUG](c.n.p.c.h.SpanHandler              :76 ) Received SPAN=TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 15, spanId:-5806343023473299612, startTime:1527786424427, elapsed:1, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:0, endElapsed:1, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=SUMA&dato1=hgfhgh615g&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:07:05 [DEBUG](p.c.d.h.HbaseMapStatisticsCallerDao:95 ) [Caller] firstappn (USER) forfirstag -> firstappn (WEBLOGIC)[forfirstag]
2018-05-31 11:07:05 [DEBUG](p.c.d.h.HbaseMapStatisticsCalleeDao:95 ) [Callee] firstappn (WEBLOGIC) <- firstappn (USER)[forfirstag]
2018-05-31 11:07:05 [DEBUG](c.n.p.c.d.h.HbaseMapResponseTimeDao:95 ) [Received] firstappn (WEBLOGIC)[forfirstag]
2018-05-31 11:07:05 [DEBUG](c.n.p.c.h.SpanHandler              :165) handle spanEvent size:1
2018-05-31 11:07:06 [DEBUG](p.c.d.h.HbaseMapStatisticsCallerDao:143) flush HbaseMapStatisticsCallerDao to [ApplicationMapStatisticsCallee_Ver2] Increment:1
2018-05-31 11:07:06 [DEBUG](p.c.d.h.HbaseMapStatisticsCalleeDao:145) flush HbaseMapStatisticsCalleeDao to [ApplicationMapStatisticsCaller_Ver2] Increment:1
2018-05-31 11:07:06 [DEBUG](c.n.p.c.d.h.HbaseMapResponseTimeDao:139) flush HbaseMapResponseTimeDao to [ApplicationMapStatisticsSelf_Ver2] Increment:1
2018-05-31 11:07:09 [DEBUG](c.n.p.c.h.SpanHandler              :76 ) Received SPAN=TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 16, spanId:-5624968436172721513, startTime:1527786428838, elapsed:2, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:1, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=RESTA&dato1=hgfhgh615g&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)
2018-05-31 11:07:09 [DEBUG](p.c.d.h.HbaseMapStatisticsCallerDao:95 ) [Caller] firstappn (USER) forfirstag -> firstappn (WEBLOGIC)[forfirstag]
2018-05-31 11:07:09 [DEBUG](p.c.d.h.HbaseMapStatisticsCalleeDao:95 ) [Callee] firstappn (WEBLOGIC) <- firstappn (USER)[forfirstag]
2018-05-31 11:07:09 [DEBUG](c.n.p.c.d.h.HbaseMapResponseTimeDao:95 ) [Received] firstappn (WEBLOGIC)[forfirstag]
2018-05-31 11:07:09 [DEBUG](c.n.p.c.h.SpanHandler              :165) handle spanEvent size:1
2018-05-31 11:07:10 [DEBUG](p.c.d.h.HbaseMapStatisticsCallerDao:143) flush HbaseMapStatisticsCallerDao to [ApplicationMapStatisticsCallee_Ver2] Increment:1
2018-05-31 11:07:10 [DEBUG](p.c.d.h.HbaseMapStatisticsCalleeDao:145) flush HbaseMapStatisticsCalleeDao to [ApplicationMapStatisticsCaller_Ver2] Increment:1
2018-05-31 11:07:10 [DEBUG](c.n.p.c.d.h.HbaseMapResponseTimeDao:139) flush HbaseMapResponseTimeDao to [ApplicationMapStatisticsSelf_Ver2] Increment:1
2018-05-31 11:07:16 [DEBUG](c.n.p.c.h.SpanHandler              :76 ) Received SPAN=TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 17, spanId:-2218195174869066778, startTime:1527786435279, elapsed:2, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:1, serviceType:1071, annotations:[TAnnotation(key:41, value:<TAnnotationValue stringValue:opsel=RESTA&dato1=454545&dato2=yhgn>)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0)

Thanks & Regards for your comments

Xylus commented 6 years ago

@ing-arriola Thanks for trying it out. It looks like the interceptor in the jsp plugin is not getting called. Could you attach the full agent log (including the startup) so I can take a look?

ing-arriola commented 6 years ago

Hi @Xylus

As you requested, I share the agent's full log.

forfirstag-pinpoint.log

Xylus commented 6 years ago

Thanks for the log, everything looks like it should work except the code added in JspPlugin.java.

private void addWebLogicJspSupport() {
    transformTemplate.transform("weblogic.servlet.jsp.JspBase", new TransformCallback() {

        @Override
        public byte[] doInTransform(Instrumentor instrumentor, ClassLoader classLoader, String className, Class<?> classBeingRedefined, ProtectionDomain protectionDomain, byte[] classfileBuffer) throws InstrumentException {
            InstrumentClass target = instrumentor.getInstrumentClass(classLoader, className, classfileBuffer);

            // This should be:
            // final InstrumentMethod serviceMethod = target.getDeclaredMethod("service", "javax.servlet.ServletRequest", "javax.servlet.ServletResponse");
            final InstrumentMethod serviceMethod = target.getDeclaredMethod("service", "javax.servlet.http.HttpServletRequest", "javax.servlet.http.HttpServletResponse");
            if (serviceMethod != null) {
                serviceMethod.addInterceptor("com.navercorp.pinpoint.plugin.jsp.interceptor.HttpJspBaseServiceMethodInterceptor");
            }
            return target.toBytecode();
        }
    });
}

Please check the inlined comment above - weblogic.servlet.jsp.JspBase service method parameters are javax.servlet.ServletRequest and javax.servlet.ServletResponse.

ing-arriola commented 6 years ago

That is to say that I have set the incorrect parameters !!

I put the following: final InstrumentMethod serviceMethod = target.getDeclaredMethod("service", "javax.servlet.http.HttpServletRequest", "javax.servlet.http.HttpServletResponse");

But in your comment I see that it says: final InstrumentMethod serviceMethod = target.getDeclaredMethod("service", "javax.servlet.ServletRequest", "javax.servlet.ServletResponse");

I will make the change and I will carry out the compilation and deployment again ... in the servers, later I will comment the results which I think will be good!

Thank you so much!!!

Xylus commented 6 years ago

@ing-arriola Yes, I think so. Thank you for trying it out :)

ing-arriola commented 6 years ago

I Compile Pinpoint and deploy it as usual had done, perform the test with the exception that had commented before and ....... guess ...

It detect the exception unhandled!

Thank you very much!!!

Now we just need one more test in a testing environment where more transactions are executed !!

One question by the way ... How can I contribute so that this change that I consider important is reflected in the Pinpoint source code?

Likewise, if it seems good, I can share a screenshot of the correct functioning and likewise I can comment on the results obtained in the testing environment where there are many more transactions ....

By the way then the modification is as shown in your last comment and additionally the call to the method where you also commented ... if it seems good I can upload the .java file where the changes are already made.

Again, thank you very much and I will tell you soon the test in the testing environment with more transactions !!

Xylus commented 6 years ago

@ing-arriola Great news! If you could share us the test results it would be much appreciated. :) Also, please do throw us a pull request with your changes once you feel the changes are solid, Check our contribution guide for details and feel free to ask any questions here. Thanks.

ing-arriola commented 6 years ago

HI @Xylus

I think it's great, I'll try to share the results as soon as possible and I'll read the guide that you mention to make the pull request.

By the way, a question that is somewhat more ambitious is: In the Log of WebLogic when an error occurs it is able to show which is the line of code where the error occurs, either an exception or an error of another type ... so ...

I wonder if PinPoint could be able to show that level of detail ... this given that as I have seen in my preliminary test ...

Pinpoint shows the file where the unhandled exception occurs and is even able to tell me what kind of exception has happened ... but I think it was not able to tell me which line of a java file the error had occurred and I think it would be a fascinating feature that Pinpoint was able to trace the problem to the line where the error occurs ... I mention this because recently I was watching some APM videos that are paid but that reach that level of detail and that would greatly facilitate the developers the detail of solving the programming errors given that this could be avoided the problem of reviewing the WAS Logs such as the WebLogic Log ... I await your comment about it ... and again...

Thank you very much!!

Xylus commented 6 years ago

@ing-arriola Yes, collecting and recording stack traces on exceptions would be great, and it has been brought up a few times before. We haven't given it much work on it though as currently, showing the exception and it's message was usually enough. Thank you for a great suggestion, having stack trace available would make it even better (though as you've said, it would require quite a bit of work) :)

ing-arriola commented 6 years ago

Hi @Xylus

Could you give me some ideas of how that part (stack traces) could be started? I'm really interested in that feature; likewise I wanted to comment that I have not been able to put Pinpoint back into operation but as soon as I do I will publish the results ... by the way you need to share some information in specific when you do the test in the environment with a high rate of transactions. .. if you need the Logs or screenshots, please tell me and I will gladly put it here.

By the way I read the guide for pull request but I am not clear about this part: "include integration tests if possible."

I do not know what kind of tests are needed ... I would be very grateful if you could clarify that point

Again thank you very much!!

Xylus commented 6 years ago

Hi @ing-arriola It would be pretty hard to add integration tests to the jsp plugin so you can skip it. I'd also like to say that elaborate tests are not necessary for this particular feature as it's not doing anything extensive (it's simply tracing a single method call) and we can safely presume it's effects on performance. A simple screenshot of the call stack (like the one you posted in the opening post) for a few different jsp calls with exceptions covering different scenarios would suffice.

Regarding stack trace capturing, I don't think it's such a simple change that can be explained in any single issue. It would require changes to all agent, collector, and web modules as well as hbase if done properly and would require extensive planning and design. A good place to start would be to take a look at the code base and have a good grip on how data is collected, sent, received, stored, and read by all the different pinpoint modules. You'll probably then be able to come up with your own solution (which would probably be better than what I can draw up in this post) and get started. Thanks.

ing-arriola commented 6 years ago

Hello @Xylus

I have managed to install Pinpoint in the environment that I mentioned before that has many transactions to start with the issue of the unhandled exceptions that we have talked about extensively and that worked in my small environment with the exception of type numberFormat.

But unfortunately the test was done with some uncontrolled exceptions and Pinpoint was not able to catalog these transactions as errors again, just as it had previously happened. Check the WebLogic Log and again there are the HTTP 500 errors.

After seeing the log and thinking about the way you helped me solve before I concluded that apparently there are different types of Http 500 errors and trying to register these errors is very difficult since it would imply intercepting the class or servlet or services where the same generate For example if this day I have an error of type "500" and instrumentalize the necessary to register it, the problem would be that tomorrow there could be other errors http 500 of types "b", "c", ... etc.

Then, to register all of them, you must go through the WAS logs in question to add the necessary interceptors and thus be able to deal with as many uncontrolled exceptions. I am probably wrong and it is possible to generate a single interceptor to deal with all these errors but I do not know if that will be possible. On the other hand I share the messages of the WebLogic Log where are the errors that Pinpoint was not able to register precisely as errors.

WebLogic Log:

<Jun 11, 2018 8:24:50 AM CST> <Jun 11, 2018 8:24:50 AM CST> <[ServletContext@1415706851[app:aewap module:aewap.war path:/aewap spec-version:2.5]] Root cause of ServletException. javax.xml.ws.soap.SOAPFaultException: oracle.xdo.webservice.exception.OperationFailedException: PublicReportService::generateReport for reportAbsolutePath [/TEST/AEWAP/rpt_Detalle_Marcaciones_v2/rpt_Detalle_Marcaciones_v2.xdo] failed: due to oracle.xdo.server.ServerException: oracle.xdo.servlet.data.DataException: oracle.xdo.servlet.data.DataException: oracle.xdo.servlet.data.DataException: oracle.xdo.XDOException: java.sql.SQLException: ORA-06550: line 2, column 1: PLS-00201: identifier 'RPT_DETALLE_MARCACIONES_V2.FECINI' must be declared ORA-06550: line 2, column 1: PL/SQL: Statement ignored ORA-06550: line 3, column 1: PLS-00201: identifier 'RPT_DETALLE_MARCACIONES_V2.FECFIN' must be declared ORA-06550: line 3, column 1: PL/SQL: Statement ignored ORA-06550: line 4, column 1: PLS-00201: identifier 'RPT_DETALLE_MARCACIONES_V2.USERAPPI' must be declared ORA-06550: line 4, column 1: PL/SQL: Statement ignored ORA-06550: line 5, column 1: PLS-00201: identifier 'RPT_DETALLE_MARCACIONES_V2.CODE' must be declared ORA-06550: line 5, column 1: PL/SQL: Statement ignored

at com.sun.xml.ws.fault.SOAP11Fault.getProtocolException(SOAP11Fault.java:197)
at com.sun.xml.ws.fault.SOAPFaultBuilder.createException(SOAPFaultBuilder.java:130)
at com.sun.xml.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:125)
at com.sun.xml.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:95)
at com.sun.xml.ws.client.sei.SEIStub.invoke(SEIStub.java:136)
Truncated. see log file for complete stacktrace

<Jun 11, 2018 8:25:30 AM CST> <Jun 11, 2018 8:25:30 AM CST> <[ServletContext@1415706851[app:aewap module:aewap.war path:/aewap spec-version:2.5]] Root cause of ServletException. javax.xml.ws.soap.SOAPFaultException: oracle.xdo.webservice.exception.OperationFailedException: PublicReportService::generateReport for reportAbsolutePath [/TEST/AEWAP/rpt_Detalle_Marcaciones_v2/rpt_Detalle_Marcaciones_v2.xdo] failed: due to oracle.xdo.server.ServerException: oracle.xdo.servlet.data.DataException: oracle.xdo.servlet.data.DataException: oracle.xdo.servlet.data.DataException: oracle.xdo.XDOException: java.sql.SQLException: ORA-06550: line 2, column 1: PLS-00201: identifier 'RPT_DETALLE_MARCACIONES_V2.FECINI' must be declared ORA-06550: line 2, column 1: PL/SQL: Statement ignored ORA-06550: line 3, column 1: PLS-00201: identifier 'RPT_DETALLE_MARCACIONES_V2.FECFIN' must be declared ORA-06550: line 3, column 1: PL/SQL: Statement ignored ORA-06550: line 4, column 1: PLS-00201: identifier 'RPT_DETALLE_MARCACIONES_V2.USERAPPI' must be declared ORA-06550: line 4, column 1: PL/SQL: Statement ignored ORA-06550: line 5, column 1: PLS-00201: identifier 'RPT_DETALLE_MARCACIONES_V2.CODE' must be declared ORA-06550: line 5, column 1: PL/SQL: Statement ignored

at com.sun.xml.ws.fault.SOAP11Fault.getProtocolException(SOAP11Fault.java:197)
at com.sun.xml.ws.fault.SOAPFaultBuilder.createException(SOAPFaultBuilder.java:130)
at com.sun.xml.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:125)
at com.sun.xml.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:95)
at com.sun.xml.ws.client.sei.SEIStub.invoke(SEIStub.java:136)
Truncated. see log file for complete stacktrace

Thank you in advance for your help and comments on this topic.

Xylus commented 6 years ago

@ing-arriola If you're looking to have the servlet mark 5xx responses as errors, then the approach mentioned by @jaehong-kim above would be best (although I'm not sure if it'll cover the error you posted).

ing-arriola commented 6 years ago

Hi @Xylus

That does not work correctly because if that were the case, all the previous discussion we have had would not have been necessary. In fact what happens is an unhandled exception as you may have noticed in the part of the WebLogic Log that I have shared. So when we talked about the issue of the NumberFormat exception, what happened was an unhandled exception. The fact is that both exceptions are unhandled and generate an error of type HTTP 500, which probably as you mentioned above are not being intercepted and for that reason is added in the JspPlugin.java file an additional method and the call to it. My previous comment was focused on the situation that to classify the unhandled exceptions (which are also classified as HTTP 500 error) as an error it is necessary to add the interception of each of them, according to the procedure that was done before (ie the modification to the JspPlugin.java file). On the one hand it could be that way but this would imply having to generate the greatest number of types of errors and then adding one by one as appropriate, but that would be the most negative scenario and on the other hand I thought that there could probably be a method to be able to Intercept all these errors in a general way. The ideal would be the line that you mentioned but the problem is that in fact Pinpoint in the configuration file of the agent already has configured as I show you next. I hope you can help me with the problem of the Log so that I can make the necessary changes in Pinpoint, compile it and retest it and then perform the pull request.

config_agente

Beforehand thank you very much.

ing-arriola commented 6 years ago

Hi @Xylus

I hope you can help me with the comment I left earlier.

Thanks!

Xylus commented 6 years ago

Hi @ing-arriola Sorry I missed your last comment.

Using the profiler.http.status.code.errors configuration is the approach mentioned by @jaehong-kim earlier. If you take a look at Tomcat plugin's StandardHostValveInvokeInterceptor, you can see how it work. Basically, it'll take a look at the response object's http status code and if it matches the ones configured by profiler.http.status.code.errors, it'll mark the span as having an error. This however is not yet implemented in the Weblogic plugin so if this is what you are looking for, you will have to add something similar to the Weblogic plugin.

If you take a look at WeblogicPlugin, you'll see that it's adding an interceptor to weblogic.servlet.internal.WebAppServletContext#execute(ServletRequestImpl, ServletResponseImpl) method. Since the interceptor has access to ServletResponseImpl object, it will be able to get the http status code from it. I suggest taking a look at Tomcat plugin's StandardHostValveInvokeInterceptor (the HttpStatusCodeRecorder in it in particular and how it's used), to implement something similar to Weblogic plugin's ServletStubImplInterceptor.

Let me know if you have any questions. Thanks

Xylus commented 6 years ago

To explain a bit more on how this differs from the jsp plugin code you implemented - what you implemented is to hook the jsp processing. So if there is any exception thrown from the java code inside the jsp, your code in the jsp plugin will record it.

However, this only works for jsp. Other requests that are served differently will have any and all exceptions handled by weblogic.servlet.internal.WebAppServletContext#execute(ServletRequestImpl, ServletResponseImpl) method and have them converted to various http response status codes. Since any and all exceptions are handled, the interceptor in the Weblogic plugin will not see any exceptions and will never mark traces as having an error. This is where the second approach comes in. The HttpStatusCodeRecorder will take a look at the http response status code and if it matches 5xx (default), it'll mark the trace as having an error.

ing-arriola commented 6 years ago

Hi @Xylus

Here I share, as I mentioned before, some results that the change made in the JspPlugin.java file has indeed been successful in detecting the unhandled exceptions found in a project that has been presented with such problems. Now with the comments you have given me about the problem in general with the HTTP 500 errors, I will start to review the files that you have told me to implement the detection of all these errors in the WebLogic plugin. I will share here as in the previous occasion the modification that I made to the code so that this plugin is able to correctly report HTTP 500 errors.

Thank you very much for your help, comments and suggestions that have been very useful.

Soon I will put in this same topic the changes I made to achieve the goal that I mentioned before and by the way I am in debt with the pull request of the JspPlugin.java file but soon I will do it to add that functionality to the source files of the community. enc1 enc2 enc3 enc4

ing-arriola commented 6 years ago

Hi @Xylus

I have read your answer and trying to take your comment to the code I have done the following but I still have the doubt about the nnn file ... mainly because I see several methods that are declared but I am not entirely sure if in the interceptor file WebLogic plugin said methods should be. For example, here is a set of methods that I have seen but I am not sure if they should be in the www file: before despues de getRequestParameter . . . And many others

On the other hand I have also seen that this file has more than one class, in summary it contains the following classes: StandardHostValveInvokeInterceptor (This is the most interesting, as I understood) Bypass RealIpHeaderResolver

So in conclusion I have also seen that the call to obtain the state of the response object is in the deleteTrace method, this method I do not know if I should do it either, or on the other hand if all the additional work with respect to the HTTP 500 topic should be in the getRequest method of the ServletStubImplInterceptor file.

Here I share the idea that I have had about the change you have suggested, but after this I share I am not sure how to continue.

CODE:

package com.navercorp.pinpoint.plugin.weblogic.interceptor;
import com.navercorp.pinpoint.bootstrap.context.MethodDescriptor;
import com.navercorp.pinpoint.bootstrap.context.TraceContext;
import weblogic.servlet.internal.ServletRequestImpl;
import com.navercorp.pinpoint.bootstrap.plugin.http.HttpStatusCodeRecorder; //add the plugin of HttpStatusCodeRecorder

/**
 * 
 * @author andyspan
 *
 */
public class ServletStubImplInterceptor extends AbstractServerHandleInterceptor {

    private final HttpStatusCodeRecorder httpStatusCodeRecorder;//Add a variable to store http Status
    private TraceContext traceContext;//Add a variable to store trace Context
    public ServletStubImplInterceptor(TraceContext traceContext, MethodDescriptor descriptor) {
        super(traceContext, descriptor);
        this.traceContext = traceContext;//This get the TraceContext into the traceContext variable
        //As in the TOMCAT StandardHostValveInvokeInterceptor traceContext is set in constructor, i set the traceContext in constructor of this class
        this.httpStatusCodeRecorder = new HttpStatusCodeRecorder(traceContext.getProfilerConfig().getHttpStatusCodeErrors());//store code errors from configuration file
        //As in the TOMCAT StandardHostValveInvokeInterceptor httpStatusCodeRecorder is initialized in the
        //constructor, i initialized that variable in the constructor
    }
    @Override
    protected ServletRequestImpl getRequest(Object[] args) {
        final Object iRequestObject = args[0];

        if (!(iRequestObject instanceof ServletRequestImpl)) {
           return null;
        }
        return (ServletRequestImpl) iRequestObject;
    }
}
Xylus commented 6 years ago

Hi @ing-arriola I don't think you should add the code related to recording http response status code in the getRequest() of ServletStubImplInterceptor. What you could do is add an abstract method to AbstractServerHandleInterceptor's deleteTrace(...) for example -

    private void deleteTrace(Trace trace, Object target, Object[] args, Object result, Throwable throwable) {
        trace.traceBlockEnd();
        yourMethodHere(args);
        trace.close();
    }

    protected abstract yourMethodHere(Object[] args);

Then implement this method in ServletStubImplInterceptor to record the http response status code.

PS your screenshots on weblogic jsp trace look good :+1:

ing-arriola commented 6 years ago

Hi @Xylus

I have reviewed what you mentioned in your last two comments, I must apologize since I had not read in detail the use of HttpStatusCodeRecorder but now that I have done it I have a proposal of the implementation that you mentioned that practically takes up what has been done in the class StandardHostValveInvokeInterceptor, specifically in the deleteTrace method.

By the way, consider putting screenshots on this occasion because when I paste the code it gives me the sensation that it is uncomfortable for you to see it. On the other hand I also attach the files that I have modified, in case you want to make a modification that you consider appropriate.

ServletStubImplInterceptor.zip

I have attached a snapshot of the ServletStubImplInterceptor class that I modified:

clase_modificada

On the other hand I have also modified the AbstractServerHandleInterceptor class, I also attach a capture:

clase_2mod

After showing you what I have done, I must say that I have a very big doubt about the Response variable, which in Tomcat's case comes from this: import org.apache.catalina.connector.Response;

The truth is I do not know how to work that in WebLogic and likewise, although I have assumed that I should investigate what that Response does and then see what its equivalent in WebLogic would be to then make the appropriate substitution; On the other hand, if you had some idea of ​​how to solve that, it would be of great help to me, even if I will continue investigating to solve it.

Again, I appreciate all your comments that are of great help and I hope that this can be successfully completed so that PinPoint can have a much more complete support for one of the most used WAS.

PS: As you can see I have added an argument called trace that is of Trace type because the implementation of the webLogicHttpFiveHundred method that is the equivalent of deleteTrace in StandardHostValveInvokeInterceptor, also requires this variable to be used in the following line: final SpanRecorder spanRecorder = trace.getSpanRecorder ();

Thanks and regards

Xylus commented 6 years ago

WebLogic would have a different Response type. Please take a look at your WebLogic's WebAppServletContext class and it's execute(...) method the interceptor is hooking to find out the type of the method arguments. Also, your webLogicHttpFiveHundred() implementation looks exactly the same as the one in StandardHostValveInvokeInterceptor. You'll have to modify your code to have it work with WebLogic.

ing-arriola commented 6 years ago

Hi @Xylus

I'll work on it and I'll share what you do. By the way, the method you mention, I only copy it from the Tomcat class since I have not yet understood how everything works, but I am working on that in order to correctly write the method for WebLogic as you say it.

Thank you very much

ing-arriola commented 6 years ago

Hi @Xylus

In the research I have done, I have found that in the case Tomcat import org.apache.catalina.connector.Response; I found the information about the Tomcat class in: http://www.docjar.com/html/api/org/apache/catalina/connector/Response.java.html

For WebLogic It should be replaced with: import weblogic.servlet.internal.servletresponseimpl; I found the information about the WebLogic class in: http://www.docjar.com/html/api/weblogic/servlet/internal/ServletResponseImpl.java.html since both classes implement HttpServletResponse also in the IDE that I am using (InteliJ) tells me that he can not solve the servletresponseimpl symbol I understand that MAVEN takes care of that when he compiles PinPoint. On the other hand I'm still researching about WebAppServletContext

Thanks & Regards

ing-arriola commented 6 years ago

Hi @Xylus

I have been looking for two days for information about how this works: WebAppServletContext class and it's execute (...) method But I have not found anything, I really do not know what this information would be for me but I have searched for it following your recommendation since you have usually given me good ideas but I do not know if I could expand a bit more on this. On the other hand I have also read information about the BCI in order to understand more deeply what we are looking to achieve with WebLogic. The closest inofrmacion I have found is this: https://fossies.org/dox/apache-lenya-2.0.4-src/namespaceweblogic_1_1servlet_1_1internal.html

Another doubt dear friend is that I can not understand well what should be the content of the webLogicHttpFiveHundred () method.

I hope you can help me so that PinPoint has this important support for WebLogic. By the way I've been researching the pull request and I have to tell you that I did not know much about GIT but I'm also in the process of understanding that to be able to participate in the community more actively sharing the functionality for the JSP that you have helped me before to develop.

Probably the help I need you will say that part of the approach could be part of what these posts are made for but I would like you to see it from the perspective that my desire is to have a better functionality in PinPoint that would be a benefit for me but also for the community putting the resources that I have for it that are two redhat servers and our time. If I could continue counting on your help, I promise to share the progress i have. In fact as you can see maybe this is the issue that has more comments (37). All this I mention in order to show my interest in PinPoint and also to solve some problems I have with http500 errors. In a few words dear friend we all win by having this functionality developed.

PS: I share what I have:

ServletStubImplInterceptor.zip

PS2:

I have found this: II. The WebLogic internal servlets WebLogic uses several internal HTTP servlets to support the various types of web-related functionality. These servlets are registered in the weblogic.properties file. WebLogic does not publish their classdocs as part of the public API, but a description of each HTTP servlet is provided in the Setting WebLogic Properties document under Registering the WebLogic servlets. You can call upon these servlets from an HTTP client, and can integrate their features into your web based applications.

At: https://docs.oracle.com/cd/E13222_01/wls/docs/classdocs/API_servlet.html

Thanks & Regards

Xylus commented 6 years ago

Hi @ing-arriola Perhaps giving the Plugin Developer Guide will help if you haven't given it a read yet. It'll give you a better picture on how everything works in regards to tracing. Once you have the basic idea of how pinpoint plugins work, everything inside the WebLogic plugin will be much easier to digest.

Regarding WebAppServletContext, you can decompile the class file packaged inside WebLogic jar file to take a look at it's source code. The version I've used for this is *wls1213_dev_update3 and WebAppServletContext* class file was in wlserver/server/lib/weblogic-classes/weblogic/servlet/internal* directory.

Ankcy commented 6 years ago

I don't know why nothing data in hbase of table(ApplicationMapStatisticsCallee_Ver2、ApplicationMapStatisticsCaller_Ver2、ApplicationMapStatisticsSelf_Ver2) when the collector had get the log below:

2018-05-31 11:07:09 [DEBUG](c.n.p.c.h.SpanHandler :76 ) Received SPAN=TSpan(agentId:forfirstag, applicationName:firstappn, agentStartTime:1527785686715, transactionId:00 01 BB 8D FE B8 BB 2C 16, spanId:-5624968436172721513, startTime:1527786428838, elapsed:2, rpc:/test_linux/controlador.jsp, serviceType:1070, endPoint:172.23.112.192:7004, remoteAddr:172.23.112.192, flag:0, err:0, spanEventList:[TSpanEvent(sequence:0, startElapsed:1, endElapsed:1, serviceType:1071, annotations:[TAnnotation(key:41, value:)], depth:1, apiId:1)], apiId:-2, applicationServiceType:1070, loggingTransactionInfo:0) 2018-05-31 11:07:09 DEBUG [Caller] firstappn (USER) forfirstag -> firstappn (WEBLOGIC)[forfirstag] 2018-05-31 11:07:09 DEBUG [Callee] firstappn (WEBLOGIC) <- firstappn (USER)[forfirstag] 2018-05-31 11:07:09 DEBUG [Received] firstappn (WEBLOGIC)[forfirstag] 2018-05-31 11:07:09 [DEBUG](c.n.p.c.h.SpanHandler :165) handle spanEvent size:1 2018-05-31 11:07:10 DEBUG flush HbaseMapStatisticsCallerDao to [ApplicationMapStatisticsCallee_Ver2] Increment:1 2018-05-31 11:07:10 DEBUG flush HbaseMapStatisticsCalleeDao to [ApplicationMapStatisticsCaller_Ver2] Increment:1 2018-05-31 11:07:10 DEBUG flush HbaseMapResponseTimeDao to [ApplicationMapStatisticsSelf_Ver2] Increment:1

Xylus commented 6 years ago

Hi @Ankcy Please create a new issue according to the issue template so we can further investigate your issue (please make it as detailed as possible, collector/web logs would be helpful).

ing-arriola commented 6 years ago

Hi @Xylus

Okay, I will study the information and I hope to share the achievements that I have.

Thanks & Regards!!