paulmataruso/zulip
1
0
Fork 0
mirror of https://github.com/zulip/zulip.git synced 2025-11-04 22:13:26 +00:00
Code Issues Packages Projects Releases Wiki Activity

middleware: Log user.id/realm.string_id instead of _email.

Browse Source
This commit is contained in:
Mateusz Mandera
2020-03-09 11:39:20 +01:00
committed by Tim Abbott
parent 700123a30b
commit 0255ca9b6a
10 changed files with 30 additions and 26 deletions
Download Patch File Download Diff File Expand all files Collapse all files

12
zerver/decorator.py
View File

@@ -197,7 +197,7 @@ def validate_api_key(request: HttpRequest, role: Optional[str],
if get_subdomain(request) != Realm.SUBDOMAIN_FOR_ROOT_DOMAIN: if get_subdomain(request) != Realm.SUBDOMAIN_FOR_ROOT_DOMAIN:
raise JsonableError(_("Invalid subdomain for push notifications bouncer")) raise JsonableError(_("Invalid subdomain for push notifications bouncer"))
request.user = remote_server request.user = remote_server
request._email = "zulip-server:" + role request._requestor_for_logs = "zulip-server:" + role
remote_server.rate_limits = "" remote_server.rate_limits = ""
# Skip updating UserActivity, since remote_server isn't actually a UserProfile object. # Skip updating UserActivity, since remote_server isn't actually a UserProfile object.
process_client(request, remote_server, skip_update_user_activity=True) process_client(request, remote_server, skip_update_user_activity=True)
@@ -208,7 +208,7 @@ def validate_api_key(request: HttpRequest, role: Optional[str],
raise JsonableError(_("This API is not available to incoming webhook bots.")) raise JsonableError(_("This API is not available to incoming webhook bots."))
request.user = user_profile request.user = user_profile
request._email = user_profile.delivery_email request._requestor_for_logs = user_profile.format_requestor_for_logs()
process_client(request, user_profile, client_name=client_name) process_client(request, user_profile, client_name=client_name)
return user_profile return user_profile
@@ -409,7 +409,7 @@ def do_login(request: HttpRequest, user_profile: UserProfile) -> None:
and also adds helpful data needed by our server logs. and also adds helpful data needed by our server logs.
""" """
django_login(request, user_profile) django_login(request, user_profile)
request._email = user_profile.delivery_email request._requestor_for_logs = user_profile.format_requestor_for_logs()
process_client(request, user_profile, is_browser_view=True) process_client(request, user_profile, is_browser_view=True)
if settings.TWO_FACTOR_AUTHENTICATION_ENABLED: if settings.TWO_FACTOR_AUTHENTICATION_ENABLED:
# Login with two factor authentication as well. # Login with two factor authentication as well.
@@ -425,7 +425,7 @@ def log_view_func(view_func: ViewFuncT) -> ViewFuncT:
def add_logging_data(view_func: ViewFuncT) -> ViewFuncT: def add_logging_data(view_func: ViewFuncT) -> ViewFuncT:
@wraps(view_func) @wraps(view_func)
def _wrapped_view_func(request: HttpRequest, *args: Any, **kwargs: Any) -> HttpResponse: def _wrapped_view_func(request: HttpRequest, *args: Any, **kwargs: Any) -> HttpResponse:
request._email = request.user.delivery_email request._requestor_for_logs = request.user.format_requestor_for_logs()
process_client(request, request.user, is_browser_view=True, process_client(request, request.user, is_browser_view=True,
query=view_func.__name__) query=view_func.__name__)
return rate_limit()(view_func)(request, *args, **kwargs) return rate_limit()(view_func)(request, *args, **kwargs)
@@ -649,7 +649,7 @@ def authenticate_log_and_execute_json(request: HttpRequest,
process_client(request, user_profile, is_browser_view=True, process_client(request, user_profile, is_browser_view=True,
query=view_func.__name__) query=view_func.__name__)
request._email = user_profile.delivery_email request._requestor_for_logs = user_profile.format_requestor_for_logs()
return limited_view_func(request, user_profile, *args, **kwargs) return limited_view_func(request, user_profile, *args, **kwargs)
# Checks if the request is a POST request and that the user is logged # Checks if the request is a POST request and that the user is logged
@@ -712,7 +712,7 @@ def internal_notify_view(is_tornado_view: bool) -> Callable[[ViewFuncT], ViewFun
raise RuntimeError('Tornado notify view called with no Tornado handler') raise RuntimeError('Tornado notify view called with no Tornado handler')
if not is_tornado_view and is_tornado_request: if not is_tornado_view and is_tornado_request:
raise RuntimeError('Django notify view called with Tornado handler') raise RuntimeError('Django notify view called with Tornado handler')
request._email = "internal" request._requestor_for_logs = "internal"
return view_func(request, *args, **kwargs) return view_func(request, *args, **kwargs)
return _wrapped_func_arguments return _wrapped_func_arguments
return _wrapped_view_func return _wrapped_view_func

2
zerver/lib/test_helpers.py
View File

@@ -280,7 +280,7 @@ class HostRequestMock:
self.method = '' self.method = ''
self.body = '' self.body = ''
self.content_type = '' self.content_type = ''
self._email = '' self._requestor_for_logs = ''
def get_host(self) -> str: def get_host(self) -> str:
return self.host return self.host

19
zerver/middleware.py
View File

@@ -105,8 +105,9 @@ statsd_blacklisted_requests = [
'upload_file', 'realm_activity', 'user_activity' 'upload_file', 'realm_activity', 'user_activity'
] ]
def write_log_line(log_data: MutableMapping[str, Any], path: str, method: str, remote_ip: str, email: str, def write_log_line(log_data: MutableMapping[str, Any], path: str, method: str, remote_ip: str,
client_name: str, status_code: int=200, error_content: Optional[AnyStr]=None, requestor_for_logs: str, client_name: str, status_code: int=200,
error_content: Optional[AnyStr]=None,
error_content_iter: Optional[Iterable[AnyStr]]=None) -> None: error_content_iter: Optional[Iterable[AnyStr]]=None) -> None:
assert error_content is None or error_content_iter is None assert error_content is None or error_content_iter is None
if error_content is not None: if error_content is not None:
@@ -199,7 +200,7 @@ def write_log_line(log_data: MutableMapping[str, Any], path: str, method: str, r
extra_request_data = " %s" % (log_data['extra'],) extra_request_data = " %s" % (log_data['extra'],)
else: else:
extra_request_data = "" extra_request_data = ""
logger_client = "(%s via %s)" % (email, client_name) logger_client = "(%s via %s)" % (requestor_for_logs, client_name)
logger_timing = ('%5s%s%s%s%s%s %s' % logger_timing = ('%5s%s%s%s%s%s %s' %
(format_timedelta(time_delta), optional_orig_delta, (format_timedelta(time_delta), optional_orig_delta,
remote_cache_output, bugdown_output, remote_cache_output, bugdown_output,
@@ -214,7 +215,7 @@ def write_log_line(log_data: MutableMapping[str, Any], path: str, method: str, r
if (is_slow_query(time_delta, path)): if (is_slow_query(time_delta, path)):
queue_json_publish("slow_queries", dict( queue_json_publish("slow_queries", dict(
query="%s (%s)" % (logger_line, email))) query="%s (%s)" % (logger_line, requestor_for_logs)))
if settings.PROFILE_ALL_REQUESTS: if settings.PROFILE_ALL_REQUESTS:
log_data["prof"].disable() log_data["prof"].disable()
@@ -233,7 +234,7 @@ def write_log_line(log_data: MutableMapping[str, Any], path: str, method: str, r
error_data = repr(b''.join(error_content_list)) error_data = repr(b''.join(error_content_list))
if len(error_data) > 200: if len(error_data) > 200:
error_data = u"[content more than 200 characters]" error_data = u"[content more than 200 characters]"
logger.info('status=%3d, data=%s, uid=%s' % (status_code, error_data, email)) logger.info('status=%3d, data=%s, uid=%s' % (status_code, error_data, requestor_for_logs))
class LogRequests(MiddlewareMixin): class LogRequests(MiddlewareMixin):
# We primarily are doing logging using the process_view hook, but # We primarily are doing logging using the process_view hook, but
@@ -284,11 +285,11 @@ class LogRequests(MiddlewareMixin):
if remote_ip is None: if remote_ip is None:
remote_ip = request.META['REMOTE_ADDR'] remote_ip = request.META['REMOTE_ADDR']
# Get the requestor's email address and client, if available. # Get the requestor's identifier and client, if available.
try: try:
email = request._email requestor_for_logs = request._requestor_for_logs
except Exception: except Exception:
email = "unauth" requestor_for_logs = "unauth"
try: try:
client = request.client.name client = request.client.name
except Exception: except Exception:
@@ -302,7 +303,7 @@ class LogRequests(MiddlewareMixin):
content_iter = None content_iter = None
write_log_line(request._log_data, request.path, request.method, write_log_line(request._log_data, request.path, request.method,
remote_ip, email, client, status_code=response.status_code, remote_ip, requestor_for_logs, client, status_code=response.status_code,
error_content=content, error_content_iter=content_iter) error_content=content, error_content_iter=content_iter)
return response return response

3
zerver/models.py
View File

@@ -1176,6 +1176,9 @@ class UserProfile(AbstractBaseUser, PermissionsMixin):
else: else:
return -1 return -1
def format_requestor_for_logs(self) -> str:
return "{}/{}".format(self.realm.string_id, self.id)
def set_password(self, password: Optional[str]) -> None: def set_password(self, password: Optional[str]) -> None:
if password is None: if password is None:
self.set_unusable_password() self.set_unusable_password()

6
zerver/tests/test_decorators.py
View File

@@ -379,7 +379,7 @@ body:
self.assertTrue(rate_limit_mock.called) self.assertTrue(rate_limit_mock.called)
# Verify decorator set the magic _email field used by some of our back end logging. # Verify decorator set the magic _email field used by some of our back end logging.
self.assertEqual(request._email, webhook_bot_email) self.assertEqual(request._requestor_for_logs, webhook_bot.format_requestor_for_logs())
# Verify the main purpose of the decorator, which is that it passed in the # Verify the main purpose of the decorator, which is that it passed in the
# user_profile to my_webhook, allowing it return the correct # user_profile to my_webhook, allowing it return the correct
@@ -1365,7 +1365,7 @@ class TestInternalNotifyView(TestCase):
with self.settings(SHARED_SECRET=secret): with self.settings(SHARED_SECRET=secret):
self.assertTrue(authenticate_notify(req)) self.assertTrue(authenticate_notify(req))
self.assertEqual(self.internal_notify(False, req), self.BORING_RESULT) self.assertEqual(self.internal_notify(False, req), self.BORING_RESULT)
self.assertEqual(req._email, 'internal') self.assertEqual(req._requestor_for_logs, 'internal')
with self.assertRaises(RuntimeError): with self.assertRaises(RuntimeError):
self.internal_notify(True, req) self.internal_notify(True, req)
@@ -1374,7 +1374,7 @@ class TestInternalNotifyView(TestCase):
with self.settings(SHARED_SECRET=secret): with self.settings(SHARED_SECRET=secret):
self.assertTrue(authenticate_notify(req)) self.assertTrue(authenticate_notify(req))
self.assertEqual(self.internal_notify(True, req), self.BORING_RESULT) self.assertEqual(self.internal_notify(True, req), self.BORING_RESULT)
self.assertEqual(req._email, 'internal') self.assertEqual(req._requestor_for_logs, 'internal')
with self.assertRaises(RuntimeError): with self.assertRaises(RuntimeError):
self.internal_notify(False, req) self.internal_notify(False, req)

4
zerver/tests/test_middleware.py
View File

@@ -40,7 +40,7 @@ class SlowQueryTest(ZulipTestCase):
self.log_data['time_started'] = time.time() - self.SLOW_QUERY_TIME self.log_data['time_started'] = time.time() - self.SLOW_QUERY_TIME
write_log_line(self.log_data, path='/socket/open', method='SOCKET', write_log_line(self.log_data, path='/socket/open', method='SOCKET',
remote_ip='123.456.789.012', email='unknown', client_name='?') remote_ip='123.456.789.012', requestor_for_logs='unknown', client_name='?')
last_message = self.get_last_message() last_message = self.get_last_message()
self.assertEqual(last_message.sender.email, "error-bot@zulip.com") self.assertEqual(last_message.sender.email, "error-bot@zulip.com")
self.assertIn("logs", str(last_message.recipient)) self.assertIn("logs", str(last_message.recipient))
@@ -56,7 +56,7 @@ class SlowQueryTest(ZulipTestCase):
mock_logging_info: Mock) -> None: mock_logging_info: Mock) -> None:
self.log_data['time_started'] = time.time() - self.SLOW_QUERY_TIME self.log_data['time_started'] = time.time() - self.SLOW_QUERY_TIME
write_log_line(self.log_data, path='/socket/open', method='SOCKET', write_log_line(self.log_data, path='/socket/open', method='SOCKET',
remote_ip='123.456.789.012', email='unknown', client_name='?') remote_ip='123.456.789.012', requestor_for_logs='unknown', client_name='?')
mock_internal_send_stream_message.assert_not_called() mock_internal_send_stream_message.assert_not_called()
class OpenGraphTest(ZulipTestCase): class OpenGraphTest(ZulipTestCase):

2
zerver/tests/test_queue_worker.py
View File

@@ -96,7 +96,7 @@ class WorkerTest(ZulipTestCase):
worker.setup() worker.setup()
# `write_log_line` is where we publish slow queries to the queue. # `write_log_line` is where we publish slow queries to the queue.
with patch('zerver.middleware.is_slow_query', return_value=True): with patch('zerver.middleware.is_slow_query', return_value=True):
write_log_line(log_data=dict(test='data'), email='test@zulip.com', write_log_line(log_data=dict(test='data'), requestor_for_logs='test@zulip.com',
remote_ip='127.0.0.1', client_name='website', path='/test/', remote_ip='127.0.0.1', client_name='website', path='/test/',
method='GET') method='GET')
worker.start() worker.start()

2
zerver/tornado/handlers.py
View File

@@ -218,7 +218,7 @@ class AsyncDjangoHandler(tornado.web.RequestHandler, base.BaseHandler):
request._log_data = old_request._log_data request._log_data = old_request._log_data
if hasattr(request, "_rate_limit"): if hasattr(request, "_rate_limit"):
request._rate_limit = old_request._rate_limit request._rate_limit = old_request._rate_limit
request._email = old_request._email request._requestor_for_logs = old_request._requestor_for_logs
request.user = old_request.user request.user = old_request.user
request.client = old_request.client request.client = old_request.client

2
zerver/tornado/views.py
View File

@@ -37,7 +37,7 @@ def cleanup_event_queue(request: HttpRequest, user_profile: UserProfile,
def get_events_internal(request: HttpRequest, def get_events_internal(request: HttpRequest,
user_profile_id: int = REQ(validator=check_int)) -> HttpResponse: user_profile_id: int = REQ(validator=check_int)) -> HttpResponse:
user_profile = get_user_profile_by_id(user_profile_id) user_profile = get_user_profile_by_id(user_profile_id)
request._email = user_profile.delivery_email request._requestor_for_logs = user_profile.format_requestor_for_logs()
process_client(request, user_profile, client_name="internal") process_client(request, user_profile, client_name="internal")
return get_events_backend(request, user_profile) return get_events_backend(request, user_profile)

4
zerver/views/auth.py
View File

@@ -309,7 +309,7 @@ def finish_mobile_flow(request: HttpRequest, user_profile: UserProfile, otp: str
# Mark this request as having a logged-in user for our server logs. # Mark this request as having a logged-in user for our server logs.
process_client(request, user_profile) process_client(request, user_profile)
request._email = user_profile.delivery_email request._requestor_for_logs = user_profile.format_requestor_for_logs()
return response return response
@@ -920,7 +920,7 @@ def api_fetch_api_key(request: HttpRequest, username: str=REQ(), password: str=R
# Mark this request as having a logged-in user for our server logs. # Mark this request as having a logged-in user for our server logs.
process_client(request, user_profile) process_client(request, user_profile)
request._email = user_profile.delivery_email request._requestor_for_logs = user_profile.format_requestor_for_logs()
api_key = get_api_key(user_profile) api_key = get_api_key(user_profile)
return json_success({"api_key": api_key, "email": user_profile.delivery_email}) return json_success({"api_key": api_key, "email": user_profile.delivery_email})