Improve logging

- Remove extra handler - flask default handler is fine (everything was
  logged twice due to changes in flask 1.0)
- Add more logging messages

JIRA INFRA-2899 #action In Progress

app/api/utils.py

@@ -12,6 +12,7 @@ This module implements useful functions for the API.
 import urllib.parse
 import sqlalchemy as sa
 from flask import current_app, jsonify, request
+from flask_login import current_user
 from flask_sqlalchemy import Pagination
 from ..extensions import db
 from .. import utils
@@ -124,7 +125,6 @@ def get_json_body():
     data = request.get_json()
     if data is None:
         raise utils.CSEntryError("Body should be a JSON object")
-    current_app.logger.debug(f"Received: {data}")
     if not data:
         raise utils.CSEntryError("At least one field is required", status_code=422)
     return data
@@ -154,6 +154,9 @@ def create_generic_model(model, mandatory_fields=("name",), **kwargs):
         raise utils.CSEntryError(str(e), status_code=422)
     db.session.add(instance)
     commit()
+    current_app.logger.info(
+        f"New {model.__tablename__} created by {current_user}: {instance.to_dict()}"
+    )
     return jsonify(instance.to_dict()), 201
 
 
@@ -166,6 +169,9 @@ def delete_generic_model(model, primary_key):
     instance = model.query.get_or_404(primary_key)
     db.session.delete(instance)
     commit()
+    current_app.logger.info(
+        f"{model.__tablename__} {instance} deleted by {current_user}"
+    )
     return jsonify(), 204
 
 
@@ -195,4 +201,7 @@ def update_generic_model(model, primary_key, allowed_fields):
     except Exception as e:
         raise utils.CSEntryError(str(e), status_code=422)
     commit()
+    current_app.logger.info(
+        f"{model.__tablename__} {primary_key} updated by {current_user}: {instance.to_dict()}"
+    )
     return jsonify(instance.to_dict()), 200

app/factory.py

@@ -72,19 +72,7 @@ def create_app(config=None):
             integrations=[FlaskIntegration()],
         )
 
-    if not app.debug:
-        # Log to stderr
-        handler = logging.StreamHandler()
-        handler.setFormatter(
-            logging.Formatter(
-                "%(asctime)s %(levelname)s: %(message)s " "[in %(pathname)s:%(lineno)d]"
-            )
-        )
-        # Set app logger level to DEBUG
-        # otherwise only WARNING and above are propagated
-        app.logger.setLevel(logging.DEBUG)
-        handler.setLevel(logging.DEBUG)
-        app.logger.addHandler(handler)
+    app.logger.setLevel(logging.DEBUG)
     app.logger.info("CSEntry created!")
     # Remove variables that contain a password
     settings_to_display = {

app/network/views.py

@@ -110,7 +110,7 @@ def create_host():
             current_app.logger.warning(f"{e}")
             flash(f"{e}", "error")
             return render_template("network/create_host.html", form=form)
-        current_app.logger.debug(f"Trying to create: {host!r}")
+        current_app.logger.debug(f"Trying to create: {host}")
         db.session.add(host)
         try:
             db.session.commit()
@@ -119,6 +119,9 @@ def create_host():
             current_app.logger.warning(f"{e}")
             flash(f"{e}", "error")
         else:
+            current_app.logger.info(
+                f"Host {host} created by {current_user}: {host.to_dict()}"
+            )
             flash(f"Host {host} created!", "success")
         # Save network_id and device_type_id to the session to retrieve them after the redirect
         session["network_id"] = network_id
@@ -138,6 +141,7 @@ def delete_host():
     # defined on the model
     db.session.delete(host)
     db.session.commit()
+    current_app.logger.info(f"Host {host} deleted by {current_user}")
     flash(f"Host {host.name} has been deleted", "success")
     if host.device_type.name == "VirtualMachine":
         flash(
@@ -202,7 +206,7 @@ def view_host(name):
                     utils.trigger_core_services_update()
                 db.session.commit()
                 current_app.logger.info(
-                    f"Set network boot profile to {boot_profile} for {name} requested: task {task.id}"
+                    f"Set network boot profile to {boot_profile} for {name} requested by {current_user}: task {task.id}"
                 )
                 flash(
                     f"Set network boot profile to {boot_profile} for {name} requested! "
@@ -227,7 +231,9 @@ def view_host(name):
                     skip_post_install_job=form.skip_post_install_job.data,
                 )
                 db.session.commit()
-                current_app.logger.info(f"Creation of {name} requested: task {task.id}")
+                current_app.logger.info(
+                    f"Creation of {name} requested by {current_user}: task {task.id}"
+                )
                 flash(
                     f"Creation of {name} requested! Refresh the page to update the status.",
                     "success",
@@ -267,7 +273,7 @@ def edit_host(name):
             current_app.logger.warning(f"{e}")
             flash(f"{e}", "error")
             return render_template("network/edit_host.html", form=form)
-        current_app.logger.debug(f"Trying to update: {host!r}")
+        current_app.logger.debug(f"Trying to update: {host}")
         try:
             db.session.commit()
         except sa.exc.IntegrityError as e:
@@ -275,6 +281,9 @@ def edit_host(name):
             current_app.logger.warning(f"{e}")
             flash(f"{e}", "error")
         else:
+            current_app.logger.info(
+                f"Host {name} updated by {current_user}: {host.to_dict()}"
+            )
             flash(f"Host {host} updated!", "success")
         return redirect(url_for("network.view_host", name=host.name))
     return render_template("network/edit_host.html", form=form)
@@ -333,6 +342,9 @@ def create_interface(hostname):
             current_app.logger.warning(f"{e}")
             flash(f"{e}", "error")
         else:
+            current_app.logger.info(
+                f"Interface {interface} created by {current_user}: {interface.to_dict()}"
+            )
             flash(f"Interface {interface} created!", "success")
         return redirect(url_for("network.create_interface", hostname=hostname))
     return render_template(
@@ -415,6 +427,9 @@ def edit_interface(name):
             current_app.logger.warning(f"{e}")
             flash(f"{e}", "error")
         else:
+            current_app.logger.info(
+                f"Interface {name} updated by {current_user}: {interface.to_dict()}"
+            )
             flash(f"Interface {interface} updated!", "success")
         return redirect(url_for("network.view_host", name=interface.host.name))
     return render_template(
@@ -437,6 +452,7 @@ def delete_interface():
     # defined on the model
     db.session.delete(interface)
     db.session.commit()
+    current_app.logger.info(f"Interface {interface} deleted by {current_user}")
     flash(f"Interface {interface.name} has been deleted", "success")
     return redirect(url_for("network.view_host", name=hostname))
 
@@ -460,6 +476,7 @@ def delete_ansible_group():
     group = models.AnsibleGroup.query.get_or_404(request.form["group_id"])
     db.session.delete(group)
     db.session.commit()
+    current_app.logger.info(f"Group {group} deleted by {current_user}")
     flash(f"Group {group.name} has been deleted", "success")
     return redirect(url_for("network.list_ansible_groups"))
 
@@ -513,6 +530,9 @@ def edit_ansible_group(name):
             current_app.logger.warning(f"{e}")
             flash(f"{e}", "error")
         else:
+            current_app.logger.info(
+                f"Group {name} updated by {current_user}: {group.to_dict()}"
+            )
             flash(f"Group {group} updated!", "success")
         return redirect(url_for("network.view_ansible_group", name=group.name))
     return render_template("network/edit_group.html", form=form)
@@ -547,6 +567,9 @@ def create_ansible_group():
             current_app.logger.warning(f"{e}")
             flash(f"{e}", "error")
         else:
+            current_app.logger.info(
+                f"Group {group} created by {current_user}: {group.to_dict()}"
+            )
             flash(f"Group {group} created!", "success")
         return redirect(url_for("network.view_ansible_group", name=group.name))
     return render_template("network/create_group.html", form=form)
@@ -574,6 +597,9 @@ def create_domain():
             current_app.logger.warning(f"{e}")
             flash(f"{e}", "error")
         else:
+            current_app.logger.info(
+                f"Domain {domain} created by {current_user}: {domain.to_dict()}"
+            )
             flash(f"Domain {domain} created!", "success")
         return redirect(url_for("network.create_domain"))
     return render_template("network/create_domain.html", form=form)
@@ -621,6 +647,9 @@ def create_scope():
             current_app.logger.warning(f"{e}")
             flash(f"{e}", "error")
         else:
+            current_app.logger.info(
+                f"Network scope {scope} created by {current_user}: {scope.to_dict()}"
+            )
             flash(f"Network Scope {scope} created!", "success")
         return redirect(url_for("network.create_scope"))
     return render_template("network/create_scope.html", form=form)
@@ -655,6 +684,9 @@ def edit_scope(name):
             current_app.logger.warning(f"{e}")
             flash(f"{e}", "error")
         else:
+            current_app.logger.info(
+                f"Network scope {name} updated by {current_user}: {scope.to_dict()}"
+            )
             flash(f"Network Scope {scope} updated!", "success")
         return redirect(url_for("network.view_scope", name=scope.name))
     return render_template("network/edit_scope.html", form=form)
@@ -734,6 +766,9 @@ def create_network():
             current_app.logger.warning(f"{e}")
             flash(f"{e}", "error")
         else:
+            current_app.logger.info(
+                f"Network {network} created by {current_user}: {network.to_dict()}"
+            )
             flash(f"Network {network} created!", "success")
         # Save scope_id to the session to retrieve it after the redirect
         session["scope_id"] = scope_id
@@ -776,6 +811,9 @@ def edit_network(vlan_name):
             current_app.logger.warning(f"{e}")
             flash(f"{e}", "error")
         else:
+            current_app.logger.info(
+                f"Network {vlan_name} updated by {current_user}: {network.to_dict()}"
+            )
             flash(f"Network {network} updated!", "success")
         return redirect(url_for("network.view_network", vlan_name=network.vlan_name))
     return render_template("network/edit_network.html", form=form)