diff --git a/.eslintrc.json b/.eslintrc.json index 1334de11aa..849ef5b259 100644 --- a/.eslintrc.json +++ b/.eslintrc.json @@ -57,6 +57,7 @@ "typing_events": false, "typing_data": false, "typing_status": false, + "sent_messages": false, "compose": false, "compose_actions": false, "compose_state": false, diff --git a/frontend_tests/node_tests/compose.js b/frontend_tests/node_tests/compose.js index 7c2034aee4..4a47c916c3 100644 --- a/frontend_tests/node_tests/compose.js +++ b/frontend_tests/node_tests/compose.js @@ -34,6 +34,11 @@ set_global('stream_edit', {}); set_global('markdown', {}); set_global('loading', {}); +set_global('sent_messages', { + start_tracking_message: noop, + report_server_ack: noop, +}); + // Setting these up so that we can test that links to uploads within messages are // automatically converted to server relative links. global.document.location.protocol = 'https:'; @@ -261,72 +266,23 @@ people.add(bob); $("#send-status").show(); $("#compose-send-button").attr('disabled', 'disabled'); $("#sending-indicator").show(); - var set_timeout_called = false; - global.patch_builtin('setTimeout', function (func, delay) { - assert.equal(delay, 5000); - func(); - set_timeout_called = true; - }); - var server_events_triggered; - global.server_events = { - restart_get_events: function () { - server_events_triggered = true; - }, - }; + var reify_message_id_checked; echo.reify_message_id = function (local_id, message_id) { assert.equal(local_id, 1001); assert.equal(message_id, 12); reify_message_id_checked = true; }; - var test_date = 'Wed Jun 28 2017 22:12:48 GMT+0000 (UTC)'; - compose.send_message_success(1001, 12, new Date(test_date), false); + + compose.send_message_success(1001, 12, false); + assert.equal($("#new_message_content").val(), ''); assert($("#new_message_content").is_focused()); assert(!$("#send-status").visible()); assert.equal($("#compose-send-button").prop('disabled'), false); assert(!$("#sending-indicator").visible()); - assert.equal(_.keys(compose.send_times_data).length, 1); - assert.equal(compose.send_times_data[12].start.getTime(), new Date(test_date).getTime()); - assert(!compose.send_times_data[12].locally_echoed); + assert(reify_message_id_checked); - assert(server_events_triggered); - assert(set_timeout_called); -}()); - -(function test_mark_rendered_content_disparity() { - compose.mark_rendered_content_disparity(13, true); - assert.deepEqual(compose.send_times_data[13], { rendered_content_disparity: true }); -}()); - -(function test_report_as_received() { - var msg = { - id: 12, - sent_by_me: true, - }; - var set_timeout_called = false; - global.patch_builtin('setTimeout', function (func, delay) { - assert.equal(delay, 0); - func(); - set_timeout_called = true; - }); - compose.send_times_data[12].locally_echoed = true; - channel.post = function (payload) { - assert.equal(payload.url, '/json/report_send_time'); - assert.equal(typeof(payload.data.time), 'string'); - assert(payload.data.locally_echoed); - assert(!payload.data.rendered_content_disparity); - }; - compose.report_as_received(msg); - assert.equal(typeof(compose.send_times_data[12].received), 'object'); - assert.equal(typeof(compose.send_times_data[12].displayed), 'object'); - assert(set_timeout_called); - - delete compose.send_times_data[13]; - msg.id = 13; - compose.report_as_received(msg); - assert.equal(typeof(compose.send_times_data[13].received), 'object'); - assert.equal(typeof(compose.send_times_data[13].displayed), 'object'); }()); (function test_send_message() { @@ -337,7 +293,6 @@ people.add(bob); stub_state.local_id_counter = 0; stub_state.send_msg_ajax_post_called = 0; stub_state.get_events_running_called = 0; - stub_state.server_events_triggered = 0; stub_state.reify_message_id_checked = 0; return stub_state; } @@ -346,9 +301,6 @@ people.add(bob); func(); }); global.server_events = { - restart_get_events: function () { - stub_state.server_events_triggered += 1; - }, assert_get_events_running: function () { stub_state.get_events_running_called += 1; }, @@ -392,7 +344,7 @@ people.add(bob); assert.equal(typeof(message_id), 'number'); stub_state.reify_message_id_checked += 1; }; - compose.send_times_data = {}; + // Setting message content with a host server link and we will assert // later that this has been converted to a relative link. $("#new_message_content").val('[foobar]' + @@ -409,10 +361,8 @@ people.add(bob); get_events_running_called: 1, reify_message_id_checked: 1, send_msg_ajax_post_called: 1, - server_events_triggered: 1, }; assert.deepEqual(stub_state, state); - assert.equal(_.keys(compose.send_times_data).length, 1); assert.equal($("#new_message_content").val(), ''); assert($("#new_message_content").is_focused()); assert(!$("#send-status").visible()); @@ -444,10 +394,8 @@ people.add(bob); get_events_running_called: 1, reify_message_id_checked: 0, send_msg_ajax_post_called: 1, - server_events_triggered: 0, }; assert.deepEqual(stub_state, state); - assert.equal(_.keys(compose.send_times_data).length, 1); assert(server_error_triggered); assert(reload_initiate_triggered); }()); @@ -485,10 +433,8 @@ people.add(bob); get_events_running_called: 1, reify_message_id_checked: 0, send_msg_ajax_post_called: 1, - server_events_triggered: 0, }; assert.deepEqual(stub_state, state); - assert.equal(_.keys(compose.send_times_data).length, 1); assert(server_error_triggered); assert(!reload_initiate_triggered); assert(xhr_error_msg_checked); @@ -511,6 +457,10 @@ people.add(bob); return; }; + sent_messages.get_new_local_id = function () { + return 'loc-55'; + }; + compose.send_message(); var state = { @@ -518,10 +468,8 @@ people.add(bob); get_events_running_called: 1, reify_message_id_checked: 0, send_msg_ajax_post_called: 1, - server_events_triggered: 0, }; assert.deepEqual(stub_state, state); - assert.equal(_.keys(compose.send_times_data).length, 1); assert(server_error_triggered); assert(!reload_initiate_triggered); assert(xhr_error_msg_checked); @@ -792,9 +740,10 @@ function test_with_mock_socket(test_params) { // socket_user_agent field will be added. var request = {foo: 'bar'}; - // Our success function gets passed all the way through to - // socket.send, so we can just use a stub to test that. - var success = 'success-function-stub'; + var success_func_checked = false; + var success = function () { + success_func_checked = true; + }; // Our error function gets wrapped, so we set up a real // function to test the wrapping mechanism. @@ -818,8 +767,8 @@ function test_with_mock_socket(test_params) { socket_user_agent: 'unittest_transmit_message', }); - // Our success function never gets wrapped. - assert.equal(send_args.success, success); + send_args.success({}); + assert(success_func_checked); // Our error function does get wrapped, so we test by // using socket.send's error callback, which should @@ -1258,25 +1207,6 @@ function test_with_mock_socket(test_params) { assert($("#markdown_preview").visible()); }()); - (function test_message_id_changed_document() { - var handler = $(document).get_on_handler('message_id_changed'); - compose.send_times_data = { - 1031: { - data: 'Test data!', - }, - }; - event.old_id = 1031; - event.new_id = 1045; - - handler(event); - - var send_times_data = { - 1045: { - data: 'Test data!', - }, - }; - assert.deepEqual(compose.send_times_data, send_times_data); - }()); }()); (function test_upload_started() { diff --git a/static/js/compose.js b/static/js/compose.js index 067c63c5c3..a61581f38d 100644 --- a/static/js/compose.js +++ b/static/js/compose.js @@ -179,20 +179,6 @@ function send_message_ajax(request, success, error) { }); } -function report_send_time(send_time, receive_time, display_time, locally_echoed, rendered_changed) { - var data = {time: send_time.toString(), - received: receive_time.toString(), - displayed: display_time.toString(), - locally_echoed: locally_echoed}; - if (locally_echoed) { - data.rendered_content_disparity = rendered_changed; - } - channel.post({ - url: '/json/report_send_time', - data: data, - }); -} - var socket; if (page_params.use_websockets) { socket = new Socket("/sockjs"); @@ -211,61 +197,6 @@ function send_message_socket(request, success, error) { }); } -exports.send_times_data = {}; -function maybe_report_send_times(message_id) { - var data = exports.send_times_data[message_id]; - if (data.send_finished === undefined || data.received === undefined || - data.displayed === undefined) { - // We report the data once we have both the send and receive times - return; - } - report_send_time(data.send_finished - data.start, - data.received - data.start, - data.displayed - data.start, - data.locally_echoed, - data.rendered_content_disparity || false); -} - -function mark_end_to_end_receive_time(message_id) { - if (exports.send_times_data[message_id] === undefined) { - exports.send_times_data[message_id] = {}; - } - exports.send_times_data[message_id].received = new Date(); - maybe_report_send_times(message_id); -} - -function mark_end_to_end_display_time(message_id) { - exports.send_times_data[message_id].displayed = new Date(); - maybe_report_send_times(message_id); -} - -exports.mark_rendered_content_disparity = function (message_id, changed) { - if (exports.send_times_data[message_id] === undefined) { - exports.send_times_data[message_id] = {}; - } - exports.send_times_data[message_id].rendered_content_disparity = changed; -}; - -exports.report_as_received = function report_as_received(message) { - if (message.sent_by_me) { - mark_end_to_end_receive_time(message.id); - setTimeout(function () { - mark_end_to_end_display_time(message.id); - }, 0); - } -}; - -function process_send_time(message_id, start_time, locally_echoed) { - var send_finished = new Date(); - if (exports.send_times_data[message_id] === undefined) { - exports.send_times_data[message_id] = {}; - } - exports.send_times_data[message_id].start = start_time; - exports.send_times_data[message_id].send_finished = send_finished; - exports.send_times_data[message_id].locally_echoed = locally_echoed; - maybe_report_send_times(message_id); -} - function clear_compose_box() { $("#new_message_content").val('').focus(); drafts.delete_draft_after_send(); @@ -276,25 +207,25 @@ function clear_compose_box() { resize.resize_bottom_whitespace(); } -exports.send_message_success = function (local_id, message_id, start_time, locally_echoed) { +exports.send_message_success = function (local_id, message_id, locally_echoed) { if (!locally_echoed) { clear_compose_box(); } - process_send_time(message_id, start_time, locally_echoed); - echo.reify_message_id(local_id, message_id); - - setTimeout(function () { - if (exports.send_times_data[message_id].received === undefined) { - blueslip.log("Restarting get_events due to delayed receipt of sent message " + message_id); - server_events.restart_get_events(); - } - }, 5000); }; -exports.transmit_message = function (request, success, error) { - delete exports.send_times_data[request.id]; +exports.transmit_message = function (request, on_success, error) { + + function success(data) { + // Call back to our callers to do things like closing the compose + // box and turning off spinners and reifying locally echoed messages. + on_success(data); + + // Once everything is done, get ready to report times to the server. + sent_messages.report_server_ack(request.local_id); + } + if (page_params.use_websockets) { send_message_socket(request, success, error); } else { @@ -313,27 +244,41 @@ exports.send_message = function send_message(request) { request.to = JSON.stringify([request.to]); } - var start_time = new Date(); var local_id; + var locally_echoed; local_id = echo.try_deliver_locally(request); - if (local_id !== undefined) { - // We delivered this message locally - request.local_id = local_id; + if (local_id) { + // We are rendering this message locally with an id + // like 92l99.01 that corresponds to a reasonable + // approximation of the id we'll get from the server + // in terms of sorting messages. + locally_echoed = true; + } else { + // We are not rendering this message locally, but we + // track the message's life cycle with an id like + // loc-1, loc-2, loc-3,etc. + locally_echoed = false; + local_id = sent_messages.get_new_local_id(); } - var locally_echoed = local_id !== undefined; + request.local_id = local_id; + + sent_messages.start_tracking_message({ + local_id: local_id, + locally_echoed: locally_echoed, + }); request.locally_echoed = locally_echoed; function success(data) { - exports.send_message_success(local_id, data.id, start_time, locally_echoed); + exports.send_message_success(local_id, data.id, locally_echoed); } function error(response) { // If we're not local echo'ing messages, or if this message was not // locally echoed, show error in compose box - if (!request.locally_echoed) { + if (!locally_echoed) { compose_error(response, $('#new_message_content')); return; } @@ -893,15 +838,6 @@ exports.initialize = function () { compose_actions.start("stream", {}); } } - - $(document).on('message_id_changed', function (event) { - if (exports.send_times_data[event.old_id] !== undefined) { - var value = exports.send_times_data[event.old_id]; - delete exports.send_times_data[event.old_id]; - exports.send_times_data[event.new_id] = - _.extend({}, exports.send_times_data[event.old_id], value); - } - }); }; return exports; diff --git a/static/js/echo.js b/static/js/echo.js index 170772e0d3..b3e9909a68 100644 --- a/static/js/echo.js +++ b/static/js/echo.js @@ -9,26 +9,34 @@ function resend_message(message, row) { message.content = message.raw_content; var retry_spinner = row.find('.refresh-failed-message'); retry_spinner.toggleClass('rotating', true); + // Always re-set queue_id if we've gotten a new one // since the time when the message object was initially created message.queue_id = page_params.queue_id; - var start_time = new Date(); - compose.transmit_message(message, function success(data) { - retry_spinner.toggleClass('rotating', false); + var local_id = message.local_id; + + function on_success(data) { var message_id = data.id; + var locally_echoed = true; retry_spinner.toggleClass('rotating', false); - compose.send_message_success(message.local_id, message_id, start_time, true); + + compose.send_message_success(local_id, message_id, locally_echoed); // Resend succeeded, so mark as no longer failed message_store.get(message_id).failed_request = false; ui.show_failed_message_success(message_id); - }, function error(response) { - exports.message_send_error(message.local_id, response); + } + + function on_error(response) { + exports.message_send_error(local_id, response); retry_spinner.toggleClass('rotating', false); blueslip.log("Manual resend of message failed"); - }); + } + + sent_messages.start_resend(local_id); + compose.transmit_message(message, on_success, on_error); } function truncate_precision(float) { @@ -205,18 +213,18 @@ exports.process_from_server = function process_from_server(messages) { var msgs_to_rerender = []; messages = _.filter(messages, function (message) { // In case we get the sent message before we get the send ACK, reify here - exports.reify_message_id(message.local_id, message.id); var client_message = waiting_for_ack[message.local_id]; if (client_message !== undefined) { + exports.reify_message_id(message.local_id, message.id); + if (client_message.content !== message.content) { client_message.content = message.content; updated = true; - compose.mark_rendered_content_disparity(message.id, true); + sent_messages.mark_disparity(message.local_id); } msgs_to_rerender.push(client_message); locally_processed_ids.push(client_message.id); - compose.report_as_received(client_message); delete waiting_for_ack[client_message.id]; return false; } diff --git a/static/js/message_util.js b/static/js/message_util.js index 16c74fc7af..6ff722e26d 100644 --- a/static/js/message_util.js +++ b/static/js/message_util.js @@ -19,14 +19,6 @@ exports.add_messages = function add_messages(messages, msg_list, opts) { $('#first_run_message').remove(); msg_list.add_messages(messages, opts); - - if (msg_list === home_msg_list && opts.messages_are_new) { - _.each(messages, function (message) { - if (message.local_id === undefined) { - compose.report_as_received(message); - } - }); - } }; diff --git a/static/js/sent_messages.js b/static/js/sent_messages.js new file mode 100644 index 0000000000..82d7de922f --- /dev/null +++ b/static/js/sent_messages.js @@ -0,0 +1,184 @@ +var sent_messages = (function () { + +var exports = {}; + +exports.messages = {}; + +exports.reset_id_state = function () { + exports.next_local_id = 0; +}; + +exports.get_new_local_id = function () { + exports.next_local_id += 1; + var local_id = exports.next_local_id; + return 'loc-' + local_id.toString(); +}; + +function report_send_time(send_time, receive_time, + locally_echoed, rendered_changed) { + var data = { + time: send_time.toString(), + received: receive_time.toString(), + locally_echoed: locally_echoed, + }; + + if (locally_echoed) { + data.rendered_content_disparity = rendered_changed; + } + + channel.post({ + url: '/json/report_send_time', + data: data, + }); +} + +exports.start_tracking_message = function (opts) { + var local_id = opts.local_id; + + if (!opts.local_id) { + blueslip.error('You must supply a local_id'); + return; + } + + if (exports.messages[local_id] !== undefined) { + blueslip.error('We are re-using a local_id'); + return; + } + + var state = exports.message_state(opts); + + exports.messages[local_id] = state; +}; + +exports.message_state = function (opts) { + var self = {}; + self.data = {}; + + self.data.start = new Date(); + + self.data.local_id = opts.local_id; + self.data.locally_echoed = opts.locally_echoed; + + + self.data.received = undefined; + self.data.send_finished = undefined; + self.data.rendered_content_disparity = false; + + self.start_resend = function () { + self.data.start = new Date(); + self.data.received = undefined; + self.data.send_finished = undefined; + self.data.rendered_content_disparity = false; + }; + + self.maybe_restart_event_loop = function () { + if (self.data.received) { + // We got our event, no need to do anything + return; + } + + blueslip.log("Restarting get_events due to " + + "delayed receipt of sent message " + + self.data.local_id); + + server_events.restart_get_events(); + }; + + self.maybe_report_send_times = function () { + if (!self.ready()) { + return; + } + var data = self.data; + report_send_time(data.send_finished - data.start, + data.received - data.start, + data.locally_echoed, + data.rendered_content_disparity); + }; + + self.report_event_received = function () { + self.data.received = new Date(); + self.maybe_report_send_times(); + }; + + self.mark_disparity = function () { + self.data.rendered_content_disparity = true; + }; + + self.report_server_ack = function () { + self.data.send_finished = new Date(); + self.maybe_report_send_times(); + + // We only start our timer for events coming in here, + // since it's plausible the server rejected our message, + // or took a while to process it, but there is nothing + // wrong with our event loop. + + if (!self.data.received) { + setTimeout(self.maybe_restart_event_loop, 5000); + } + }; + + self.ready = function () { + return (self.data.send_finished !== undefined) && + (self.data.received !== undefined); + }; + + return self; +}; + +exports.get_message_state = function (local_id) { + var state = exports.messages[local_id]; + + if (!state) { + blueslip.warn('Unknown local_id: ' + local_id); + } + + return state; +}; + + +exports.mark_disparity = function (local_id) { + var state = exports.get_message_state(local_id); + if (!state) { + return; + } + state.mark_disparity(); +}; + +exports.report_event_received = function (local_id) { + var state = exports.get_message_state(local_id); + if (!state) { + return; + } + + state.report_event_received(); +}; + +exports.start_resend = function (local_id) { + var state = exports.get_message_state(local_id); + if (!state) { + return; + } + + state.start_resend(); +}; + +exports.report_server_ack = function (local_id) { + var state = exports.get_message_state(local_id); + if (!state) { + return; + } + + state.report_server_ack(); +}; + +exports.initialize = function () { + exports.reset_id_state(); +}; + +return exports; + +}()); +if (typeof module !== 'undefined') { + module.exports = sent_messages; +} diff --git a/static/js/server_events.js b/static/js/server_events.js index ee3636adb9..150cc25eac 100644 --- a/static/js/server_events.js +++ b/static/js/server_events.js @@ -68,8 +68,9 @@ function get_events_success(events) { case 'message': var msg = event.message; msg.flags = event.flags; - if (event.local_message_id !== undefined) { + if (event.local_message_id) { msg.local_id = event.local_message_id; + sent_messages.report_event_received(event.local_message_id); } messages.push(msg); break; diff --git a/static/js/ui_init.js b/static/js/ui_init.js index 9875f86989..15f86b22d9 100644 --- a/static/js/ui_init.js +++ b/static/js/ui_init.js @@ -267,6 +267,7 @@ $(function () { pm_list.initialize(); stream_list.initialize(); drafts.initialize(); + sent_messages.initialize(); compose.initialize(); }); diff --git a/zproject/settings.py b/zproject/settings.py index bc22b2969d..789530e5af 100644 --- a/zproject/settings.py +++ b/zproject/settings.py @@ -873,6 +873,7 @@ JS_SPECS = { 'js/markdown.js', 'js/echo.js', 'js/socket.js', + 'js/sent_messages.js', 'js/compose_state.js', 'js/compose_actions.js', 'js/compose.js',