0

I have my doubts that this problem is actually caused by my Drupal configuration, but am wondering if anyone else has experienced a similar issue and how they went (or would go about) troubleshooting it.

I am running a production environment with:

  • Drupal 8.6.12
  • Apache/2.4.6 (CentOS) OpenSSL/1.0.2k-fips
  • PHP/7.1.28
  • memory limit 1028M
  • 5.5.60-MariaDB
  • MySQL, MariaDB, Percona Server, or equivalent.

A staging environment on a different machine with the same code base runs (mostly the same):

  • Drupal 8.6.12
  • Apache/2.4.6 (CentOS) OpenSSL/1.0.2k-fips mod_fcgid/2.3.9
  • PHP/7.1.27
  • memory limit 1028M
  • 5.5.60-MariaDB
  • MySQL, MariaDB, Percona Server, or equivalent.

I have a cron job that is scheduled (using Crontab scheduling) to run every Sunday at 5 PM EST using Ultimate Cron, scheduled for 0 17 * * 0.

CentOS crontab attempts to run behind-schedule Drupal cron tasks every 15 minutes:

*/15 * * * * wget https://<site domain>/cron/<cron token> --delete-after

About a month ago, this particular cron task started executing multiple times overnight, but only completing on the final attempt. The task sends four e-mails. It has been sending the first e-mail on every execution attempt (13-14 times), but the final three e-mails only upon final completion (once).

The production server takes a full code and DB backup of the site at 1 am. The cron task first tries to run at 5 PM (determined by the timestamp of the sent email), and then tries again at around 6 pm, 7:30 pm, 8:30 pm, etc etc, about every 1-2 hours (always at 0, 15, 30, or 45 minutes past the hour, which makes sense as those times match the contents of my centOS crontab), until it finally finishes at around 7-8 am the next day. I took the 1 am DB backup (at a time when the task had not yet successfully completed, and would not on its next attempt either) and replaced the staging site's database with it. In Configuration > System > Cron, there was no record on Drupal's behalf of this task ever having run. Drupal states the task was last run a week prior, so this suggests to me that PHP is exiting completely and Drupal has no chance to log an error message. This seems to explain why it is trying to run multiple times, as if Drupal has no recollection of the task ever having run, it will see the task as being behind schedule and try to run it next time crontab issues wget on the site's cron URL. (However that doesn't explain why it only seems to happen once an hour at most, when crontab checks every 15 minutes.)

I am wondering, firstly, if there is anything I can do to get around that and have Drupal record when such a thing happens, but I suspect not as it is happening at the PHP process level. (I do not believe it is caused by exceeding the memory_limit property in php.ini, as I've seen that problem before and Drupal would say so in the cron logs if the task had exited for that reason.)

This also suggests to me that the cron is failing to continue running sometime between the first and second e-mail, which makes sense as during this part of the code a very taxing and complicated SQL query is run on the user tables (selects users with a particular role meeting a complicated condition, which then takes loops through the retrieved entity IDs, loads the user, changes a field value, changes the user's role, and then saves the user), but for whatever reason is succeeding the 14th time. However, according to my database timestamps, the part of the code that updates the user field value and then saves the user is completing on the second or third cron run attempt, so past that it seems that it is just running the query and returning no results (which also makes sense, as the query selects for a particular role, and is changing the role of the users it finds, so there would be no users returned once they've all been converted).

The code for this cron task has not changed since October. I am unsure what could have happened.

In my Apache logs, I was seeing several error messages like the following:

Sun Apr 14 18:18:27 2019 (1893): Error Cannot kill process 1169: Success!
[Sun Apr 14 18:18:27.170950 2019] [core:notice] [pid 6755] AH00052: child pid 1893 exit signal Segmentation fault (11)

These error messages were only appearing around the times the cron task was executing. However, looking at the timestamps of the e-mails sent by the cron task, some of them do not have a matching error message in the apache error log.

This error message is bizarre, but it was suggested to me that this is caused by a PHP bug and that I should change my configuration to use php-fpm and the event MPM, which I did on Friday. However, the problem persisted. It is no longer logging segfaults, but now has logged zend_mm_heap corrupted two times with no timestamp, where I can see from the task's sent emails that it attempted to run 14 times.

The PHP error logs from the site contain no information related to the task exiting.

I have tried simply letting the cron run on the staging environment like the production environment, but it executes correctly with no exits, and never takes longer than ten minutes.

I am at a loss, and wondering if anyone else has experienced a similar issue with Drupal cron jobs, and may have any further recommendations for troubleshooting.

  • 1
    And triggering the cron with Drush? $ drush cron. Or from Drupal's UI? Is it the same? – leymannx Apr 22 at 19:52
  • 1
    Don't rely on e-mails for timestamp. You could have a a false positive. It could be e-mail sender is failing for x reason rather than cron. Use \Drupal::logger('my_module')->notice($message); then check the /admin/reports/dblog the next day to tell whether it's cron's or e-mail sender's fault. – No Sssweat Apr 23 at 3:36
  • You could attach that logger to hook_mail_alter if you didn't write the e-mail sender code. – No Sssweat Apr 23 at 5:04
  • I haven't triggered this cron from Drupal's UI on production, but on staging it showed no difference in runtime. I am using hook_mail. – saramm1 Apr 23 at 13:18
  • 1
    Approx how many e-mails are suppose to be sent? – No Sssweat Apr 24 at 11:46

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.