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()
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()
