better logging in many places

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:

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):

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!'))

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!'))

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))
+            logger = logging.getLogger('c3nav')
-            print(_('%d modified, %d deleted, %d created.') % (num_modified, num_deleted, num_created))
+            logger.info(_('%d altitude areas built.') % len(areas))
+            logger.info(_('%d modified, %d deleted, %d created.') % (num_modified, num_deleted, num_created))

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:
+            logger.info('%.3f m² of altitude areas affected.' % changed_geometries.area)
-                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):
 
-                    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()
 

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,
         })

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,
+        },
     },
 }