0001-misc-add-log-mecanism-for-cron-jobs-57604.patch
tests/settings.py | ||
---|---|---|
1 | 1 |
TIME_ZONE = 'Europe/Paris' |
2 | 2 |
LANGUAGE_CODE = 'en-us' |
3 | 3 |
ALLOWED_HOSTS = ['*'] |
4 |
CRON_LOG_FILENAME = '/var/lib/wcs/cron-test.log' |
tests/test_publisher.py | ||
---|---|---|
206 | 206 |
assert pub.cfg['sp'] == {'what': 'ever'} |
207 | 207 | |
208 | 208 | |
209 |
def test_cron_command(): |
|
209 |
def test_cron_command(settings): |
|
210 |
def clear_log_file(): |
|
211 |
utcnow = datetime.datetime.utcnow() |
|
212 |
with open('%s-%s' % (settings.CRON_LOG_FILENAME, utcnow.strftime('%Y%m%d')), 'w'): |
|
213 |
pass |
|
214 | ||
215 |
def get_logs(): |
|
216 |
utcnow = datetime.datetime.utcnow() |
|
217 |
with open('%s-%s' % (settings.CRON_LOG_FILENAME, utcnow.strftime('%Y%m%d'))) as fd: |
|
218 |
lines = fd.readlines() |
|
219 |
lines = [line[27:].strip() for line in lines] # 27 chars for date & time |
|
220 |
return lines |
|
221 | ||
222 |
offset = ord(settings.SECRET_KEY[-1]) % 60 |
|
210 | 223 |
pub = create_temporary_pub() |
211 | 224 |
with mock.patch('tempfile.gettempdir') as gettempdir: |
212 | 225 |
gettempdir.side_effect = lambda: pub.app_dir |
... | ... | |
221 | 234 |
mock_tenants.return_value = [ |
222 | 235 |
Tenant(os.path.join(pub.app_dir, x)) for x in ('example.net', 'foo.bar', 'something.com') |
223 | 236 |
] |
237 |
clear_log_file() |
|
224 | 238 |
call_command('cron') |
225 | 239 |
assert cron_worker.call_count == 3 |
240 |
assert get_logs() == [ |
|
241 |
'starting cron (minutes offset is %s)' % offset, |
|
242 |
'[tenant example.net] start', |
|
243 |
'[tenant foo.bar] start', |
|
244 |
'[tenant something.com] start', |
|
245 |
] |
|
226 | 246 |
cron_worker.reset_mock() |
247 |
clear_log_file() |
|
227 | 248 |
call_command('cron', domain='example.net') |
228 | 249 |
assert cron_worker.call_count == 1 |
250 |
assert get_logs() == [ |
|
251 |
'starting cron (minutes offset is %s)' % offset, |
|
252 |
'[tenant example.net] start', |
|
253 |
] |
|
229 | 254 |
cron_worker.reset_mock() |
230 | 255 | |
231 | 256 |
# disable cron on something.com |
... | ... | |
238 | 263 |
''' |
239 | 264 |
) |
240 | 265 | |
266 |
clear_log_file() |
|
241 | 267 |
call_command('cron') |
242 | 268 |
assert cron_worker.call_count == 2 |
269 |
assert get_logs() == [ |
|
270 |
'starting cron (minutes offset is %s)' % offset, |
|
271 |
'[tenant example.net] start', |
|
272 |
'[tenant foo.bar] start', |
|
273 |
] |
|
243 | 274 |
cron_worker.reset_mock() |
244 | 275 |
os.unlink(site_options_path) |
245 | 276 | |
... | ... | |
289 | 320 |
def job2(pub): |
290 | 321 |
jobs.append('job2') |
291 | 322 | |
292 |
def job3(pub): |
|
323 |
def job3(pub, job):
|
|
293 | 324 |
jobs.append('job3') |
325 |
for key in ['foo', 'bar', 'blah']: |
|
326 |
with job.log_long_job(key): |
|
327 |
pass |
|
294 | 328 | |
295 | 329 |
@classmethod |
296 | 330 |
def register_test_cronjobs(cls): |
... | ... | |
303 | 337 |
call_command('cron', job_name='job1', domain='example.net') |
304 | 338 |
assert jobs == [] |
305 | 339 |
get_publisher_class().cronjobs = [] |
340 |
clear_log_file() |
|
306 | 341 |
call_command('cron', job_name='job2', domain='example.net') |
307 | 342 |
assert jobs == ['job2'] |
343 |
assert get_logs() == [ |
|
344 |
'starting cron (minutes offset is %s)' % offset, |
|
345 |
'[tenant example.net] start', |
|
346 |
] |
|
347 |
get_publisher_class().cronjobs = [] |
|
348 |
jobs = [] |
|
349 |
clear_log_file() |
|
350 |
with mock.patch('wcs.qommon.cron.CronJob.LONG_JOB_DURATION', 0): |
|
351 |
call_command('cron', job_name='job2', domain='example.net') |
|
352 |
assert get_logs() == [ |
|
353 |
'starting cron (minutes offset is %s)' % offset, |
|
354 |
'[tenant example.net] start', |
|
355 |
'[tenant example.net] long job: job2 (took 0 minutes)', |
|
356 |
] |
|
357 |
assert jobs == ['job2'] |
|
358 |
get_publisher_class().cronjobs = [] |
|
359 |
jobs = [] |
|
360 |
clear_log_file() |
|
361 |
with mock.patch('wcs.qommon.cron.CronJob.LONG_JOB_DURATION', 0): |
|
362 |
call_command('cron', job_name='job3', domain='example.net') |
|
363 |
assert get_logs() == [ |
|
364 |
'starting cron (minutes offset is %s)' % offset, |
|
365 |
'[tenant example.net] start', |
|
366 |
'[tenant example.net] job3: running on "foo" took 0 minutes', |
|
367 |
'[tenant example.net] job3: running on "bar" took 0 minutes', |
|
368 |
'[tenant example.net] job3: running on "blah" took 0 minutes', |
|
369 |
'[tenant example.net] long job: job3 (took 0 minutes)', |
|
370 |
] |
|
371 |
assert jobs == ['job3'] |
|
308 | 372 | |
309 | 373 | |
310 | 374 |
def test_clean_afterjobs(): |
wcs/qommon/cron.py | ||
---|---|---|
14 | 14 |
# You should have received a copy of the GNU General Public License |
15 | 15 |
# along with this program; if not, see <http://www.gnu.org/licenses/>. |
16 | 16 | |
17 |
import datetime |
|
18 |
import inspect |
|
19 |
from contextlib import contextmanager |
|
20 |
from time import perf_counter |
|
21 | ||
17 | 22 |
from django.conf import settings |
23 |
from quixote import get_publisher |
|
18 | 24 | |
19 | 25 | |
20 | 26 |
class CronJob: |
... | ... | |
25 | 31 |
days = None |
26 | 32 |
function = None |
27 | 33 | |
34 |
LONG_JOB_DURATION = 2 * 60 # 2 minutes |
|
35 | ||
28 | 36 |
def __init__(self, function, name=None, hours=None, minutes=None, weekdays=None, days=None): |
29 | 37 |
self.function = function |
30 | 38 |
self.name = name |
... | ... | |
33 | 41 |
self.weekdays = weekdays |
34 | 42 |
self.days = days |
35 | 43 | |
44 |
@contextmanager |
|
45 |
def log_long_job(self, obj_description=None): |
|
46 |
start = perf_counter() |
|
47 |
yield |
|
48 |
duration = perf_counter() - start |
|
49 |
if duration > self.LONG_JOB_DURATION: |
|
50 |
minutes = int(duration / 60) |
|
51 |
if obj_description: |
|
52 |
self.log('%s: running on "%s" took %d minutes' % (self.name, obj_description, minutes)) |
|
53 |
else: |
|
54 |
self.log('long job: %s (took %s minutes)' % (self.name, minutes)) |
|
55 | ||
56 |
@staticmethod |
|
57 |
def log(message, with_tenant=True): |
|
58 |
utcnow = datetime.datetime.utcnow() |
|
59 |
tenant_prefix = '' |
|
60 |
if with_tenant: |
|
61 |
tenant_prefix = '[tenant %s] ' % get_publisher().tenant.hostname |
|
62 |
with open('%s-%s' % (settings.CRON_LOG_FILENAME, utcnow.strftime('%Y%m%d')), 'a+') as fd: |
|
63 |
fd.write('%s %s%s\n' % (utcnow.isoformat(), tenant_prefix, message)) |
|
64 | ||
36 | 65 | |
37 | 66 |
def cron_worker(publisher, now, job_name=None): |
38 | 67 |
# reindex user and formdata if needed (should only be run once) |
... | ... | |
66 | 95 |
for extra_source in publisher.extra_sources: |
67 | 96 |
publisher.substitutions.feed(extra_source(publisher, None)) |
68 | 97 |
try: |
69 |
job.function(publisher) |
|
98 |
with job.log_long_job(): |
|
99 |
if 'job' in inspect.getfullargspec(job.function).args: |
|
100 |
job.function(publisher, job=job) |
|
101 |
else: |
|
102 |
job.function(publisher) |
|
70 | 103 |
except Exception as e: |
71 | 104 |
publisher.record_error(exception=e, context='[CRON]', notify=True) |
wcs/qommon/management/commands/cron.py | ||
---|---|---|
21 | 21 |
from django.conf import settings |
22 | 22 |
from django.core.management.base import BaseCommand, CommandError |
23 | 23 | |
24 |
from wcs.qommon.cron import cron_worker |
|
24 |
from wcs.qommon.cron import CronJob, cron_worker
|
|
25 | 25 |
from wcs.qommon.publisher import get_publisher_class |
26 | 26 |
from wcs.qommon.vendor import locket |
27 | 27 |
from wcs.wf.jump import JUMP_TIMEOUT_INTERVAL |
... | ... | |
46 | 46 |
if verbosity > 1: |
47 | 47 |
print('Command is ignored because DISABLE_CRON_JOBS is set in settings') |
48 | 48 |
return |
49 |
offset = ord(settings.SECRET_KEY[-1]) % 60 |
|
50 |
CronJob.log('starting cron (minutes offset is %s)' % offset, with_tenant=False) |
|
49 | 51 |
lockfile = os.path.join(tempfile.gettempdir(), 'wcs-cron-in-progress.lock') |
50 | 52 |
if options.get('domain'): |
51 | 53 |
domains = [options.get('domain')] |
... | ... | |
67 | 69 |
continue |
68 | 70 |
if verbosity > 1: |
69 | 71 |
print('cron work on %s' % hostname) |
72 |
CronJob.log('start') |
|
70 | 73 |
cron_worker(publisher, now, job_name=options.get('job_name')) |
71 | 74 |
if verbosity > 2: |
72 | 75 |
print('cron end (release lock %s)' % lockfile) |
wcs/settings.py | ||
---|---|---|
191 | 191 |
# components, one should disable cron jobs execution on secondary servers; |
192 | 192 |
# set the following variable True disables "cron" management command |
193 | 193 |
DISABLE_CRON_JOBS = False |
194 |
CRON_LOG_FILENAME = '/var/lib/wcs/cron.log' |
|
194 | 195 | |
195 | 196 |
# w.c.s. can have very large forms, in backoffice and frontoffice |
196 | 197 |
DATA_UPLOAD_MAX_NUMBER_FIELDS = 2000 # Django default is 1000 |
197 |
- |