def respond_send_message(data): # type: (Mapping[str, Any]) -> None log_data = data['server_meta']['log_data'] record_request_restart_data(log_data) worker_log_data = data['server_meta']['worker_log_data'] forward_queue_delay = worker_log_data['time_started'] - log_data['time_stopped'] return_queue_delay = log_data['time_restarted'] - data['server_meta']['time_request_finished'] service_time = data['server_meta']['time_request_finished'] - worker_log_data['time_started'] log_data['extra'] += ', queue_delay: %s/%s, service_time: %s]' % ( format_timedelta(forward_queue_delay), format_timedelta(return_queue_delay), format_timedelta(service_time)) client_id = data['server_meta']['client_id'] connection = get_connection(client_id) if connection is None: logger.info("Could not find connection to send response to! client_id=%s" % (client_id,)) else: connection.session.send_message({'req_id': data['req_id'], 'type': 'response', 'response': data['response']}) # TODO: Fill in client name # TODO: Maybe fill in the status code correctly write_log_line(log_data, path='/socket/service_request', method='SOCKET', remote_ip=connection.session.conn_info.ip, email=connection.session.user_profile.email, client_name='?')
def on_open(self, info): # type: (ConnectionInfo) -> None log_data = dict(extra='[transport=%s]' % (self.session.transport_name,)) record_request_start_data(log_data) ioloop = tornado.ioloop.IOLoop.instance() self.authenticated = False self.session.user_profile = None self.close_info = None # type: CloseErrorInfo self.did_close = False try: self.browser_session_id = info.get_cookie(settings.SESSION_COOKIE_NAME).value self.csrf_token = info.get_cookie(settings.CSRF_COOKIE_NAME).value except AttributeError: # The request didn't contain the necessary cookie values. We can't # close immediately because sockjs-tornado doesn't expect a close # inside on_open(), so do it on the next tick. self.close_info = CloseErrorInfo(403, "Initial cookie lacked required values") ioloop.add_callback(self.close) return def auth_timeout(): # type: () -> None self.close_info = CloseErrorInfo(408, "Timeout while waiting for authentication") self.close() self.timeout_handle = ioloop.add_timeout(time.time() + 10, auth_timeout) write_log_line(log_data, path='/socket/open', method='SOCKET', remote_ip=info.ip, email='unknown', client_name='?')
def test_slow_query_log(self, mock_logging_info: Mock) -> None: self.log_data['time_started'] = time.time() - self.SLOW_QUERY_TIME write_log_line(self.log_data, path='/socket/open', method='SOCKET', remote_ip='123.456.789.012', email='unknown', client_name='?') last_message = self.get_last_message() self.assertEqual(last_message.sender.email, "*****@*****.**") self.assertIn("logs", str(last_message.recipient)) self.assertEqual(last_message.topic_name(), "testserver: slow queries") self.assertRegexpMatches(last_message.content, r"123\.456\.789\.012 SOCKET 200 10\.\ds .*")
def on_close(self) -> None: log_data = dict(extra='[transport=%s]' % (self.session.transport_name,)) record_request_start_data(log_data) if self.close_info is not None: write_log_line(log_data, path='/socket/close', method='SOCKET', remote_ip=self.session.conn_info.ip, email='unknown', client_name='?', status_code=self.close_info.status_code, error_content=self.close_info.err_msg) else: deregister_connection(self) email = self.session.user_profile.email \ if self.session.user_profile is not None else 'unknown' write_log_line(log_data, path='/socket/close', method='SOCKET', remote_ip=self.session.conn_info.ip, email=email, client_name='?') self.did_close = True
def on_message(self, msg_raw): # type: (str) -> None log_data = dict(extra='[transport=%s' % (self.session.transport_name,)) record_request_start_data(log_data) msg = ujson.loads(msg_raw) if self.did_close: logger.info("Received message on already closed socket! transport=%s user=%s client_id=%s" % (self.session.transport_name, self.session.user_profile.email if self.session.user_profile is not None else 'unknown', self.client_id)) self.session.send_message({'req_id': msg['req_id'], 'type': 'ack'}) if msg['type'] == 'auth': log_data['extra'] += ']' try: self.authenticate_client(msg) # TODO: Fill in the correct client write_log_line(log_data, path='/socket/auth', method='SOCKET', remote_ip=self.session.conn_info.ip, email=self.session.user_profile.email, client_name='?') except SocketAuthError as e: response = {'result': 'error', 'msg': e.msg} self.session.send_message({'req_id': msg['req_id'], 'type': 'response', 'response': response}) write_log_line(log_data, path='/socket/auth', method='SOCKET', remote_ip=self.session.conn_info.ip, email='unknown', client_name='?', status_code=403, error_content=ujson.dumps(response)) return else: if not self.authenticated: response = {'result': 'error', 'msg': "Not yet authenticated"} self.session.send_message({'req_id': msg['req_id'], 'type': 'response', 'response': response}) write_log_line(log_data, path='/socket/service_request', method='SOCKET', remote_ip=self.session.conn_info.ip, email='unknown', client_name='?', status_code=403, error_content=ujson.dumps(response)) return redis_key = req_redis_key(msg['req_id']) with redis_client.pipeline() as pipeline: pipeline.hmset(redis_key, {'status': 'received'}) pipeline.expire(redis_key, 60 * 60 * 24) pipeline.execute() record_request_stop_data(log_data) queue_json_publish("message_sender", dict(request=msg['request'], req_id=msg['req_id'], server_meta=dict(user_id=self.session.user_profile.id, client_id=self.client_id, return_queue="tornado_return", log_data=log_data, request_environ=dict(REMOTE_ADDR=self.session.conn_info.ip))), fake_message_sender)
def respond_send_message(data): log_data = data['server_meta']['log_data'] record_request_restart_data(log_data) worker_log_data = data['server_meta']['worker_log_data'] forward_queue_delay = worker_log_data['time_started'] - log_data[ 'time_stopped'] return_queue_delay = log_data['time_restarted'] - data['server_meta'][ 'time_request_finished'] service_time = data['server_meta'][ 'time_request_finished'] - worker_log_data['time_started'] log_data['extra'] += ', queue_delay: %s/%s, service_time: %s]' % ( format_timedelta(forward_queue_delay), format_timedelta(return_queue_delay), format_timedelta(service_time)) client_id = data['server_meta']['client_id'] connection = get_connection(client_id) if connection is None: logger.info( "Could not find connection to send response to! client_id=%s" % (client_id, )) else: connection.session.send_message({ 'req_id': data['req_id'], 'type': 'response', 'response': data['response'] }) # TODO: Fill in client name # TODO: Maybe fill in the status code correctly write_log_line(log_data, path='/socket/service_request', method='SOCKET', remote_ip=connection.session.conn_info.ip, email=connection.session.user_profile.email, client_name='?')
def test_slow_queries_worker(self) -> None: error_bot = get_system_bot(settings.ERROR_BOT) fake_client = self.FakeClient() worker = SlowQueryWorker() create_stream_if_needed(error_bot.realm, 'errors') send_mock = patch( 'zerver.worker.queue_processors.internal_send_stream_message' ) with send_mock as sm, loopworker_sleep_mock as tm: with simulated_queue_client(lambda: fake_client): try: worker.setup() # `write_log_line` is where we publish slow queries to the queue. with patch('zerver.middleware.is_slow_query', return_value=True): write_log_line(log_data=dict(test='data'), requestor_for_logs='*****@*****.**', remote_ip='127.0.0.1', client_name='website', path='/test/', method='GET') worker.start() except AbortLoop: pass self.assertEqual(tm.call_args[0][0], 60) # should sleep 60 seconds sm.assert_called_once() args = [c[0] for c in sm.call_args_list][0] self.assertEqual(args[0], error_bot.realm) self.assertEqual(args[1].email, error_bot.email) self.assertEqual(args[2].name, "errors") self.assertEqual(args[3], "testserver: slow queries") # Testing for specific query times can lead to test discrepancies. logging_info = re.sub(r'\(db: [0-9]+ms/\d+q\)', '', args[4]) self.assertEqual(logging_info, ' 127.0.0.1 GET 200 -1000ms ' ' /test/ ([email protected] via website) ([email protected])\n')
def on_message(self, msg_raw: str) -> None: log_data = dict(extra='[transport=%s' % (self.session.transport_name, )) record_request_start_data(log_data) msg = ujson.loads(msg_raw) if self.did_close: user_email = 'unknown' if self.session.user_profile is not None: user_email = self.session.user_profile.email logger.info( "Received message on already closed socket! transport=%s user=%s client_id=%s" % (self.session.transport_name, user_email, self.client_id)) self.session.send_message({'req_id': msg['req_id'], 'type': 'ack'}) if msg['type'] == 'auth': log_data['extra'] += ']' try: self.authenticate_client(msg) # TODO: Fill in the correct client write_log_line(log_data, path='/socket/auth', method='SOCKET', remote_ip=self.session.conn_info.ip, email=self.session.user_profile.email, client_name='?') except JsonableError as e: response = e.to_json() self.session.send_message({ 'req_id': msg['req_id'], 'type': 'response', 'response': response }) write_log_line(log_data, path='/socket/auth', method='SOCKET', remote_ip=self.session.conn_info.ip, email='unknown', client_name='?', status_code=403, error_content=ujson.dumps(response)) return else: if not self.authenticated: response = {'result': 'error', 'msg': "Not yet authenticated"} self.session.send_message({ 'req_id': msg['req_id'], 'type': 'response', 'response': response }) write_log_line(log_data, path='/socket/service_request', method='SOCKET', remote_ip=self.session.conn_info.ip, email='unknown', client_name='?', status_code=403, error_content=ujson.dumps(response)) return redis_key = req_redis_key(msg['req_id']) with redis_client.pipeline() as pipeline: pipeline.hmset(redis_key, {'status': 'received'}) pipeline.expire(redis_key, 60 * 60 * 24) pipeline.execute() record_request_stop_data(log_data) request_environ = dict(REMOTE_ADDR=self.session.conn_info.ip) queue_json_publish( "message_sender", dict(request=msg['request'], req_id=msg['req_id'], server_meta=dict(user_id=self.session.user_profile.id, client_id=self.client_id, return_queue="tornado_return", log_data=log_data, request_environ=request_environ)))
def test_slow_query_log_without_error_bot(self, mock_internal_send_message: Mock, mock_logging_info: Mock) -> None: self.log_data['time_started'] = time.time() - self.SLOW_QUERY_TIME write_log_line(self.log_data, path='/socket/open', method='SOCKET', remote_ip='123.456.789.012', email='unknown', client_name='?') mock_internal_send_message.assert_not_called()