misc: add log mecanism for cron jobs (#57604)

This commit is contained in:
Lauréline Guérin 2021-10-11 15:15:57 +02:00
parent 759df9acfc
commit fd12e0cb51
No known key found for this signature in database
GPG Key ID: 1FAB9B9B4F93D473
3 changed files with 105 additions and 6 deletions

View File

@ -16,6 +16,7 @@ from django.core.management import call_command
from django.core.management.base import CommandError
from django.http import Http404
from django.test import override_settings
from django.utils.timezone import localtime
from quixote import cleanup
from wcs.qommon import get_publisher_class
@ -206,8 +207,22 @@ def test_import_config_zip():
assert pub.cfg['sp'] == {'what': 'ever'}
def test_cron_command():
def test_cron_command(settings):
pub = create_temporary_pub()
def clear_log_file():
now = localtime()
with open(os.path.join(pub.APP_DIR, 'cron.log-%s' % now.strftime('%Y%m%d')), 'w'):
pass
def get_logs():
now = localtime()
with open(os.path.join(pub.APP_DIR, 'cron.log-%s' % now.strftime('%Y%m%d'))) as fd:
lines = fd.readlines()
lines = [line[33:].strip() for line in lines] # 33 chars for date & time
return lines
offset = ord(settings.SECRET_KEY[-1]) % 60
with mock.patch('tempfile.gettempdir') as gettempdir:
gettempdir.side_effect = lambda: pub.app_dir
@ -221,11 +236,23 @@ def test_cron_command():
mock_tenants.return_value = [
Tenant(os.path.join(pub.app_dir, x)) for x in ('example.net', 'foo.bar', 'something.com')
]
clear_log_file()
call_command('cron')
assert cron_worker.call_count == 3
assert get_logs() == [
'starting cron (minutes offset is %s)' % offset,
'[tenant example.net] start',
'[tenant foo.bar] start',
'[tenant something.com] start',
]
cron_worker.reset_mock()
clear_log_file()
call_command('cron', domain='example.net')
assert cron_worker.call_count == 1
assert get_logs() == [
'starting cron (minutes offset is %s)' % offset,
'[tenant example.net] start',
]
cron_worker.reset_mock()
# disable cron on something.com
@ -238,8 +265,14 @@ def test_cron_command():
'''
)
clear_log_file()
call_command('cron')
assert cron_worker.call_count == 2
assert get_logs() == [
'starting cron (minutes offset is %s)' % offset,
'[tenant example.net] start',
'[tenant foo.bar] start',
]
cron_worker.reset_mock()
os.unlink(site_options_path)
@ -283,14 +316,17 @@ def test_cron_command():
# run a specific job
jobs = []
def job1(pub):
def job1(pub, job=None):
jobs.append('job1')
def job2(pub):
def job2(pub, job=None):
jobs.append('job2')
def job3(pub):
def job3(pub, job=None):
jobs.append('job3')
for key in ['foo', 'bar', 'blah']:
with job.log_long_job(key):
pass
@classmethod
def register_test_cronjobs(cls):
@ -303,8 +339,38 @@ def test_cron_command():
call_command('cron', job_name='job1', domain='example.net')
assert jobs == []
get_publisher_class().cronjobs = []
clear_log_file()
call_command('cron', job_name='job2', domain='example.net')
assert jobs == ['job2']
assert get_logs() == [
'starting cron (minutes offset is %s)' % offset,
'[tenant example.net] start',
]
get_publisher_class().cronjobs = []
jobs = []
clear_log_file()
with mock.patch('wcs.qommon.cron.CronJob.LONG_JOB_DURATION', 0):
call_command('cron', job_name='job2', domain='example.net')
assert get_logs() == [
'starting cron (minutes offset is %s)' % offset,
'[tenant example.net] start',
'[tenant example.net] long job: job2 (took 0 minutes)',
]
assert jobs == ['job2']
get_publisher_class().cronjobs = []
jobs = []
clear_log_file()
with mock.patch('wcs.qommon.cron.CronJob.LONG_JOB_DURATION', 0):
call_command('cron', job_name='job3', domain='example.net')
assert get_logs() == [
'starting cron (minutes offset is %s)' % offset,
'[tenant example.net] start',
'[tenant example.net] job3: running on "foo" took 0 minutes',
'[tenant example.net] job3: running on "bar" took 0 minutes',
'[tenant example.net] job3: running on "blah" took 0 minutes',
'[tenant example.net] long job: job3 (took 0 minutes)',
]
assert jobs == ['job3']
def test_clean_afterjobs():

View File

@ -14,7 +14,13 @@
# You should have received a copy of the GNU General Public License
# along with this program; if not, see <http://www.gnu.org/licenses/>.
import os
from contextlib import contextmanager
from time import perf_counter
from django.conf import settings
from django.utils.timezone import localtime
from quixote import get_publisher
class CronJob:
@ -25,6 +31,8 @@ class CronJob:
days = None
function = None
LONG_JOB_DURATION = 2 * 60 # 2 minutes
def __init__(self, function, name=None, hours=None, minutes=None, weekdays=None, days=None):
self.function = function
self.name = name
@ -33,6 +41,27 @@ class CronJob:
self.weekdays = weekdays
self.days = days
@contextmanager
def log_long_job(self, obj_description=None):
start = perf_counter()
yield
duration = perf_counter() - start
if duration > self.LONG_JOB_DURATION:
minutes = int(duration / 60)
if obj_description:
self.log('%s: running on "%s" took %d minutes' % (self.name, obj_description, minutes))
else:
self.log('long job: %s (took %s minutes)' % (self.name, minutes))
@staticmethod
def log(message, with_tenant=True):
tenant_prefix = ''
now = localtime()
if with_tenant:
tenant_prefix = '[tenant %s] ' % get_publisher().tenant.hostname
with open(os.path.join(get_publisher().APP_DIR, 'cron.log-%s' % now.strftime('%Y%m%d')), 'a+') as fd:
fd.write('%s %s%s\n' % (now.isoformat(), tenant_prefix, message))
def cron_worker(publisher, now, job_name=None):
# reindex user and formdata if needed (should only be run once)
@ -66,6 +95,7 @@ def cron_worker(publisher, now, job_name=None):
for extra_source in publisher.extra_sources:
publisher.substitutions.feed(extra_source(publisher, None))
try:
job.function(publisher)
with job.log_long_job():
job.function(publisher, job=job)
except Exception as e:
publisher.record_error(exception=e, context='[CRON]', notify=True)

View File

@ -21,7 +21,7 @@ import time
from django.conf import settings
from django.core.management.base import BaseCommand, CommandError
from wcs.qommon.cron import cron_worker
from wcs.qommon.cron import CronJob, cron_worker
from wcs.qommon.publisher import get_publisher_class
from wcs.qommon.vendor import locket
from wcs.wf.jump import JUMP_TIMEOUT_INTERVAL
@ -59,6 +59,8 @@ class Command(BaseCommand):
publisher_class = get_publisher_class()
publisher_class.register_cronjobs()
publisher = publisher_class.create_publisher()
offset = ord(settings.SECRET_KEY[-1]) % 60
CronJob.log('starting cron (minutes offset is %s)' % offset, with_tenant=False)
for hostname in domains:
publisher.set_tenant_by_hostname(hostname)
if publisher.get_site_option('disable_cron_jobs', 'variables'):
@ -67,6 +69,7 @@ class Command(BaseCommand):
continue
if verbosity > 1:
print('cron work on %s' % hostname)
CronJob.log('start')
cron_worker(publisher, now, job_name=options.get('job_name'))
if verbosity > 2:
print('cron end (release lock %s)' % lockfile)