Magento discards most New Relic cron transactions

[convenient]

Summary

Magento is discarding all new relic transaction logging/runtime information/errors for every cron job after the first one executed per process.

For example if you had three pending jobs job1, job2, and job3 you would only have a transaction for job1 and no info at all in new relic for job2 and job3.

This is a critical issue IMO as it reduces the effectiveness of our ability to support the Magento instance. I assumed I was getting all relevant data in new relic but I am actually missing performance analytics as well as possible errors that are not being tracked in new relic. This affected me debugging downtime issues affecting a website.

Cause

This issue was introduced in 2.4.0 by 5819ded

In that commit there were attempts to

1. stop logging the cron:run command as a command (the isCommandSkipped logic)
2. set the transaction name for each pending job processed in the queue.

The current implementation works a bit like so, starting at Magento\Cron\Observer\ProcessCronQueueObserver::execute

magento2/app/code/Magento/Cron/Observer/ProcessCronQueueObserver.php

Line 273 in 4c36116

$this->processPendingJobs($groupId, $jobsRoot, $currentTime);

calls

magento2/app/code/Magento/Cron/Observer/ProcessCronQueueObserver.php

Line 825 in 4c36116

$this->tryRunJob($scheduledTime, $currentTime, $jobConfig, $schedule, $groupId);

calls

magento2/app/code/Magento/Cron/Observer/ProcessCronQueueObserver.php

Line 858 in 4c36116

$this->_runJob($scheduledTime, $currentTime, $jobConfig, $schedule, $groupId);

This is the part of the process that actually executes the job, it does so like this

magento2/app/code/Magento/Cron/Observer/ProcessCronQueueObserver.php

Lines 350 to 377 in 4c36116

	$this->startProfiling($jobCode);
	$this->eventManager->dispatch('cron_job_run', ['job_name' => 'cron/' . $groupId . '/' . $jobCode]);
	try {
	$this->logger->info(sprintf('Cron Job %s is run', $jobCode));
	//phpcs:ignore Magento2.Functions.DiscouragedFunction
	call_user_func_array($callback, [$schedule]);
	} catch (\Throwable $e) {
	$schedule->setStatus(Schedule::STATUS_ERROR);
	$this->logger->error(
	sprintf(
	'Cron Job %s has an error: %s. Statistics: %s',
	$jobCode,
	$e->getMessage(),
	$this->getProfilingStat($jobCode)
	)
	);
	if (!$e instanceof \Exception) {
	$e = new \RuntimeException(
	'Error when running a cron job',
	0,
	$e
	);
	}
	throw $e;
	} finally {
	$this->stopProfiling($jobCode);
	}

You can see that each execution of a job is wrapped with startProfiling and stopProfiling.

These functions have plugins in them to set newrelic_name_transaction and newrelic_end_transaction

magento2/app/code/Magento/NewRelicReporting/Plugin/StatPlugin.php

Lines 62 to 73 in 4c36116

	public function beforeStart(Stat $schedule, ...$args): array
	{
	$timerName = current($args);
	if ($this->isCronJob($timerName)) {
	$this->newRelicWrapper->setTransactionName(
	sprintf('Cron %s', $timerName)
	);
	}
	return $args;
	}

magento2/app/code/Magento/NewRelicReporting/Plugin/StatPlugin.php

Lines 84 to 93 in 4c36116

	public function beforeStop(Stat $schedule, ...$args): array
	{
	$timerName = current($args);
	if ($this->isCronJob($timerName)) {
	$this->newRelicWrapper->endTransaction();
	}
	return $args;
	}

The issue is that we call newrelic_end_transaction but nowhere in the codebase is there another call to newrelic_start_transaction, this is required to track subsequent jobs.

For task queue managers, you can use newrelic_end_transaction() and newrelic_start_transaction() together to manually separate transactions

• https://docs.newrelic.com/docs/agents/php-agent/php-agent-api/newrelic_start_transaction/#stop-and-start

This is the major bug, without this call to restart the transaction all subsequent data is not tracked and reported to New Relic.

There is a second quality of life issue. Due to the location where we set the initial transaction name we end up with two traces per cron execution, one of them is flagged as unknown which encompasses everything up until we call newrelic_name_transaction for the first time, so basically when you see unknown on the CLI New Relic data you can think of it as "the time it takes to boot up cron:run and get to the point where you run the first actual job".

In effect what we have is the following

<?php
sleep(10); // cron:run loader
foreach ($i=1; $i<=3; $i++) {
    newrelic_name_transaction("job$i");
    sleep(10);
    newrelic_end_transaction();
}

Results

• unknown transaction containing the booting of cron:run
• job1 transaction only

When we need something like

<?php
newrelic_name_transaction("cron:run loader");
sleep(10); // cron:run loader
newrelic_end_transaction();
newrelic_start_transaction(ini_get("newrelic.appname"));
foreach ($i=1; $i<=3; $i++) {
    newrelic_name_transaction("job$i");
    sleep(10);
    newrelic_end_transaction();
    newrelic_start_transaction(ini_get("newrelic.appname"));
}

Results

• cron:run loader transaction containing the booting of cron:run
• job1 transaction
• job2 transaction
• job3 transaction

Hotfix

For anyone looking for an urgent patch to get their crons all properly logged in New Relic the following seems to be working for me. This ensures we always have a transaction running until this process terminates.

--- Model/NewRelicWrapper.php	2021-01-07 21:56:58.000000000 +0000
+++ Model/NewRelicWrapper.php	2021-09-17 09:11:31.000000000 +0100
@@ -79,6 +79,7 @@
     {
         if ($this->isExtensionInstalled()) {
             newrelic_end_transaction($ignore);
+            newrelic_start_transaction(ini_get("newrelic.appname"));
         }
     }

Proper solution

I have some rough ideas but I'll leave this for someone in Magento to pick up. I cant see any trivial way of doing what I propose as we'd need to couple the Cron module to New Relic reporting module a bit tighter.

Firstly we can give the cron:run its old transaction name back by removing this.

magento2/app/code/Magento/NewRelicReporting/etc/di.xml

Lines 49 to 55 in 5819ded

	<type name="Magento\NewRelicReporting\Plugin\CommandPlugin">
	<arguments>
	<argument name="skipCommands" xsi:type="array">
	<item xsi:type="boolean" name="cron:run">true</item>
	</argument>
	</arguments>
	</type>

Then before we call startProfiling in ProcessCronQueueObserver.php we need to end the current new relic transaction, then start a new one.

It would also feel weird for NewRelicWrapper::endTransaction to have the responsibility of newrelic_start_transaction, but I wonder whether adding a new NewRelicWrapper::startTransaction would break backwards compatibility if its a new public method 🤔 But the breakage here is so severe that it makes the cron data for new relic practically without use so something needs to be addressed here.

---

Please provide Severity assessment for the Issue as Reporter. This information will help during Confirmation and Issue triage processes.

• Severity: S0 - Affects critical data or functionality and leaves users without workaround.
• Severity: S1 - Affects critical data or functionality and forces users to employ a workaround.
• Severity: S2 - Affects non-critical data or functionality and forces users to employ a workaround.
• Severity: S3 - Affects non-critical data or functionality and does not force users to employ a workaround.
• Severity: S4 - Affects aesthetics, professional look and feel, “quality” or “usability”.

[m2-assistant]

Hi @convenient. Thank you for your report.
To help us process this issue please make sure that you provided the following information:

• Summary of the issue
• Information on your environment
• Steps to reproduce
• Expected and actual results

Please make sure that the issue is reproducible on the vanilla Magento instance following Steps to reproduce. To deploy vanilla Magento instance on our environment, please, add a comment to the issue:

@magento give me 2.4-develop instance - upcoming 2.4.x release

For more details, please, review the Magento Contributor Assistant documentation.

Please, add a comment to assign the issue: @magento I am working on this

---

• Join Magento Community Engineering Slack and ask your questions in #github channel.

⚠️ According to the Magento Contribution requirements, all issues must go through the Community Contributions Triage process. Community Contributions Triage is a public meeting.

🕙 You can find the schedule on the Magento Community Calendar page.

📞 The triage of issues happens in the queue order. If you want to speed up the delivery of your contribution, please join the Community Contributions Triage session to discuss the appropriate ticket.

🎥 You can find the recording of the previous Community Contributions Triage on the Magento Youtube Channel

✏️ Feel free to post questions/proposals/feedback related to the Community Contributions Triage process to the corresponding Slack Channel

[m2-assistant]

Hi @ddzhura. Thank you for working on this issue.
In order to make sure that issue has enough information and ready for development, please read and check the following instruction: 👇

• 1. Verify that issue has all the required information. (Preconditions, Steps to reproduce, Expected result, Actual result).
     Details

     If the issue has a valid description, the label Issue: Format is valid will be added to the issue automatically. Please, edit issue description if needed, until label Issue: Format is valid appears.
• 2. Verify that issue has a meaningful description and provides enough information to reproduce the issue. If the report is valid, add Issue: Clear Description label to the issue by yourself.
• 3. Add Component: XXXXX label(s) to the ticket, indicating the components it may be related to.
• 4. Verify that the issue is reproducible on 2.4-develop branch
     Details

     - Add the comment @magento give me 2.4-develop instance to deploy test instance on Magento infrastructure.
     - If the issue is reproducible on 2.4-develop branch, please, add the label Reproduced on 2.4.x.
     - If the issue is not reproducible, add your comment that issue is not reproducible and close the issue and stop verification process here!

---

• Join Magento Community Engineering Slack and ask your questions in #github channel.

[m2-assistant]

Hi @maghamed. Thank you for working on this issue.
In order to make sure that issue has enough information and ready for development, please read and check the following instruction: 👇

• 1. Verify that issue has all the required information. (Preconditions, Steps to reproduce, Expected result, Actual result).
     Details

     If the issue has a valid description, the label Issue: Format is valid will be added to the issue automatically. Please, edit issue description if needed, until label Issue: Format is valid appears.
• 2. Verify that issue has a meaningful description and provides enough information to reproduce the issue. If the report is valid, add Issue: Clear Description label to the issue by yourself.
• 3. Add Component: XXXXX label(s) to the ticket, indicating the components it may be related to.
• 4. Verify that the issue is reproducible on 2.4-develop branch
     Details

     - Add the comment @magento give me 2.4-develop instance to deploy test instance on Magento infrastructure.
     - If the issue is reproducible on 2.4-develop branch, please, add the label Reproduced on 2.4.x.
     - If the issue is not reproducible, add your comment that issue is not reproducible and close the issue and stop verification process here!

---

• Join Magento Community Engineering Slack and ask your questions in #github channel.

[m2-assistant]

Hi @kandy. Thank you for working on this issue.
In order to make sure that issue has enough information and ready for development, please read and check the following instruction: 👇

• 1. Verify that issue has all the required information. (Preconditions, Steps to reproduce, Expected result, Actual result).
     Details

     If the issue has a valid description, the label Issue: Format is valid will be added to the issue automatically. Please, edit issue description if needed, until label Issue: Format is valid appears.
• 2. Verify that issue has a meaningful description and provides enough information to reproduce the issue. If the report is valid, add Issue: Clear Description label to the issue by yourself.
• 3. Add Component: XXXXX label(s) to the ticket, indicating the components it may be related to.
• 4. Verify that the issue is reproducible on 2.4-develop branch
     Details

     - Add the comment @magento give me 2.4-develop instance to deploy test instance on Magento infrastructure.
     - If the issue is reproducible on 2.4-develop branch, please, add the label Reproduced on 2.4.x.
     - If the issue is not reproducible, add your comment that issue is not reproducible and close the issue and stop verification process here!

---

• Join Magento Community Engineering Slack and ask your questions in #github channel.

[m2-assistant]

Hi @engcom-Hotel. Thank you for working on this issue.
In order to make sure that issue has enough information and ready for development, please read and check the following instruction: 👇

• 1. Verify that issue has all the required information. (Preconditions, Steps to reproduce, Expected result, Actual result).

  Details

  If the issue has a valid description, the label Issue: Format is valid will be added to the issue automatically. Please, edit issue description if needed, until label Issue: Format is valid appears.

• 2. Verify that issue has a meaningful description and provides enough information to reproduce the issue. If the report is valid, add Issue: Clear Description label to the issue by yourself.

• 3. Add Component: XXXXX label(s) to the ticket, indicating the components it may be related to.

• 4. Verify that the issue is reproducible on 2.4-develop branch

  Details

  - Add the comment @magento give me 2.4-develop instance to deploy test instance on Magento infrastructure.
  - If the issue is reproducible on 2.4-develop branch, please, add the label Reproduced on 2.4.x.
  - If the issue is not reproducible, add your comment that issue is not reproducible and close the issue and stop verification process here!

• 5. Add label Issue: Confirmed once verification is complete.

• 6. Make sure that automatic system confirms that report has been added to the backlog.

[engcom-Hotel]

Hello @convenient,

Are you still facing the issue?

Can you please tell us some more information on this issue like:

• Information on your environment
• Steps to reproduce
• Expected and actual results

Thanks

[convenient]

@engcom-Hotel this is not environment specific, any 2.4 Magento installation with New Relic should do it

The steps to reproduce and the expected and actual are already in the description.

If you are not familiar with New Relic this may need escalated internally your side.