logging: update request wrapper to expose additional data points

vcsserver/tweens/request_wrapper.py

@@ -44,24 +44,29 b' class RequestWrapperTween(object):'
     def __call__(self, request):
         start = time.time()
         log.debug('Starting request time measurement')
+        response = None
         try:
             response = self.handler(request)
         finally:
             count = request.request_count()
             _ver_ = vcsserver.__version__
             _path = safe_str(get_access_path(request.environ))
+            ip = '127.0.0.1'
+            match_route = request.matched_route.name if request.matched_route else "NOT_FOUND"
 
             total = time.time() - start
             log.info(
                 'Req[%4s] IP: %s %s Request to %s time: %.4fs [%s], VCSServer %s',
-                count, '127.0.0.1', request.environ.get('REQUEST_METHOD'),
-                _path, total, get_user_agent(request.environ), _ver_
+                count, ip, request.environ.get('REQUEST_METHOD'),
+                _path, total, get_user_agent(request.environ), _ver_,
+                extra={"time": total, "ver": _ver_,
+                       "path": _path, "view_name": match_route}
             )
 
             statsd = request.registry.statsd
             if statsd:
                 match_route = request.matched_route.name if request.matched_route else _path
-                resp_code = response.status_code
+                resp_code = getattr(response, 'status_code', 'UNDEFINED')
                 elapsed_time_ms = round(1000.0 * total)  # use ms only
                 statsd.timing(
                     "vcsserver_req_timing.histogram", elapsed_time_ms,