Logging enhancement (#6041)

* Option to overwrite uwsgi log format * Changes: - dd_user to make user visible in the log - adjust loggers to same level - converting print to log.debug * Changes: - fix typo * Changes: - fix typo * Changes: - escape set_logvar for unitests * Changes: - adding signal receivers for basic gui auth operations * Changes: - do not propagate django.request * Changes: - import in scope
DefectDojo · Apr 27, 2022 · ce966ac · ce966ac
1 parent 9a17c41
commit ce966ac
Show file tree

Hide file tree

Showing 7 changed files with 54 additions and 9 deletions.
diff --git a/docker/entrypoint-uwsgi-dev.sh b/docker/entrypoint-uwsgi-dev.sh
@@ -6,6 +6,7 @@ cd /app
 # Full list of uwsgi options: https://uwsgi-docs.readthedocs.io/en/latest/Options.html
 # --lazy-apps required for debugging --> https://uwsgi-docs.readthedocs.io/en/latest/articles/TheArtOfGracefulReloading.html?highlight=lazy-apps#preforking-vs-lazy-apps-vs-lazy
 
+DD_UWSGI_LOGFORMAT_DEFAULT='[pid: %(pid)|app: -|req: -/-] %(addr) (%(dd_user)) {%(vars) vars in %(pktsize) bytes} [%(ctime)] %(method) %(uri) => generated %(rsize) bytes in %(msecs) msecs (%(proto) %(status)) %(headers) headers in %(hsize) bytes (%(switches) switches on core %(core))'
 
 if [ ${DD_DEBUG} == "True" ]; then
   echo "Debug mode enabled, reducing # of processes and threads to 1"
@@ -25,4 +26,5 @@ exec uwsgi \
   --py-autoreload 1 \
   --buffer-size="${DD_UWSGI_BUFFER_SIZE:-8192}" \
   --lazy-apps \
-  --touch-reload="/app/dojo/setting/settings.py"
+  --touch-reload="/app/dojo/setting/settings.py" \
+  --logformat "${DD_UWSGI_LOGFORMAT:-$DD_UWSGI_LOGFORMAT_DEFAULT}"
diff --git a/docker/entrypoint-uwsgi.sh b/docker/entrypoint-uwsgi.sh
@@ -17,6 +17,8 @@ umask 0002
 # do the check with Django stack
 python3 manage.py check
 
+DD_UWSGI_LOGFORMAT_DEFAULT='[pid: %(pid)|app: -|req: -/-] %(addr) (%(dd_user)) {%(vars) vars in %(pktsize) bytes} [%(ctime)] %(method) %(uri) => generated %(rsize) bytes in %(msecs) msecs (%(proto) %(status)) %(headers) headers in %(hsize) bytes (%(switches) switches on core %(core))'
+
 exec uwsgi \
   "--${DD_UWSGI_MODE}" "${DD_UWSGI_ENDPOINT}" \
   --protocol uwsgi \
@@ -25,5 +27,6 @@ exec uwsgi \
   --threads ${DD_UWSGI_NUM_OF_THREADS:-2} \
   --wsgi dojo.wsgi:application \
   --buffer-size="${DD_UWSGI_BUFFER_SIZE:-8192}" \
-  --http 0.0.0.0:8081 --http-to ${DD_UWSGI_ENDPOINT}
-  # HTTP endpoint is enabled for Kubernetes liveness checks. It should not be exposed as a serivce.
+  --http 0.0.0.0:8081 --http-to ${DD_UWSGI_ENDPOINT} \
+  --logformat "${DD_UWSGI_LOGFORMAT:-$DD_UWSGI_LOGFORMAT_DEFAULT}"
+  # HTTP endpoint is enabled for Kubernetes liveness checks. It should not be exposed as a service.
diff --git a/dojo/finding/views.py b/dojo/finding/views.py
@@ -127,7 +127,7 @@ def findings(request, pid=None, eid=None, view=None, filter_name=None, order_by=
     if view == "All":
         filter_name = "All"
     else:
-        print('Filtering!', view)
+        logger.debug('Filtering!: %s', view)
 
     if pid:
         product = get_object_or_404(Product, id=pid)

diff --git a/dojo/middleware.py b/dojo/middleware.py
@@ -7,6 +7,7 @@
 from django.db import models
 from django.urls import reverse
 
+
 logger = logging.getLogger(__name__)
 
 EXEMPT_URLS = [compile(settings.LOGIN_URL.lstrip('/'))]
@@ -46,6 +47,14 @@ def __call__(self, request):
                 return HttpResponseRedirect(fullURL)
 
         if request.user.is_authenticated:
+            logger.debug("Authenticated user: %s", str(request.user))
+            try:
+                uwsgi = __import__('uwsgi', globals(), locals(), ['set_logvar'], 0)
+                # this populates dd_user log var, so can appear in the uwsgi logs
+                uwsgi.set_logvar('dd_user', str(request.user))
+            except:
+                # to avoid unittests to fail
+                pass
             path = request.path_info.lstrip('/')
             from dojo.models import Dojo_User
             if Dojo_User.force_password_reset(request.user) and path != 'change_password':

diff --git a/dojo/settings/settings.dist.py b/dojo/settings/settings.dist.py
@@ -1305,8 +1305,8 @@ def saml2_attrib_map_format(dict):
     'loggers': {
         'django.request': {
             'handlers': ['mail_admins', 'console'],
-            'level': 'WARN',
-            'propagate': True,
+            'level': '%s' % LOG_LEVEL,
+            'propagate': False,
         },
         'django.security': {
             'handlers': [r'%s' % LOGGING_HANDLER],
@@ -1333,17 +1333,18 @@ def saml2_attrib_map_format(dict):
         'saml2': {
             'handlers': [r'%s' % LOGGING_HANDLER],
             'level': '%s' % LOG_LEVEL,
+            'propagate': False,
         },
         'MARKDOWN': {
             # The markdown library is too verbose in it's logging, reducing the verbosity in our logs.
             'handlers': [r'%s' % LOGGING_HANDLER],
-            'level': 'WARNING',
+            'level': '%s' % LOG_LEVEL,
             'propagate': False,
         },
         'titlecase': {
             # The titlecase library is too verbose in it's logging, reducing the verbosity in our logs.
             'handlers': [r'%s' % LOGGING_HANDLER],
-            'level': 'WARNING',
+            'level': '%s' % LOG_LEVEL,
             'propagate': False,
         },
     }

diff --git a/dojo/utils.py b/dojo/utils.py
@@ -36,6 +36,7 @@
 import crum
 from dojo.celery import app
 from dojo.decorators import dojo_async_task, dojo_model_from_id, dojo_model_to_id
+from django.contrib.auth.signals import user_logged_in, user_logged_out, user_login_failed
 
 
 logger = logging.getLogger(__name__)
@@ -2129,3 +2130,32 @@ def get_enabled_notifications_list():
 def is_finding_groups_enabled():
     """Returns true is feature is enabled otherwise false"""
     return get_system_setting("enable_finding_groups")
+
+
+@receiver(user_logged_in)
+def log_user_login(sender, request, user, **kwargs):
+    # to cover more complex cases:
+    # http://stackoverflow.com/questions/4581789/how-do-i-get-user-ip-address-in-django
+
+    logger.info('login user: {user} via ip: {ip}'.format(
+        user=user.username,
+        ip=request.META.get('REMOTE_ADDR')
+    ))
+
+
+@receiver(user_logged_out)
+def log_user_logout(sender, request, user, **kwargs):
+
+    logger.info('logout user: {user} via ip: {ip}'.format(
+        user=user.username,
+        ip=request.META.get('REMOTE_ADDR')
+    ))
+
+
+@receiver(user_login_failed)
+def log_user_login_failed(sender, credentials, request, **kwargs):
+
+    logger.warning('login failed for: {credentials} via ip: {ip}'.format(
+        credentials=credentials['username'],
+        ip=request.META['REMOTE_ADDR']
+    ))
diff --git a/nginx/nginx.conf b/nginx/nginx.conf
@@ -61,7 +61,7 @@ http {
       return 200 "Born to be alive!\n";
       access_log off;
     }
-    # Used by Kuebernetes readiness checks
+    # Used by Kubernetes readiness checks
     location = /uwsgi_health {
       limit_except GET { deny all; }
       rewrite /.+ /login?force_login_form&next=/ break;