From c890ae6bbfdfd86952429628ec5556038838adaa Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Laura=20Kl=C3=BCnder?= Date: Thu, 16 Nov 2017 20:54:59 +0100 Subject: [PATCH] better logging in many places --- src/c3nav/mapdata/cache.py | 6 ++++ src/c3nav/mapdata/fields.py | 10 +++++++ .../management/commands/clearmapcache.py | 11 +++++++ .../management/commands/processupdates.py | 6 +++- src/c3nav/mapdata/models/geometry/level.py | 6 ++-- src/c3nav/mapdata/models/update.py | 30 ++++++++++++------- src/c3nav/mapdata/tasks.py | 14 +++++++-- src/c3nav/settings.py | 7 ++++- 8 files changed, 74 insertions(+), 16 deletions(-) diff --git a/src/c3nav/mapdata/cache.py b/src/c3nav/mapdata/cache.py index 1cd0a059..6ddbdfda 100644 --- a/src/c3nav/mapdata/cache.py +++ b/src/c3nav/mapdata/cache.py @@ -256,6 +256,12 @@ class GeometryChangeTracker: self._geometries_by_level = {} self._deleted_levels = set() + @property + def area(self): + return sum((unary_union(geometries).area + for level_id, geometries in self._geometries_by_level.items() + if level_id not in self._deleted_levels), 0) + def finalize(self): for level_id in self._deleted_levels: try: diff --git a/src/c3nav/mapdata/fields.py b/src/c3nav/mapdata/fields.py index a53c71fd..bbae0c17 100644 --- a/src/c3nav/mapdata/fields.py +++ b/src/c3nav/mapdata/fields.py @@ -1,4 +1,5 @@ import json +import logging import typing from django.core.exceptions import ValidationError @@ -15,6 +16,8 @@ from c3nav.mapdata.utils.json import format_geojson validate_bssid_lines = RegexValidator(regex=r'^([0-9a-f]{2}(:[0-9a-f]{2}){5}(\r?\n[0-9a-f]{2}(:[0-9a-f]{2}){5})*)?$', message=_('please enter a newline seperated lowercase list of BSSIDs')) +logger = logging.getLogger('c3nav') + def validate_geometry(geometry: BaseGeometry): if not isinstance(geometry, BaseGeometry): @@ -24,6 +27,9 @@ def validate_geometry(geometry: BaseGeometry): raise ValidationError('Invalid geometry: %s' % validation.explain_validity(geometry)) +shapely_logger = logging.getLogger('shapely.geos') + + class GeometryField(models.TextField): default_validators = [validate_geometry] @@ -77,13 +83,17 @@ class GeometryField(models.TextField): return None self._validate_geomtype(value, exception=TypeError) json_value = format_geojson(mapping(value)) + shapely_logger.setLevel('ERROR') rounded_value = shape(json_value) if not rounded_value.is_valid: + logging.debug('Rounded geometry is invalid, trying to fix this...') rounded_value = rounded_value.buffer(0) if not rounded_value.is_empty: json_value = format_geojson(mapping(rounded_value), round=False) else: + logging.debug('Fixing failed, saving it to the database without rounding.') json_value = format_geojson(mapping(value), round=False) + shapely_logger.setLevel('INFO') return json.dumps(json_value) def value_to_string(self, obj): diff --git a/src/c3nav/mapdata/management/commands/clearmapcache.py b/src/c3nav/mapdata/management/commands/clearmapcache.py index ad7ad61e..08ce65ef 100644 --- a/src/c3nav/mapdata/management/commands/clearmapcache.py +++ b/src/c3nav/mapdata/management/commands/clearmapcache.py @@ -1,3 +1,4 @@ +import logging import os from django.conf import settings @@ -14,12 +15,22 @@ class Command(BaseCommand): def handle(self, *args, **options): from c3nav.mapdata.models import MapUpdate + + logger = logging.getLogger('c3nav') + MapUpdate.objects.create(type='management') + logger.info('New management update created.') if options['include_history']: + logger.info('Deleting base history...') for filename in os.listdir(settings.CACHE_ROOT): if filename.startswith('level_') and '_history_' in filename: + logger.info('Deleting %s...' % filename) os.remove(os.path.join(settings.CACHE_ROOT, filename)) + logger.info('Base history deleted.') if not settings.HAS_REAL_CACHE: print(_('You have no external cache configured, so don\'t forget to restart your c3nav instance!')) + + if not settings.HAS_CELERY: + print(_('You don\'t have celery installed, so don\'t forget to call processupdates!')) diff --git a/src/c3nav/mapdata/management/commands/processupdates.py b/src/c3nav/mapdata/management/commands/processupdates.py index 02bea85e..b2cc9423 100644 --- a/src/c3nav/mapdata/management/commands/processupdates.py +++ b/src/c3nav/mapdata/management/commands/processupdates.py @@ -1,3 +1,5 @@ +import logging + from django.conf import settings from django.core.management.base import BaseCommand from django.db import DatabaseError @@ -10,10 +12,12 @@ class Command(BaseCommand): help = 'process unprocessed map updates' def handle(self, *args, **options): + logger = logging.getLogger('c3nav') + try: process_map_updates() except DatabaseError: - print(_('Error: There is already map update processing in progress.')) + logger.error(_('There is already map update processing in progress.')) if not settings.HAS_REAL_CACHE: print(_('You have no external cache configured, so don\'t forget to restart your c3nav instance!')) diff --git a/src/c3nav/mapdata/models/geometry/level.py b/src/c3nav/mapdata/models/geometry/level.py index faaae776..cd4b9f1b 100644 --- a/src/c3nav/mapdata/models/geometry/level.py +++ b/src/c3nav/mapdata/models/geometry/level.py @@ -1,3 +1,4 @@ +import logging from itertools import chain, combinations from operator import attrgetter, itemgetter @@ -483,5 +484,6 @@ class AltitudeArea(LevelGeometryMixin, models.Model): num_created += 1 areas[tmpid].save() - print(_('%d altitude areas built.') % len(areas)) - print(_('%d modified, %d deleted, %d created.') % (num_modified, num_deleted, num_created)) + logger = logging.getLogger('c3nav') + logger.info(_('%d altitude areas built.') % len(areas)) + logger.info(_('%d modified, %d deleted, %d created.') % (num_modified, num_deleted, num_created)) diff --git a/src/c3nav/mapdata/models/update.py b/src/c3nav/mapdata/models/update.py index 0ea83f86..ccb94629 100644 --- a/src/c3nav/mapdata/models/update.py +++ b/src/c3nav/mapdata/models/update.py @@ -1,3 +1,4 @@ +import logging import os import pickle from contextlib import contextmanager, suppress @@ -84,6 +85,8 @@ class MapUpdate(models.Model): @classmethod def process_updates(cls): + logger = logging.getLogger('c3nav') + with transaction.atomic(): new_updates = tuple(cls.objects.filter(processed=False).select_for_update(nowait=True)) if not new_updates: @@ -92,27 +95,34 @@ class MapUpdate(models.Model): from c3nav.mapdata.cache import changed_geometries changed_geometries.reset() + logger.info('Recalculating altitude areas...') + from c3nav.mapdata.models import AltitudeArea AltitudeArea.recalculate() - for new_update in new_updates: - print('Applying changed geometries from MapUpdate #%s!' % new_update.pk) - try: - changed_geometries.combine( - pickle.load(open(new_update._changed_geometries_filename(), 'rb')) - ) - except FileNotFoundError: - print('Changed geometries file not found!') - with suppress(FileNotFoundError): + logger.info('%.3f m² of altitude areas affected.' % changed_geometries.area) - print('done') + for new_update in new_updates: + logger.info('Applying changed geometries from MapUpdate #%(id)s (%(type)s)...' % + {'id': new_update.pk, 'type': new_update.type}) + try: + new_changes = pickle.load(open(new_update._changed_geometries_filename(), 'rb')) + except FileNotFoundError: + logger.warning('changed_geometries pickle file not found.') + else: + logger.info('%.3f m² affected by this update.' % new_changes.area) + changed_geometries.combine(new_changes) new_update.processed = True new_update.save() + logger.info('%.3f m² of geometries affected in total.' % changed_geometries.area) + last_processed_update = cls.objects.filter(processed=True).latest().to_tuple changed_geometries.save(last_processed_update, new_updates[-1].to_tuple) + logger.info('Rebuilding level render data...') + from c3nav.mapdata.render.data import LevelRenderData LevelRenderData.rebuild() diff --git a/src/c3nav/mapdata/tasks.py b/src/c3nav/mapdata/tasks.py index 606a2849..56ba2b5e 100644 --- a/src/c3nav/mapdata/tasks.py +++ b/src/c3nav/mapdata/tasks.py @@ -1,3 +1,5 @@ +import logging + from django.db import DatabaseError from django.utils.formats import date_format from django.utils.translation import ugettext_lazy as _ @@ -5,24 +7,32 @@ from django.utils.translation import ungettext_lazy from c3nav.celery import app +logger = logging.getLogger('c3nav') + @app.task(bind=True, max_retries=10) def process_map_updates(self): + if self.request.called_directly: + logger.info('Processing map updates by direct command...') + else: + logger.info('Processing map updates...') + from c3nav.mapdata.models import MapUpdate try: updates = MapUpdate.process_updates() except DatabaseError: if self.request.called_directly: raise + logger.info('Processing is already running, retrying in 30 seconds.') raise self.retry(countdown=30) if updates: print() - print(ungettext_lazy('%d map update processed.', '%d map updates processed.', len(updates)) % len(updates)) + logger.info(ungettext_lazy('%d map update processed.', '%d map updates processed.', len(updates)) % len(updates)) if updates: - print(_('Last processed update: %(date)s (#%(id)d)') % { + logger.info(_('Last processed update: %(date)s (#%(id)d)') % { 'date': date_format(updates[-1].datetime, 'DATETIME_FORMAT'), 'id': updates[-1].pk, }) diff --git a/src/c3nav/settings.py b/src/c3nav/settings.py index b0c36cc9..93580216 100644 --- a/src/c3nav/settings.py +++ b/src/c3nav/settings.py @@ -350,7 +350,12 @@ LOGGING = { 'handlers': ['file', 'console'], 'level': 'INFO', # Do not output all the queries 'propagate': True, - } + }, + 'shapely.geos': { + 'handlers': ['file', 'console'], + 'level': 'INFO', + 'propagate': True, + }, }, }