logger: Add new create_logger abstraction to simplify logging.

This deduplicates a ton of Python logger-creation code to use a single
standard implementation, so we can avoid copy-paste problems.

analytics/lib/counts.py

@@ -14,21 +14,12 @@ from typing import Any, Callable, Dict, List, Optional, Text, Tuple, Type, Union
 
 from collections import defaultdict, OrderedDict
 from datetime import timedelta, datetime
-import logging
+from zerver.lib.logging_util import create_logger
 import time
 
 ## Logging setup ##
 
-log_format = '%(asctime)s %(levelname)-8s %(message)s'
-logging.basicConfig(format=log_format)
-
-formatter = logging.Formatter(log_format)
-file_handler = logging.FileHandler(settings.ANALYTICS_LOG_PATH)
-file_handler.setFormatter(formatter)
-
-logger = logging.getLogger("zulip.management")
-logger.setLevel(logging.INFO)
-logger.addHandler(file_handler)
+logger = create_logger('zulip.management', settings.ANALYTICS_LOG_PATH, 'INFO')
 
 # You can't subtract timedelta.max from a datetime, so use this instead
 TIMEDELTA_MAX = timedelta(days=365*1000)

zerver/decorator.py

@@ -25,13 +25,14 @@ from django.core.handlers import base
 from functools import wraps
 import base64
 import datetime
-import logging
 import ujson
+import logging
 from io import BytesIO
 from six.moves import zip, urllib
 
 from typing import Union, Any, Callable, Sequence, Dict, Optional, TypeVar, Text, cast
 from zerver.lib.str_utils import force_bytes
+from zerver.lib.logging_util import create_logger
 
 # This is a hack to ensure that RemoteZulipServer always exists even
 # if Zilencer isn't enabled.
@@ -46,16 +47,8 @@ FuncT = TypeVar('FuncT', bound=Callable[..., Any])
 ViewFuncT = TypeVar('ViewFuncT', bound=Callable[..., HttpResponse])
 
 ## logger setup
-log_format = "%(asctime)s: %(message)s"
-
-formatter = logging.Formatter(log_format)
-file_handler = logging.FileHandler(
-    settings.API_KEY_ONLY_WEBHOOK_LOG_PATH)
-file_handler.setFormatter(formatter)
-
-webhook_logger = logging.getLogger("zulip.zerver.webhooks")
-webhook_logger.setLevel(logging.DEBUG)
-webhook_logger.addHandler(file_handler)
+webhook_logger = create_logger(
+    "zulip.zerver.webhooks", settings.API_KEY_ONLY_WEBHOOK_LOG_PATH, 'DEBUG')
 
 class _RespondAsynchronously(object):
     pass

zerver/lib/digest.py

@@ -19,19 +19,9 @@ from zerver.models import UserProfile, UserMessage, Recipient, Stream, \
     Realm
 from zerver.context_processors import common_context
 from zerver.lib.queue import queue_json_publish
+from zerver.lib.logging_util import create_logger
 
-import logging
-
-log_format = "%(asctime)s: %(message)s"
-logging.basicConfig(format=log_format)
-
-formatter = logging.Formatter(log_format)
-file_handler = logging.FileHandler(settings.DIGEST_LOG_PATH)
-file_handler.setFormatter(formatter)
-
-logger = logging.getLogger(__name__)
-logger.setLevel(logging.DEBUG)
-logger.addHandler(file_handler)
+logger = create_logger(__name__, settings.DIGEST_LOG_PATH, 'DEBUG')
 
 VALID_DIGEST_DAY = 1  # Tuesdays
 DIGEST_CUTOFF = 5

zerver/lib/logging_util.py

@@ -9,6 +9,7 @@ import traceback
 from datetime import datetime, timedelta
 from django.conf import settings
 from zerver.lib.str_utils import force_bytes
+from logging import Logger
 
 # Adapted http://djangosnippets.org/snippets/2242/ by user s29 (October 25, 2010)
 
@@ -89,3 +90,26 @@ def skip_site_packages_logs(record):
     if 'site-packages' in record.pathname:
         return False
     return True
+
+def create_logger(name, log_file, log_level, log_format="%(asctime)s %(levelname)-8s %(message)s"):
+    # type: (str, str, str, str) -> Logger
+    """Creates a named logger for use in logging content to a certain
+    file.  A few notes:
+
+    * "name" is used in determining what gets logged to which files;
+    see "loggers" in zproject/settings.py for details.  Don't use `""`
+    -- that's the root logger.
+    * "log_file" should be declared in zproject/settings.py in ZULIP_PATHS.
+
+    """
+    logging.basicConfig(format=log_format)
+    logger = logging.getLogger(name)
+    logger.setLevel(getattr(logging, log_level))
+
+    if log_file:
+        formatter = logging.Formatter(log_format)
+        file_handler = logging.FileHandler(log_file)
+        file_handler.setFormatter(formatter)
+        logger.addHandler(file_handler)
+
+    return logger

zerver/lib/soft_deactivation.py

@@ -1,6 +1,6 @@
 from __future__ import absolute_import
 
-import logging
+from zerver.lib.logging_util import create_logger
 from collections import defaultdict
 from django.db import transaction
 from django.db.models import Max
@@ -11,16 +11,7 @@ from typing import DefaultDict, List, Union, Any
 from zerver.models import UserProfile, UserMessage, RealmAuditLog, \
     Subscription, Message, Recipient, UserActivity, Realm
 
-log_format = "%(asctime)s: %(message)s"
-logging.basicConfig(format=log_format)
-
-formatter = logging.Formatter(log_format)
-file_handler = logging.FileHandler(settings.SOFT_DEACTIVATION_LOG_PATH)
-file_handler.setFormatter(formatter)
-
-logger = logging.getLogger('zulip.soft_deactivation')
-logger.setLevel(logging.INFO)
-logger.addHandler(file_handler)
+logger = create_logger("zulip.soft_deactivation", settings.SOFT_DEACTIVATION_LOG_PATH, 'INFO')
 
 def filter_by_subscription_history(
         user_profile, all_stream_messages, all_stream_subscription_logs):

zerver/management/commands/deliver_email.py

@@ -21,22 +21,13 @@ from zerver.lib.context_managers import lockfile
 from zerver.lib.send_email import send_email, EmailNotDeliveredException
 
 import time
-import logging
+from zerver.lib.logging_util import create_logger
 from datetime import datetime
 from ujson import loads
 from typing import Any
 
 ## Setup ##
-log_format = "%(asctime)s: %(message)s"
-logging.basicConfig(format=log_format)
-
-formatter = logging.Formatter(log_format)
-file_handler = logging.FileHandler(settings.EMAIL_DELIVERER_LOG_PATH)
-file_handler.setFormatter(formatter)
-
-logger = logging.getLogger(__name__)
-logger.setLevel(logging.DEBUG)
-logger.addHandler(file_handler)
+logger = create_logger(__name__, settings.EMAIL_DELIVERER_LOG_PATH, 'DEBUG')
 
 class Command(BaseCommand):
     help = """Deliver emails queued by various parts of Zulip

zerver/management/commands/enqueue_digest_emails.py

@@ -1,6 +1,5 @@
 from __future__ import absolute_import
 import datetime
-import logging
 
 from typing import Any, List
 
@@ -9,19 +8,10 @@ from django.core.management.base import BaseCommand
 from django.utils.timezone import now as timezone_now
 
 from zerver.lib.digest import enqueue_emails, DIGEST_CUTOFF
+from zerver.lib.logging_util import create_logger
 
 ## Logging setup ##
-
-log_format = "%(asctime)s: %(message)s"
-logging.basicConfig(format=log_format)
-
-formatter = logging.Formatter(log_format)
-file_handler = logging.FileHandler(settings.DIGEST_LOG_PATH)
-file_handler.setFormatter(formatter)
-
-logger = logging.getLogger(__name__)
-logger.setLevel(logging.DEBUG)
-logger.addHandler(file_handler)
+logger = create_logger(__name__, settings.DIGEST_LOG_PATH, 'DEBUG')
 
 class Command(BaseCommand):
     help = """Enqueue digest emails for users that haven't checked the app

zerver/management/commands/sync_ldap_user_data.py

@@ -1,6 +1,5 @@
 from __future__ import absolute_import
 
-import logging
 from typing import Any
 
 from django.core.management.base import BaseCommand
@@ -9,19 +8,10 @@ from django.conf import settings
 
 from zproject.backends import ZulipLDAPUserPopulator
 from zerver.models import UserProfile
+from zerver.lib.logging_util import create_logger
 
 ## Setup ##
-
-log_format = "%(asctime)s: %(message)s"
-logging.basicConfig(format=log_format)
-
-formatter = logging.Formatter(log_format)
-file_handler = logging.FileHandler(settings.LDAP_SYNC_LOG_PATH)
-file_handler.setFormatter(formatter)
-
-logger = logging.getLogger(__name__)
-logger.setLevel(logging.INFO)
-logger.addHandler(file_handler)
+logger = create_logger(__name__, settings.LDAP_SYNC_LOG_PATH, 'INFO')
 
 # Run this on a cronjob to pick up on name changes.
 def sync_ldap_user_data():