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

sbhakta99 · 2024-02-16T17:24:32Z

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 [email protected]/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 [email protected]/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 · 2024-02-16T18:55:30Z

Investigating and will update via support case

sbhakta99 · 2024-02-16T18:58:28Z

Investigating and will update via support case

Thank you appreciate it.

sbhakta99 · 2024-02-16T21:10:59Z

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 · 2024-02-16T22:21:51Z

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 · 2024-02-16T22:53:59Z

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 <#20 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ACDKAS4OC2RZ5F5ITLHV5LLYT7LYVAVCNFSM6AAAAABDMMJVXKVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSNBZGQYTONZWGI> . You are receiving this because you commented.Message ID: ***@***.*** com>

sbhakta99 added the bug Something isn't working label Feb 16, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

sbhakta99 commented Feb 16, 2024 •

edited

Loading

dhilpipre commented Feb 16, 2024

sbhakta99 commented Feb 16, 2024

sbhakta99 commented Feb 16, 2024

sbhakta99 commented Feb 16, 2024 •

edited

Loading

dhilpipre commented Feb 16, 2024 via email

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

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

Comments

sbhakta99 commented Feb 16, 2024 • edited Loading

Description

Steps to Reproduce

Example of NULL

Expected Behavior

Relevant Logs / Console output

Your Environment

Additional context

dhilpipre commented Feb 16, 2024

sbhakta99 commented Feb 16, 2024

sbhakta99 commented Feb 16, 2024

sbhakta99 commented Feb 16, 2024 • edited Loading

dhilpipre commented Feb 16, 2024 via email

sbhakta99 commented Feb 16, 2024 •

edited

Loading

sbhakta99 commented Feb 16, 2024 •

edited

Loading