Issue with multiple mule applications

[krishnaprasadhg]

Hello,

We have multiple mule applications. Mule application & APM works fine with security policies are disabled. The issue is mule applications stops working when we enable client id enforcement security policies.

We tested with APM agent v 1.18.0/1.17.0.

Thanks

[michaelhyatt]

Hi Krishna. Are you using Mule domain to deploy multiple applications?

…

On Wed, 16 Sep 2020 at 13:16, krishnaprasadhg ***@***.***> wrote: Hello, We have multiple mule applications. Mule application & APM works fine when the APM+dependent jars are configured at application level. However this increases Mule application jar by ~15 MB. Increase in Mule application jars causes low memory issues. So we placed the APM +dependent jars in the mule host level. The issue we encountered is the very 1st mule application works fine, remaining mule applications not able to get any API/http calls. Thanks — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#9>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ADXR5DKO7Z5ALXPO6K67AVTSGAUYLANCNFSM4ROEH2SA> .

[krishnaprasadhg]

Hi Michael,

Yes. We are using mule domain.

Thanks

[manishgcjain]

Michael,
There are multple projects which are under 1 common domain so we cant apply domain-tracer approach their as it would then group all APM under that domain .
so we are following tracer.xml approach .
Manish

[michaelhyatt]

sorry for the delay, I was busy with my day job :) Will have a look at it today.

…

On Fri, 18 Sep 2020 at 22:56, Manish Jain ***@***.***> wrote: Michael, There are multple projects which are under 1 common domain so we cant apply domain-tracer approach their as it would then group all APM under that domain . so we are following tracer.xml approach . Manish — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#9 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ADXR5DJH5N6RVP5M25TWUMTSGNKGTANCNFSM4ROEH2SA> .

[michaelhyatt]

Hi @manishgcjain and @krishnaprasadhg,

I created a test project that also uses API autodiscovery (attached) and Mule 4.3.0. I then pushed a client.id enforcement policy and created an application that allowed the request to go through:

➜  stack-docker curl -v --basic --user 2afa4df8242c4341806f0951b6f4d7a3:e964FeADfB894c35a953b53A242f9600 http://localhost:8081
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 8081 (#0)
* Server auth using Basic with user '2afa4df8242c4341806f0951b6f4d7a3'
> GET / HTTP/1.1
> Host: localhost:8081
> Authorization: Basic MmFmYTRkZjgyNDJjNDM0MTgwNmYwOTUxYjZmNGQ3YTM6ZTk2NEZlQURmQjg5NGMzNWE5NTNiNTNBMjQyZjk2MDA=
> User-Agent: curl/7.64.1
> Accept: */*
> 
< HTTP/1.1 401 Unauthorized
* Authentication problem. Ignoring this.
< www-authenticate: Basic realm="mule-realm"
< Content-Type: application/json; charset=UTF-8
< Content-Length: 31
< Date: Thu, 24 Sep 2020 01:50:48 GMT
< 
{
  "error": "Invalid Client"
* Connection #0 to host localhost left intact
}* Closing connection 0
➜  stack-docker curl -v --basic --user c6677a797a64409dbd6507f0393759b:6625d30dc204EF3aE9ca2cE7F81dA38 http://localhost:8081
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 8081 (#0)
* Server auth using Basic with user 'c6677a797a64409dbd6507f03937599b'
> GET / HTTP/1.1
> Host: localhost:8081
> Authorization: Basic YzY2NzdhNzk3YTY0NDA5ZGJkNjUwN2YwMzkzNzUOWI6NjYyNWQzODBkYzIwNEVGM2FFOWNhMmNFN0Y4MWRBMzg=
> User-Agent: curl/7.64.1
> Accept: */*
> 
< HTTP/1.1 200 OK
< Content-Length: 18
< Date: Thu, 24 Sep 2020 02:00:14 GMT
< 
* Connection #0 to host localhost left intact
{ "result": "ok" }* Closing connection 0

I was able to see an APM transaction created for the successful call to the flow, but the one where the policy blocked the execution due to the invalid client-id the flow wasn't invoked. In the flow itself, I am tracking the start and finish of the flow execution, but with APM policy violation the flow is not being invoked at all. Is this the problem you are experiencing?

I wanted to ask your help to get Mulesoft to update their documentation and publish the specs for their event APIs the same way they did for Mule 3. Mule 4 has been around for a while, but their documentation is inadequate, for example the page with Javadoc points still at 4.1.1 and I had no luck trying to contact them to do something about it. Voeful lack of documentation and open community (Stack Overflow or even Mulesoft own forums) made me stop developing the agent for Mule 4, so if you can help me to get Mulesoft to lift up their game with the documentation, I am happy to continue making enhancements.

Javadoc:
https://docs.mulesoft.com/mule-runtime/4.3/mule-4-api-javadoc
test-policies-1.zip

[michaelhyatt]

I can also invoke the application multiple times with the policy succeeding and it seems to work ok. See below 7 successful calls. Do you know which policy you are using that causes the problem?

My API definition is:

{"api":{"$self":{"name":"v1:16383844","groupId":"a1cb42d2-1a95-4d63-bdc9-4ea2b5ad0e35","assetId":"test-api-1","assetVersion":"1.0.0","productVersion":"v1","description":null,"tags":[],"order":1,"providerId":null,"deprecated":false,"endpointUri":null,"instanceLabel":null}},"endpoint":{"$self":{"type":"http","uri":null,"proxyUri":null,"isCloudHub":null,"deploymentType":"CH","policiesVersion":null,"referencesUserDomain":null,"responseTimeout":null,"muleVersion4OrAbove":true}},"policyConfigurations":[{"$self":{"policyTemplateId":"299240","groupId":"68ef9520-24e9-4cf2-b2f5-620025690913","assetId":"client-id-enforcement","assetVersion":"1.2.2","configurationData":{"credentialsOriginHasHttpBasicAuthenticationHeader":"httpBasicAuthenticationHeader","clientIdExpression":"#[attributes.headers['client_id']]"},"pointcutData":null,"disabled":false,"order":1}}]}

[AlanElliottMAG]

Hi Michael,

I have also been having issues when API Auto-discovery is enabled. I've raised a ticket with Mulesoft asking them to update their documentation for https://docs.mulesoft.com/mule-runtime/4.3/mule-4-api-javadoc. If there is anything else that would help to progress this, please let me know.

Thanks,

Alan

[AlanElliottMAG]

Hi,

I have had a response from Mulesoft stating:

The documentation for 4.3.0 can be found at:
https://www.mulesoft.org/docs/site/4.3.0/apidocs/

However we are ware that the title of the documentation is wrong as it states:
pom-javadoc 4.2.0-SNAPSHOT API

Hope this helps.

Thanks,

Alan

[akhilpathak26]

Hi Michael,

I am facing issue intermittently with APM, it is working fine if we are adding the mule-agent in a first place means while building a mule application from scratch. But, if we are adding the mule-agent in an existing mule application then it is throwing 500 connection close error.

To make work APM changes in existing application if we remove the application instance from API Manager and deploy the application in Runtime Manager and after the successful deployment again manage the application in API Manager it is working fine.

[michaelhyatt]

Hi Akhil. Can you send me the error that Mule is throwing when 500 error occurs? Hopefully, it logs an exception when it happens.

[michaelhyatt]

Also, what policies are you using? I am trying to figure out if one of them can be causing an issue.

[akhilpathak26]

Hi Michael,

getting below error, it is not logging any error in mule_ee as well as mule application logs.
HTTP/1.1 500 Server Error
Transfer-Encoding: chunked
Date: Fri, 09 Oct 2020 05:01:39 GMT
Connection: close

following policies are applied on APIs -

1. Client Id enforcement.
2. JSON Threat.
3. Rate Limiting.
4. JWT token. (in fewAPIs)
   5 HTTP Caching. (in fewAPIs)

[michaelhyatt]

Can you please set the elastic.apm.log_level=INFO and increase the Mule log level verbosity for org.mule and com.mulesoft loggers to see if there is anything useful being logged that can give a bit more details about the error?

Another thing, I tried to run some load testing on my end to try and reproduce the failure and the only thing I could achieve was saturating the internal reporter queue for the APM agent due to too many messages needing to be sent to the APM server. Just to test this further, can you please increase the size and the number of instances of the APM server?

This is the error I saw in my logs:

2020-10-09 16:59:38,602 [elastic-apm-server-reporter] ERROR co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Error sending data to APM server: Server returned HTTP response code: 503 for URL: http://localhost:8200/intake/v2/events, response code is 503
2020-10-09 16:59:38,603 [elastic-apm-server-reporter] WARN  co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - {
  "accepted": 110,
  "errors": [
    {
      "message": "queue is full"
    }
  ]
}

[michaelhyatt]

Also, to debug it further, can you please ask Mulesoft support to get you the exact exception that Mule policy throws when the API consumers see the 500 error?

[AlanElliottMAG]

Hi Michael,

I wasn't getting any messages back other than the 500 Server Error when the APM log level was set to INFO. I ran the application in Debug mode in Anypoint Studio and set the log level to Debug. Anypoint Studio gave the following message:

java.lang.RuntimeException: java.util.NoSuchElementException: Context does not contain key: policy.nextOperation

The logs from APM in Debug are below:

2020-10-12 09:34:36.722 [http.listener.09 SelectorRunner] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation StartTransactionInstrumentation: (name(equals(co.elastic.apm.api.ElasticApm)) and not(isInterface())) matches class co.elastic.apm.api.ElasticApm
2020-10-12 09:34:36.722 [http.listener.09 SelectorRunner] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation StartTransactionWithRemoteParentInstrumentation: (name(equals(co.elastic.apm.api.ElasticApm)) and not(isInterface())) matches class co.elastic.apm.api.ElasticApm
2020-10-12 09:34:36.722 [http.listener.09 SelectorRunner] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation CurrentTransactionInstrumentation: (name(equals(co.elastic.apm.api.ElasticApm)) and not(isInterface())) matches class co.elastic.apm.api.ElasticApm
2020-10-12 09:34:36.722 [http.listener.09 SelectorRunner] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation CurrentSpanInstrumentation: (name(equals(co.elastic.apm.api.ElasticApm)) and not(isInterface())) matches class co.elastic.apm.api.ElasticApm
2020-10-12 09:34:36.723 [http.listener.09 SelectorRunner] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation CaptureExceptionInstrumentation: (name(equals(co.elastic.apm.api.ElasticApm)) and not(isInterface())) matches class co.elastic.apm.api.ElasticApm
2020-10-12 09:34:36.740 [http.listener.09 SelectorRunner] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation StartTransactionInstrumentation: name(equals(doStartTransaction)) matches private static java.lang.Object co.elastic.apm.api.ElasticApm.doStartTransaction()
2020-10-12 09:34:36.742 [http.listener.09 SelectorRunner] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation StartTransactionWithRemoteParentInstrumentation: name(equals(doStartTransactionWithRemoteParentFunction)) matches private static java.lang.Object co.elastic.apm.api.ElasticApm.doStartTransactionWithRemoteParentFunction(java.lang.invoke.MethodHandle,co.elastic.apm.api.HeaderExtractor,java.lang.invoke.MethodHandle,co.elastic.apm.api.HeadersExtractor)
2020-10-12 09:34:36.744 [http.listener.09 SelectorRunner] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation CurrentTransactionInstrumentation: name(equals(doGetCurrentTransaction)) matches private static java.lang.Object co.elastic.apm.api.ElasticApm.doGetCurrentTransaction()
2020-10-12 09:34:36.744 [http.listener.09 SelectorRunner] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation CurrentSpanInstrumentation: name(equals(doGetCurrentSpan)) matches private static java.lang.Object co.elastic.apm.api.ElasticApm.doGetCurrentSpan()
2020-10-12 09:34:36.745 [http.listener.09 SelectorRunner] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation CaptureExceptionInstrumentation: name(equals(captureException)) matches public static void co.elastic.apm.api.ElasticApm.captureException(java.lang.Throwable)
2020-10-12 09:34:36.749 [http.listener.09 SelectorRunner] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation CaptureExceptionInstrumentation: ((name(equals(co.elastic.apm.api.NoopTransaction)) or name(equals(co.elastic.apm.api.NoopSpan))) and not(isInterface())) matches class co.elastic.apm.api.NoopTransaction
2020-10-12 09:34:36.756 [http.listener.09 SelectorRunner] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation CaptureExceptionInstrumentation: (name(equals(captureException)) and hasParameter(hasTypes(erasures(containing(is(class java.lang.Throwable)))))) matches public java.lang.String co.elastic.apm.api.NoopTransaction.captureException(java.lang.Throwable)
2020-10-12 09:34:36.759 [http.listener.09 SelectorRunner] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Type match for instrumentation CaptureExceptionInstrumentation: ((name(equals(co.elastic.apm.api.NoopTransaction)) or name(equals(co.elastic.apm.api.NoopSpan))) and not(isInterface())) matches class co.elastic.apm.api.NoopSpan
2020-10-12 09:34:36.764 [http.listener.09 SelectorRunner] DEBUG co.elastic.apm.agent.bci.ElasticApmAgent - Method match for instrumentation CaptureExceptionInstrumentation: (name(equals(captureException)) and hasParameter(hasTypes(erasures(containing(is(class java.lang.Throwable)))))) matches public java.lang.String co.elastic.apm.api.NoopSpan.captureException(java.lang.Throwable)
2020-10-12 09:34:38.411 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Beginning scheduled configuration reload (interval is 30 sec)...
2020-10-12 09:34:38.411 [elastic-apm-configuration-reloader] DEBUG co.elastic.apm.agent.impl.ElasticApmTracerBuilder - Finished scheduled configuration reload
2020-10-12 09:34:38.452 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Receiving METRICS event (sequence 0)
2020-10-12 09:34:38.452 [elastic-apm-server-reporter] DEBUG co.elastic.apm.agent.report.IntakeV2ReportingEventHandler - Starting new request to https://.................................................apm.eu-west-1.aws.cloud.es.io:443/intake/v2/events
2020-10-12 09:34:38.860 [elastic-apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Reloading configuration from APM Server https://..................................................apm.eu-west-1.aws.cloud.es.io:443/config/v1/agents
2020-10-12 09:34:39.077 [elastic-apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Configuration did not change
2020-10-12 09:34:39.077 [elastic-apm-remote-config-poller] DEBUG co.elastic.apm.agent.configuration.ApmServerConfigurationSource - Scheduling next remote configuration reload in 30s