Synapse
  1. Synapse
  2. SYNAPSE-622

NPE in ClientConnectionDebug.java:36 when running in a failover scenario

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Critical Critical
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: NIGHTLY, 2.0, 3.0
    • Component/s: Core
    • Labels:
      None

      Description

      When I run sample #52 with one of the leaf endpoint being timeout, following NPE is thrown time to time. Once this is encountered that message is permanently lost. I'll upload a small patch which will fix the problem.

      1. SYNAPSE-622.patch
        1 kB
        Rajika Kumarasiri

        Activity

        Hide
        Rajika Kumarasiri added a comment -

        A possible patch to fix the problem.

        Show
        Rajika Kumarasiri added a comment - A possible patch to fix the problem.
        Hide
        Eric Hubert added a comment - - edited

        Just two small questions to think about before committing:
        1) Could this hide some other problem? Why is either the context not available or has no attribute with the connection creation time?
        2) Is the rest of the code just fine with an uninitilized connection creation time or could this lead to misleading/wrong output/calculations later on?

        Would be nice to have answers on both before committing the change although it is definitely correct to be defensive in this area as no runtime issue in this part should populate up the stack.
        If there would be more logic one could even get a step further and implement a fault barrier around the public interface which catches all exceptions and ensures that message processing will not be affected no matter what aspect fails within the connection (debug) tracing aspect.

        Show
        Eric Hubert added a comment - - edited Just two small questions to think about before committing: 1) Could this hide some other problem? Why is either the context not available or has no attribute with the connection creation time? 2) Is the rest of the code just fine with an uninitilized connection creation time or could this lead to misleading/wrong output/calculations later on? Would be nice to have answers on both before committing the change although it is definitely correct to be defensive in this area as no runtime issue in this part should populate up the stack. If there would be more logic one could even get a step further and implement a fault barrier around the public interface which catches all exceptions and ensures that message processing will not be affected no matter what aspect fails within the connection (debug) tracing aspect.
        Hide
        Rajika Kumarasiri added a comment -

        Sorry I missed the stack trace. Here it goes.

        [HttpClientWorker-8] INFO EndpointContext Endpoint :
        AnonymousEndpoint has been marked for SUSPENSION, but no further
        retries remain. Thus it will be SUSPENDED.
        2010-03-30 14:04:55,488 [127.0.1.1-evanthika-laptop]
        [HttpClientWorker-8] ERROR Axis2Sender Unexpected error during sending
        message out
        java.lang.NullPointerException
        at org.apache.synapse.transport.nhttp.ClientConnectionDebug.recordRequestStartTime(ClientConnectionDebug.java:36)
        at org.apache.synapse.transport.nhttp.HttpCoreNIOSender.sendAsyncRequest(HttpCoreNIOSender.java:387)
        at org.apache.synapse.transport.nhttp.HttpCoreNIOSender.invoke(HttpCoreNIOSender.java:295)
        at org.apache.axis2.engine.AxisEngine.send(AxisEngine.java:448)
        at org.apache.synapse.core.axis2.DynamicAxisOperation$DynamicOperationClient.send(DynamicAxisOperation.java:190)
        at org.apache.synapse.core.axis2.DynamicAxisOperation$DynamicOperationClient.executeImpl(DynamicAxisOperation.java:174)
        at org.apache.axis2.client.OperationClient.execute(OperationClient.java:163)
        at org.apache.synapse.core.axis2.Axis2FlexibleMEPClient.send(Axis2FlexibleMEPClient.java:304)
        at org.apache.synapse.core.axis2.Axis2Sender.sendOn(Axis2Sender.java:57)
        at org.apache.synapse.core.axis2.Axis2SynapseEnvironment.send(Axis2SynapseEnvironment.java:232)
        at org.apache.synapse.endpoints.AbstractEndpoint.send(AbstractEndpoint.java:205)
        at org.apache.synapse.endpoints.LoadbalanceEndpoint.send(LoadbalanceEndpoint.java:79)
        at org.apache.synapse.endpoints.LoadbalanceEndpoint.onChildEndpointFail(LoadbalanceEndpoint.java:123)
        at org.apache.synapse.endpoints.AbstractEndpoint.onFault(AbstractEndpoint.java:302)
        at org.apache.synapse.endpoints.AddressEndpoint.onFault(AddressEndpoint.java:50)
        at org.apache.synapse.FaultHandler.handleFault(FaultHandler.java:101)
        at org.apache.synapse.core.axis2.SynapseCallbackReceiver.handleMessage(SynapseCallbackReceiver.java:189)
        at org.apache.synapse.core.axis2.SynapseCallbackReceiver.receive(SynapseCallbackReceiver.java:131)
        at org.apache.synapse.transport.nhttp.ClientHandler$1.run(ClientHandler.java:435)
        at org.apache.synapse.transport.base.threads.NativeWorkerPool$1.run(NativeWorkerPool.java:58)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)

        Show
        Rajika Kumarasiri added a comment - Sorry I missed the stack trace. Here it goes. [HttpClientWorker-8] INFO EndpointContext Endpoint : AnonymousEndpoint has been marked for SUSPENSION, but no further retries remain. Thus it will be SUSPENDED. 2010-03-30 14:04:55,488 [127.0.1.1-evanthika-laptop] [HttpClientWorker-8] ERROR Axis2Sender Unexpected error during sending message out java.lang.NullPointerException at org.apache.synapse.transport.nhttp.ClientConnectionDebug.recordRequestStartTime(ClientConnectionDebug.java:36) at org.apache.synapse.transport.nhttp.HttpCoreNIOSender.sendAsyncRequest(HttpCoreNIOSender.java:387) at org.apache.synapse.transport.nhttp.HttpCoreNIOSender.invoke(HttpCoreNIOSender.java:295) at org.apache.axis2.engine.AxisEngine.send(AxisEngine.java:448) at org.apache.synapse.core.axis2.DynamicAxisOperation$DynamicOperationClient.send(DynamicAxisOperation.java:190) at org.apache.synapse.core.axis2.DynamicAxisOperation$DynamicOperationClient.executeImpl(DynamicAxisOperation.java:174) at org.apache.axis2.client.OperationClient.execute(OperationClient.java:163) at org.apache.synapse.core.axis2.Axis2FlexibleMEPClient.send(Axis2FlexibleMEPClient.java:304) at org.apache.synapse.core.axis2.Axis2Sender.sendOn(Axis2Sender.java:57) at org.apache.synapse.core.axis2.Axis2SynapseEnvironment.send(Axis2SynapseEnvironment.java:232) at org.apache.synapse.endpoints.AbstractEndpoint.send(AbstractEndpoint.java:205) at org.apache.synapse.endpoints.LoadbalanceEndpoint.send(LoadbalanceEndpoint.java:79) at org.apache.synapse.endpoints.LoadbalanceEndpoint.onChildEndpointFail(LoadbalanceEndpoint.java:123) at org.apache.synapse.endpoints.AbstractEndpoint.onFault(AbstractEndpoint.java:302) at org.apache.synapse.endpoints.AddressEndpoint.onFault(AddressEndpoint.java:50) at org.apache.synapse.FaultHandler.handleFault(FaultHandler.java:101) at org.apache.synapse.core.axis2.SynapseCallbackReceiver.handleMessage(SynapseCallbackReceiver.java:189) at org.apache.synapse.core.axis2.SynapseCallbackReceiver.receive(SynapseCallbackReceiver.java:131) at org.apache.synapse.transport.nhttp.ClientHandler$1.run(ClientHandler.java:435) at org.apache.synapse.transport.base.threads.NativeWorkerPool$1.run(NativeWorkerPool.java:58) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:619)
        Hide
        Rajika Kumarasiri added a comment -

        Eric,
        I agree with your two questions. We should really look why the conn or the context was null and the behaviour of the rest of the code in such situation. I'll invest some time on this and update this thread with the findings.

        Rajika

        Show
        Rajika Kumarasiri added a comment - Eric, I agree with your two questions. We should really look why the conn or the context was null and the behaviour of the rest of the code in such situation. I'll invest some time on this and update this thread with the findings. Rajika
        Hide
        Ruwan Linton added a comment -

        Hi Rajika,

        This is caused not because neither the connection nor the context was null, rather the respective attribute that we were looking for is null.

        Eric, you are absolutely correct, this could lead to wrong information on the connection debug log. Actual issue in this particular case is where we seem to miss to add the connection creation time in one of the flows. I came across a similar issue which I think is caused by this. We need to fix the root cause before applying this patch, yet it is important for this patch to be there.

        Thanks,
        Ruwan

        Show
        Ruwan Linton added a comment - Hi Rajika, This is caused not because neither the connection nor the context was null, rather the respective attribute that we were looking for is null. Eric, you are absolutely correct, this could lead to wrong information on the connection debug log. Actual issue in this particular case is where we seem to miss to add the connection creation time in one of the flows. I came across a similar issue which I think is caused by this. We need to fix the root cause before applying this patch, yet it is important for this patch to be there. Thanks, Ruwan
        Hide
        Ruwan Linton added a comment -

        The original issue has been fixed on the trunk and will be available on the 2.0 release

        Show
        Ruwan Linton added a comment - The original issue has been fixed on the trunk and will be available on the 2.0 release
        Hide
        Kasun Indrasiri added a comment -

        We came across this issue intermittently when timeouts occurs from the backend. Possible this is due to a typo in ClientHandler.

        ClinetHandler:
        -------------------
        public static final String CONNECTION_CREATION_TIME = "synapse.connectioCreationTime";
        ...
        this.connectionCreationTime = (Long) conn.getContext().getAttribute(
        ClientHandler.CONNECTION_CREATION_TIME);

        Server handler:
        ----------------------

        public static final String CONNECTION_CREATION_TIME = "synapse.connectionCreationTime";
        ...
        conn.getContext().setAttribute(CONNECTION_CREATION_TIME, System.currentTimeMillis());

        Show
        Kasun Indrasiri added a comment - We came across this issue intermittently when timeouts occurs from the backend. Possible this is due to a typo in ClientHandler. ClinetHandler: ------------------- public static final String CONNECTION_CREATION_TIME = "synapse.connectioCreationTime"; ... this.connectionCreationTime = (Long) conn.getContext().getAttribute( ClientHandler.CONNECTION_CREATION_TIME); Server handler: ---------------------- public static final String CONNECTION_CREATION_TIME = "synapse.connectionCreationTime"; ... conn.getContext().setAttribute(CONNECTION_CREATION_TIME, System.currentTimeMillis());
        Hide
        Hiranya Jayathilaka added a comment -

        I'm going to resolve this. Ruwan seems to have fixed the root cause and the typo Kasun has pointed out is fixed in the trunk. If anybody runs into this issue again, please reopen with a stacktrace and if possible a NHTTP debug log.

        Show
        Hiranya Jayathilaka added a comment - I'm going to resolve this. Ruwan seems to have fixed the root cause and the typo Kasun has pointed out is fixed in the trunk. If anybody runs into this issue again, please reopen with a stacktrace and if possible a NHTTP debug log.

          People

          • Assignee:
            Kasun Indrasiri
            Reporter:
            Rajika Kumarasiri
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development