Variables are printing 'null' with New Relic 8.9.0 enabled on Mulesoft Runtime 4.5.x & 4.6.x version

sbhakta99 commented 8 months ago

New Relic Support Case #00187431

Description

After upgrading to Mule 4.5.x & 4.6.x Runtime version and adding New Relic to the Wrapper.conf file, we encountered an issue where our application variables were becoming null. Upon contacting Mule support, we were advised to comment out the New Relic Jar, after which the application variables started working normally again. It appears that there is some interaction between New Relic and MuleSoft Runtime which is causing instability in our applications.

It New Relic Enabled works fine with 4.4.x Mulesoft Versions

Steps to Reproduce

Example of NULL

{"customerNumber":vars.lw9399res.customerNumber default 0, "divisionNumber":vars.lw9399res.divisionNumber default 0, "responseCode":payload.responseCode, "productListCount":vars.lwreq.productListCount default 0, "consumerId":vars.lwPriceReqHeader.consumerId, "subConsumerId":vars.lwPriceReqHeader.subConsumerId, "roundedProductCount":(ceil((vars.lwReq.productListCount default 0)/'${roundedProductCount}')) * 50, "allVariables": vars, "lw9399res": vars.lw9399res

}

Response: { "customerNumber": 0, "divisionNumber": 0, "responseCode": 9398, "productListCount": 0, "consumerId": null, "subConsumerId": null, "roundedProductCount": 0, "allVariables": { "exceptionFlag": "true" }, "lw9399res": null }

Expected Behavior

Example when New Relic is DISABLED on 4.5.x & 4.6.x

{ "customerNumber": 14374680, "divisionNumber": 1933, "responseCode": null, "productListCount": 1, "consumerId": "mule-test", "subConsumerId": "mule-test", "roundedProductCount": 50, "allVariables": { "lw9399res": { "divisionNumber": 1933, "customerNumber": 14374680, "priceSourceFlag": "Y", "priceRecommendationFlag": "Y", "gaurdrailsFlag": "Y", "costBasisDetailsFlag": "Y", "lastWeekPriceFlag": "Y", "pricingDateTime": "2024-02-15T15:21:00", "lastWeekPriceDateTime": "2023-12-18T07:03:00", "productListCount": 1, "productList": [ { "productNumber": 9449588, "sequenceNumber": 1 } ] }, "lwPriceReqHeader": { "consumerId": "mule-test", "subConsumerId": "mule-test", "transactionId": "Mule-fdc45378-dfb1-448f-ae39-b48af3eebf42", "correlationId": "1234444", "timeZone": "America/Chicago" }, "reqCheck": { "levsLWFlag": "Y", "lwDuration": "N", "levsFlag": "N", "reqDuration": "N" }, "outboundHeaders": { }, "lwReq": { "divisionNumber": 1933, "customerNumber": 14374680, "priceSourceFlag": "Y", "priceRecommendationFlag": "Y", "gaurdrailsFlag": "Y", "costBasisDetailsFlag": "Y", "lastWeekPriceFlag": "Y", "pricingDateTime": "2024-02-15T15:21:00", "lastWeekPriceDateTime": "2023-12-18T07:03:00", "productListCount": 1, "productList": [ { "productNumber": 9449588, "sequenceNumber": 1 } ] }, "apiStartTime": "2024-02-16T11:09:36.129-06:00" }, "lw9399res": { "divisionNumber": 1933, "customerNumber": 14374680, "priceSourceFlag": "Y", "priceRecommendationFlag": "Y", "gaurdrailsFlag": "Y", "costBasisDetailsFlag": "Y", "lastWeekPriceFlag": "Y", "pricingDateTime": "2024-02-15T15:21:00", "lastWeekPriceDateTime": "2023-12-18T07:03:00", "productListCount": 1, "productList": [ { "productNumber": 9449588, "sequenceNumber": 1 } ] } }

Relevant Logs / Console output

Your Environment

ALL ENVIRONMENTS

ex: Browser name and version:
ex: Operating System and version:

Additional context

Logs from newrelic_agent.log

2024-02-15T15:09:35,242-0600 [30379 133] com.newrelic INFO: Using default collector host: collector.newrelic.com 2024-02-15T15:09:35,242-0600 [30379 133] com.newrelic INFO: Using default metric ingest URI: https://metric-api.newrelic.com/metric/v1 2024-02-15T15:09:35,242-0600 [30379 133] com.newrelic INFO: Using default event ingest URI: https://insights-collector.newrelic.com/v1/accounts/events 2024-02-15T15:09:35,244-0600 [30379 133] com.newrelic INFO: Using default collector host: collector.newrelic.com 2024-02-15T15:09:35,244-0600 [30379 133] com.newrelic INFO: Using default metric ingest URI: https://metric-api.newrelic.com/metric/v1 2024-02-15T15:09:35,244-0600 [30379 133] com.newrelic INFO: Using default event ingest URI: https://insights-collector.newrelic.com/v1/accounts/events 2024-02-15T15:12:37,477-0600 [30379 193] com.newrelic INFO: Setting audit_mode to false 2024-02-15T15:12:37,478-0600 [30379 34] com.newrelic INFO: Host name is 1plsrmulas08.main.usfood.com, display host 1plsrmulas08.main.usfood.com for application null-sample 2024-02-15T15:12:37,478-0600 [30379 34] com.newrelic INFO: New Relic JFR Monitor is disabled: JFR config has not been enabled in the Java agent. 2024-02-15T15:12:38,077-0600 [30379 34] com.newrelic INFO: Collector redirection to collector.newrelic.com:443 2024-02-15T15:12:38,353-0600 [30379 34] com.newrelic INFO: Max payload size is 1,000,000 bytes 2024-02-15T15:12:38,353-0600 [30379 34] com.newrelic INFO: Agent run id: BclUHQHn2d5KAAb_qSEaP_Zlzn6YAAIBAAAnIQEAAHarAgQhGiq5AwAFOC45LjAAHDFwbHNybXVsYXMwOC5tYWluLnVzZm9vZC5jb20AC251bGwtc2FtcGxl 2024-02-15T15:12:38,353-0600 [30379 34] com.newrelic INFO: Agent 30379@1plsrmulas08.main.usfood.com/null-sample connected to collector.newrelic.com:443 2024-02-15T15:12:38,353-0600 [30379 34] com.newrelic INFO: Reporting to: https://rpm.newrelic.com/accounts/458665/applications/555363001 2024-02-15T15:12:38,354-0600 [30379 34] com.newrelic INFO: Using default collector host: collector.newrelic.com 2024-02-15T15:12:38,354-0600 [30379 34] com.newrelic INFO: Using default metric ingest URI: https://metric-api.newrelic.com/metric/v1 2024-02-15T15:12:38,354-0600 [30379 34] com.newrelic INFO: Using default event ingest URI: https://insights-collector.newrelic.com/v1/accounts/events 2024-02-15T15:12:38,355-0600 [30379 34] com.newrelic INFO: Using default collector host: collector.newrelic.com 2024-02-15T15:12:38,355-0600 [30379 34] com.newrelic INFO: Using default metric ingest URI: https://metric-api.newrelic.com/metric/v1 2024-02-15T15:12:38,355-0600 [30379 34] com.newrelic INFO: Using default event ingest URI: https://insights-collector.newrelic.com/v1/accounts/events 2024-02-15T15:12:38,357-0600 [30379 34] com.newrelic INFO: Real user monitoring is enabled for application null-sample. Auto instrumentation is enabled. 2024-02-15T15:15:35,347-0600 [30379 194] com.newrelic INFO: Remote get_agent_commands call failed : javax.net.ssl.SSLException: Connection reset. 2024-02-15T15:16:08,371-0600 [30379 194] com.newrelic INFO: Remote get_agent_commands call failed : javax.net.ssl.SSLException: Connection reset. 2024-02-15T15:20:08,370-0600 [30379 194] com.newrelic INFO: Remote get_agent_commands call failed : javax.net.ssl.SSLException: Connection reset. 2024-02-15T15:29:02,150-0600 [30379 195] com.newrelic INFO: Remote span_event_data call failed : javax.net.ssl.SSLException: Connection reset. 2024-02-15T15:29:35,348-0600 [30379 194] com.newrelic INFO: Remote get_agent_commands call failed : javax.net.ssl.SSLException: Connection reset. 2024-02-15T15:44:32,150-0600 [30379 194] com.newrelic INFO: Remote get_agent_commands call failed : javax.net.ssl.SSLException: Connection reset. 2024-02-15T15:44:57,282-0600 [30379 195] com.newrelic INFO: Remote analytic_event_data call failed : javax.net.ssl.SSLException: Connection reset. 2024-02-15T15:45:52,281-0600 [30379 195] com.newrelic INFO: Remote analytic_event_data call failed : javax.net.ssl.SSLException: Connection reset. 2024-02-15T15:48:32,368-0600 [30379 194] com.newrelic INFO: Remote metric_data call failed : com.newrelic.agent.ForceRestartException: . 2024-02-15T15:48:32,368-0600 [30379 194] com.newrelic WARN: Received a ForceRestartException: com.newrelic.agent.ForceRestartException: . The agent will attempt to reconnect for data reporting. If this message continues, please contact support via https://support.newrelic.com/. 2024-02-15T15:48:32,643-0600 [30379 194] com.newrelic INFO: Host name is 1plsrmulas08.main.usfood.com, display host 1plsrmulas08.main.usfood.com for application mule-sit 2024-02-15T15:48:32,644-0600 [30379 194] com.newrelic INFO: New Relic JFR Monitor is disabled: JFR config has not been enabled in the Java agent. 2024-02-15T15:48:33,224-0600 [30379 194] com.newrelic INFO: Collector redirection to collector.newrelic.com:443 2024-02-15T15:48:33,458-0600 [30379 194] com.newrelic INFO: Max payload size is 1,000,000 bytes 2024-02-15T15:48:33,458-0600 [30379 194] com.newrelic INFO: Agent run id: BXaRTJnZrSuEAAb_qSDgeGtlzocIAAIBAAAnIQEAAHarAgQg4BXpAwAFOC45LjAAHDFwbHNybXVsYXMwOC5tYWluLnVzZm9vZC5jb20ACG11bGUtc2l0 2024-02-15T15:48:33,458-0600 [30379 194] com.newrelic INFO: Agent 30379@1plsrmulas08.main.usfood.com/mule-sit connected to collector.newrelic.com:443 2024-02-15T15:48:33,458-0600 [30379 194] com.newrelic INFO: Reporting to: https://rpm.newrelic.com/accounts/458665/applications/551556585 2024-02-15T15:48:33,459-0600 [30379 194] com.newrelic INFO: Using default collector host: collector.newrelic.com 2024-02-15T15:48:33,459-0600 [30379 194] com.newrelic INFO: Using default metric ingest URI: https://metric-api.newrelic.com/metric/v1 2024-02-15T15:48:33,459-0600 [30379 194] com.newrelic INFO: Using default event ingest URI: https://insights-collector.newrelic.com/v1/accounts/events 2024-02-15T15:48:33,461-0600 [30379 194] com.newrelic INFO: Using default collector host: collector.newrelic.com 2024-02-15T15:48:33,461-0600 [30379 194] com.newrelic INFO: Using default metric ingest URI: https://metric-api.newrelic.com/metric/v1 2024-02-15T15:48:33,461-0600 [30379 194] com.newrelic INFO: Using default event ingest URI: https://insights-collector.newrelic.com/v1/accounts/events 2024-02-15T15:48:33,464-0600 [30379 194] com.newrelic INFO: Real user monitoring is enabled for application mule-sit. Auto instrumentation is enabled. 2024-02-15T16:01:28,479-0600 [30379 195] com.newrelic INFO: Remote analytic_event_data call failed : javax.net.ssl.SSLException: Connection reset.

dhilpipre commented 8 months ago

Investigating and will update via support case

sbhakta99 commented 8 months ago

Investigating and will update via support case

Thank you appreciate it.

sbhakta99 commented 8 months ago

Investigating and will update via support case

Response from support, did you want me to proceed with this, I would assume that all instrumentation for mule would not work if we disable correct?

It sounds to me like something our agent is doing is interacting negatively with your application. There are only a few places where our agent directly interacts with your application in a way that could potentially break something. We do the following:

We add headers to HTTP requests as part of our Distributed Tracing product.
We inject our Page Load Timing scripts into JSPs compiled with Jasper, as part of our automatic Browser instrumentation.
We wrap various classes in your code base using bytecode injection.

These features of the agent can be selectively disabled.

To disable our Distributed Tracing feature, pass the following in your newrelic.yml file:

distributed_tracing: enabled: false

To disable our Browser injection feature, pass the following in your newrelic.yml file:

browser_monitoring: auto_instrument: false

To disable class transformation, pass the following in your newrelic.yml file:

class_transformer: enabled: false

I would recommend selectively disabling these features to see which one changes the symptoms. This is by way of a troubleshooting step, not a final resolution. If we can narrow down the precise feature of the agent that is triggering this behavior, then I believe we can implement a workaround.

sbhakta99 commented 8 months ago

I did the additional mentioned on 4.6 Mule Runtime with New Relic Java Agent 8.9.0

-Removed extensions folder from New Relic Install and Mule API works fine, NO NULL ISSUE -Put the jars that begin with Mule-Core-xxxx.jar back into the extensions directory and restarted works fine, NO NULL ISSUE

So it is something from the addtional Mulesoft New Relic Instrumentation Jars, we also would need 4.6 Core

https://github.com/newrelic-experimental/newrelic-java-mule-4/releases/tag/v3.1.3

dhilpipre commented 8 months ago

okay, thanks for the update. No time to look into it further today and New Relic is off Monday for President's Day, so I will look into it Tuesday.

For now, run with the agent the core jar files and I'll let you know which ones to try next

Doug Hilpipre Senior Principal Solution Architect, Programmability New Relic Labs New Relic @.*** 763-228-5460 - mobile 415-233-9346 - office

On Fri, Feb 16, 2024 at 4:22 PM Suba @.***> wrote:

I did the additional mentioned on 4.6 Mule Runtime with New Relic Java Agent 8.9.0

-Removed extensions folder from New Relic Install and Mule API works fine, NO NULL ISSUE -Put the jars that begin with Mule-Core-xxxx.jar back into the extensions directory and restarted works fine, NO NULL ISSUE

So it is something from the addtional Mulesoft New Relic Instrumentation Jars

https://github.com/newrelic-experimental/newrelic-java-mule-4/releases/tag/v3.1.3

— Reply to this email directly, view it on GitHub https://github.com/newrelic-experimental/newrelic-java-mule-4/issues/20#issuecomment-1949417762, or unsubscribe https://github.com/notifications/unsubscribe-auth/ACDKAS4OC2RZ5F5ITLHV5LLYT7LYVAVCNFSM6AAAAABDMMJVXKVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSNBZGQYTONZWGI . You are receiving this because you commented.Message ID: @.*** com>

newrelic-experimental / newrelic-java-mule-4