Report proper displayed/receive time and local echo data

(imported from commit 63aba6ef05b1a55d61e975831ebbaa074f8ea74f)

static/js/compose.js

@@ -379,12 +379,17 @@ function send_message_ajax(request, success, error) {
     });
 }
 
-function report_send_time(send_time, receive_time, display_time) {
+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: {"time": send_time.toString(),
+        data: data
-               "received": receive_time.toString(),
-               "displayed": display_time.toString()}
     });
 }
 
@@ -416,7 +421,9 @@ function maybe_report_send_times(message_id) {
     }
     report_send_time(data.send_finished - data.start,
                      data.received - data.start,
-                     data.displayed - data.start);
+                     data.displayed - data.start,
+                     data.locally_echoed,
+                     data.rendered_content_disparity || false);
 }
 
 exports.mark_end_to_end_receive_time = function (message_id) {
@@ -435,7 +442,14 @@ exports.mark_end_to_end_display_time = function (message_id) {
     maybe_report_send_times(message_id);
 };
 
-function process_send_time(message_id, start_time) {
+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;
+};
+
+function process_send_time(message_id, start_time, locally_echoed) {
     var send_finished = new Date();
     var send_time = (send_finished - start_time);
     if (feature_flags.log_send_times) {
@@ -449,6 +463,7 @@ function process_send_time(message_id, start_time) {
     }
     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);
 }
 
@@ -462,12 +477,12 @@ function clear_compose_box() {
     ui.resize_bottom_whitespace();
 }
 
-exports.send_message_success = function (local_id, message_id, start_time) {
+exports.send_message_success = function (local_id, message_id, start_time, locally_echoed) {
     if (! feature_flags.local_echo) {
         clear_compose_box();
     }
 
-    process_send_time(message_id, start_time);
+    process_send_time(message_id, start_time, locally_echoed);
 
     if (feature_flags.local_echo) {
         echo.reify_message_id(local_id, message_id);
@@ -482,6 +497,7 @@ exports.send_message_success = function (local_id, message_id, start_time) {
 };
 
 exports.transmit_message = function (request, success, error) {
+    delete exports.send_times_data[request.id];
     if (feature_flags.use_socket) {
         send_message_socket(request, success, error);
     } else {
@@ -512,7 +528,7 @@ function send_message(request) {
     }
 
     function success(data) {
-        exports.send_message_success(local_id, data.id, start_time);
+        exports.send_message_success(local_id, data.id, start_time, local_id !== undefined);
     }
 
     function error(response) {

static/js/echo.js

@@ -46,7 +46,7 @@ function resend_message(message, row) {
         var message_id = data.id;
 
         retry_spinner.toggleClass('rotating', false);
-        compose.send_message_success(message.local_id, message_id, start_time);
+        compose.send_message_success(message.local_id, message_id, start_time, true);
 
         // Resend succeeded, so mark as no longer failed
         all_msg_list.get(message_id).failed_request = false;
@@ -177,6 +177,7 @@ exports.process_from_server = function process_from_server(messages) {
             if (client_message.content !== message.content) {
                 client_message.content = message.content;
                 updated = true;
+                compose.mark_rendered_content_disparity(message.id, true);
             }
             // If a PM was sent to an out-of-realm address,
             // we didn't have the full person object originally,
@@ -195,6 +196,7 @@ exports.process_from_server = function process_from_server(messages) {
                 }
             }
             locally_processed_ids.push(client_message.id);
+            report_as_received(client_message);
             delete waiting_for_ack[client_message.id];
             return false;
         }

static/js/zulip.js

@@ -707,6 +707,15 @@ function add_message_metadata(message) {
     return message;
 }
 
+function report_as_received(message) {
+    if (message.sent_by_me) {
+        compose.mark_end_to_end_receive_time(message.id);
+        setTimeout(function () {
+            compose.mark_end_to_end_display_time(message.id);
+        }, 0);
+    }
+}
+
 function add_messages(messages, msg_list, opts) {
     if (!messages) {
         return;
@@ -721,11 +730,8 @@ function add_messages(messages, msg_list, opts) {
 
     if (msg_list === home_msg_list && opts.messages_are_new) {
         _.each(messages, function (message) {
-            if (message.sent_by_me) {
+            if (message.local_id === undefined) {
-                compose.mark_end_to_end_receive_time(message.id);
+                report_as_received(message);
-                setTimeout(function () {
-                    compose.mark_end_to_end_display_time(message.id);
-                }, 0);
             }
         });
     }

tools/jslint/check-all.js

@@ -65,7 +65,7 @@ var globals =
     + ' send_summarize_in_stream'
     + ' suppress_unread_counts'
     + ' msg_metadata_cache'
-    + ' get_updates_xhr get_updates_timeout'
+    + ' get_updates_xhr get_updates_timeout report_as_received'
     + ' insert_new_messages process_message_for_recent_subjects reify_person'
     ;
 

zerver/views/__init__.py

@@ -1581,13 +1581,20 @@ if not (settings.DEBUG or settings.TEST_SUITE):
 def json_report_send_time(request, user_profile,
                           time=REQ(converter=to_non_negative_int),
                           received=REQ(converter=to_non_negative_int, default="(unknown)"),
-                          displayed=REQ(converter=to_non_negative_int, default="(unknown)")):
+                          displayed=REQ(converter=to_non_negative_int, default="(unknown)"),
-    request._log_data["extra"] = "[%sms/%sms/%sms]" % (time, received, displayed)
+                          locally_echoed=REQ(converter=json_to_bool, default=False),
+                          rendered_content_disparity=REQ(converter=json_to_bool, default=False)):
+    request._log_data["extra"] = "[%sms/%sms/%sms/echo:%s/diff:%s]" \
+        % (time, received, displayed, locally_echoed, rendered_content_disparity)
     statsd.timing("endtoend.send_time.%s" % (statsd_key(user_profile.realm.domain, clean_periods=True),), time)
     if received != "(unknown)":
         statsd.timing("endtoend.receive_time.%s" % (statsd_key(user_profile.realm.domain, clean_periods=True),), received)
     if displayed != "(unknown)":
         statsd.timing("endtoend.displayed_time.%s" % (statsd_key(user_profile.realm.domain, clean_periods=True),), displayed)
+    if locally_echoed:
+        statsd.incr('locally_echoed')
+    if rendered_content_disparity:
+        statsd.incr('render_disparity')
     return json_success()
 
 @authenticated_json_post_view