Improving database logging by adding duration, referrer and post data (#1830)

* Improving logging with duration and referrer

* Handling case where referrer is None

* Providing log_this with its own session

* Attempting to fix tests

* Fixing tests

superset/migrations/versions/525c854f0005_log_this_plus.py

@@ -0,0 +1,24 @@
+"""log_this_plus
+
+Revision ID: 525c854f0005
+Revises: e46f2d27a08e
+Create Date: 2016-12-13 16:19:02.239322
+
+"""
+
+# revision identifiers, used by Alembic.
+revision = '525c854f0005'
+down_revision = 'e46f2d27a08e'
+
+from alembic import op
+import sqlalchemy as sa
+
+
+def upgrade():
+    op.add_column('logs', sa.Column('duration_ms', sa.Integer(), nullable=True))
+    op.add_column('logs', sa.Column('referrer', sa.String(length=1024), nullable=True))
+
+
+def downgrade():
+    op.drop_column('logs', 'referrer')
+    op.drop_column('logs', 'duration_ms')

superset/migrations/versions/6414e83d82b7_.py

@@ -0,0 +1,22 @@
+"""empty message
+
+Revision ID: 6414e83d82b7
+Revises: ('525c854f0005', 'f1f2d4af5b90')
+Create Date: 2016-12-19 09:57:05.814013
+
+"""
+
+# revision identifiers, used by Alembic.
+revision = '6414e83d82b7'
+down_revision = ('525c854f0005', 'f1f2d4af5b90')
+
+from alembic import op
+import sqlalchemy as sa
+
+
+def upgrade():
+    pass
+
+
+def downgrade():
+    pass

superset/models.py

@@ -2316,16 +2316,21 @@ class Log(Model):
     user = relationship('User', backref='logs', foreign_keys=[user_id])
     dttm = Column(DateTime, default=datetime.utcnow)
     dt = Column(Date, default=date.today())
+    duration_ms = Column(Integer)
+    referrer = Column(String(1024))
 
     @classmethod
     def log_this(cls, f):
         """Decorator to log user actions"""
         @functools.wraps(f)
         def wrapper(*args, **kwargs):
+            start_dttm = datetime.now()
             user_id = None
             if g.user:
                 user_id = g.user.get_id()
             d = request.args.to_dict()
+            post_data = request.form or {}
+            d.update(post_data)
             d.update(kwargs)
             slice_id = d.get('slice_id', 0)
             try:
@@ -2337,15 +2342,19 @@ class Log(Model):
                 params = json.dumps(d)
             except:
                 pass
+            value = f(*args, **kwargs)
             log = cls(
                 action=f.__name__,
                 json=params,
                 dashboard_id=d.get('dashboard_id') or None,
                 slice_id=slice_id,
+                duration_ms=(
+                    datetime.now() - start_dttm).total_seconds() * 1000,
+                referrer=request.referrer[:1000] if request.referrer else None,
                 user_id=user_id)
             db.session.add(log)
-            db.session.commit()
-            return f(*args, **kwargs)
+            db.session.flush()
+            return value
         return wrapper
 
 

superset/views.py

@@ -1369,6 +1369,7 @@ class Superset(BaseSupersetView):
         viz_obj = self.get_viz(slice_id)
         return redirect(viz_obj.get_url(**request.args))
 
+    @log_this
     @has_access_api
     @expose("/explore_json/<datasource_type>/<datasource_id>/")
     def explore_json(self, datasource_type, datasource_id):