Projet

Général

Profil

0001-misc-add-log-mecanism-for-cron-jobs-57604.patch

Lauréline Guérin, 21 octobre 2021 09:55

Télécharger (9,94 ko)

Voir les différences:

Subject: [PATCH 1/2] misc: add log mecanism for cron jobs (#57604)

 tests/settings.py                      |  1 +
 tests/test_publisher.py                | 68 +++++++++++++++++++++++++-
 wcs/qommon/cron.py                     | 35 ++++++++++++-
 wcs/qommon/management/commands/cron.py |  5 +-
 wcs/settings.py                        |  1 +
 5 files changed, 106 insertions(+), 4 deletions(-)
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
-