1// Copyright 2014 The Chromium Authors. All rights reserved.
2// Use of this source code is governed by a BSD-style license that can be
3// found in the LICENSE file.
4
5#include "components/gcm_driver/gcm_stats_recorder_impl.h"
6
7#include <deque>
8#include <vector>
9
10#include "base/format_macros.h"
11#include "base/logging.h"
12#include "base/metrics/histogram.h"
13#include "base/strings/string_util.h"
14#include "base/strings/stringprintf.h"
15
16namespace gcm {
17
18const uint32 MAX_LOGGED_ACTIVITY_COUNT = 100;
19const int64 RECEIVED_DATA_MESSAGE_BURST_LENGTH_SECONDS = 2;
20
21namespace {
22
23// Insert an item to the front of deque while maintaining the size of the deque.
24// Overflow item is discarded.
25template <typename T>
26T* InsertCircularBuffer(std::deque<T>* q, const T& item) {
27  DCHECK(q);
28  q->push_front(item);
29  if (q->size() > MAX_LOGGED_ACTIVITY_COUNT) {
30    q->pop_back();
31  }
32  return &q->front();
33}
34
35// Helper for getting string representation of the MessageSendStatus enum.
36std::string GetMessageSendStatusString(
37    gcm::MCSClient::MessageSendStatus status) {
38  switch (status) {
39    case gcm::MCSClient::QUEUED:
40      return "QUEUED";
41    case gcm::MCSClient::SENT:
42      return "SENT";
43    case gcm::MCSClient::QUEUE_SIZE_LIMIT_REACHED:
44      return "QUEUE_SIZE_LIMIT_REACHED";
45    case gcm::MCSClient::APP_QUEUE_SIZE_LIMIT_REACHED:
46      return "APP_QUEUE_SIZE_LIMIT_REACHED";
47    case gcm::MCSClient::MESSAGE_TOO_LARGE:
48      return "MESSAGE_TOO_LARGE";
49    case gcm::MCSClient::NO_CONNECTION_ON_ZERO_TTL:
50      return "NO_CONNECTION_ON_ZERO_TTL";
51    case gcm::MCSClient::TTL_EXCEEDED:
52      return "TTL_EXCEEDED";
53    default:
54      NOTREACHED();
55      return "UNKNOWN";
56  }
57}
58
59// Helper for getting string representation of the
60// ConnectionFactory::ConnectionResetReason enum.
61std::string GetConnectionResetReasonString(
62    gcm::ConnectionFactory::ConnectionResetReason reason) {
63  switch (reason) {
64    case gcm::ConnectionFactory::LOGIN_FAILURE:
65      return "LOGIN_FAILURE";
66    case gcm::ConnectionFactory::CLOSE_COMMAND:
67      return "CLOSE_COMMAND";
68    case gcm::ConnectionFactory::HEARTBEAT_FAILURE:
69      return "HEARTBEAT_FAILURE";
70    case gcm::ConnectionFactory::SOCKET_FAILURE:
71      return "SOCKET_FAILURE";
72    case gcm::ConnectionFactory::NETWORK_CHANGE:
73      return "NETWORK_CHANGE";
74    default:
75      NOTREACHED();
76      return "UNKNOWN_REASON";
77  }
78}
79
80// Helper for getting string representation of the RegistrationRequest::Status
81// enum.
82std::string GetRegistrationStatusString(
83    gcm::RegistrationRequest::Status status) {
84  switch (status) {
85    case gcm::RegistrationRequest::SUCCESS:
86      return "SUCCESS";
87    case gcm::RegistrationRequest::INVALID_PARAMETERS:
88      return "INVALID_PARAMETERS";
89    case gcm::RegistrationRequest::INVALID_SENDER:
90      return "INVALID_SENDER";
91    case gcm::RegistrationRequest::AUTHENTICATION_FAILED:
92      return "AUTHENTICATION_FAILED";
93    case gcm::RegistrationRequest::DEVICE_REGISTRATION_ERROR:
94      return "DEVICE_REGISTRATION_ERROR";
95    case gcm::RegistrationRequest::UNKNOWN_ERROR:
96      return "UNKNOWN_ERROR";
97    case gcm::RegistrationRequest::URL_FETCHING_FAILED:
98      return "URL_FETCHING_FAILED";
99    case gcm::RegistrationRequest::HTTP_NOT_OK:
100      return "HTTP_NOT_OK";
101    case gcm::RegistrationRequest::RESPONSE_PARSING_FAILED:
102      return "RESPONSE_PARSING_FAILED";
103    case gcm::RegistrationRequest::REACHED_MAX_RETRIES:
104      return "REACHED_MAX_RETRIES";
105    default:
106      NOTREACHED();
107      return "UNKNOWN_STATUS";
108  }
109}
110
111// Helper for getting string representation of the RegistrationRequest::Status
112// enum.
113std::string GetUnregistrationStatusString(
114    gcm::UnregistrationRequest::Status status) {
115  switch (status) {
116    case gcm::UnregistrationRequest::SUCCESS:
117      return "SUCCESS";
118    case gcm::UnregistrationRequest::URL_FETCHING_FAILED:
119      return "URL_FETCHING_FAILED";
120    case gcm::UnregistrationRequest::NO_RESPONSE_BODY:
121      return "NO_RESPONSE_BODY";
122    case gcm::UnregistrationRequest::RESPONSE_PARSING_FAILED:
123      return "RESPONSE_PARSING_FAILED";
124    case gcm::UnregistrationRequest::INCORRECT_APP_ID:
125      return "INCORRECT_APP_ID";
126    case gcm::UnregistrationRequest::INVALID_PARAMETERS:
127      return "INVALID_PARAMETERS";
128    case gcm::UnregistrationRequest::SERVICE_UNAVAILABLE:
129      return "SERVICE_UNAVAILABLE";
130    case gcm::UnregistrationRequest::INTERNAL_SERVER_ERROR:
131      return "INTERNAL_SERVER_ERROR";
132    case gcm::UnregistrationRequest::HTTP_NOT_OK:
133      return "HTTP_NOT_OK";
134    case gcm::UnregistrationRequest::UNKNOWN_ERROR:
135      return "UNKNOWN_ERROR";
136    default:
137      NOTREACHED();
138      return "UNKNOWN_STATUS";
139  }
140}
141
142}  // namespace
143
144GCMStatsRecorderImpl::GCMStatsRecorderImpl()
145    : is_recording_(false),
146      delegate_(NULL),
147      data_message_received_since_connected_(false),
148      received_data_message_burst_size_(0) {
149}
150
151GCMStatsRecorderImpl::~GCMStatsRecorderImpl() {
152}
153
154void GCMStatsRecorderImpl::SetRecording(bool recording) {
155  is_recording_ = recording;
156}
157
158void GCMStatsRecorderImpl::SetDelegate(Delegate* delegate) {
159  delegate_ = delegate;
160}
161
162void GCMStatsRecorderImpl::Clear() {
163  checkin_activities_.clear();
164  connection_activities_.clear();
165  registration_activities_.clear();
166  receiving_activities_.clear();
167  sending_activities_.clear();
168}
169
170void GCMStatsRecorderImpl::NotifyActivityRecorded() {
171  if (delegate_)
172    delegate_->OnActivityRecorded();
173}
174
175void GCMStatsRecorderImpl::RecordCheckin(
176    const std::string& event,
177    const std::string& details) {
178  CheckinActivity data;
179  CheckinActivity* inserted_data = InsertCircularBuffer(
180      &checkin_activities_, data);
181  inserted_data->event = event;
182  inserted_data->details = details;
183  NotifyActivityRecorded();
184}
185
186void GCMStatsRecorderImpl::RecordCheckinInitiated(uint64 android_id) {
187  if (!is_recording_)
188    return;
189  RecordCheckin("Checkin initiated",
190                base::StringPrintf("Android Id: %" PRIu64, android_id));
191}
192
193void GCMStatsRecorderImpl::RecordCheckinDelayedDueToBackoff(int64 delay_msec) {
194  if (!is_recording_)
195    return;
196  RecordCheckin("Checkin backoff",
197                base::StringPrintf("Delayed for %" PRId64 " msec",
198                                   delay_msec));
199}
200
201void GCMStatsRecorderImpl::RecordCheckinSuccess() {
202  if (!is_recording_)
203    return;
204  RecordCheckin("Checkin succeeded", std::string());
205}
206
207void GCMStatsRecorderImpl::RecordCheckinFailure(std::string status,
208                                            bool will_retry) {
209  if (!is_recording_)
210    return;
211  RecordCheckin("Checkin failed", base::StringPrintf(
212      "%s.%s",
213      status.c_str(),
214      will_retry ? " Will retry." : "Will not retry."));
215}
216
217void GCMStatsRecorderImpl::RecordConnection(
218    const std::string& event,
219    const std::string& details) {
220  ConnectionActivity data;
221  ConnectionActivity* inserted_data = InsertCircularBuffer(
222      &connection_activities_, data);
223  inserted_data->event = event;
224  inserted_data->details = details;
225  NotifyActivityRecorded();
226}
227
228void GCMStatsRecorderImpl::RecordConnectionInitiated(const std::string& host) {
229  last_connection_initiation_time_ = base::TimeTicks::Now();
230  last_connection_success_time_ = base::TimeTicks();
231  data_message_received_since_connected_ = false;
232  if (!is_recording_)
233    return;
234  RecordConnection("Connection initiated", host);
235}
236
237void GCMStatsRecorderImpl::RecordConnectionDelayedDueToBackoff(
238    int64 delay_msec) {
239  if (!is_recording_)
240    return;
241  RecordConnection("Connection backoff",
242                   base::StringPrintf("Delayed for %" PRId64 " msec",
243                                      delay_msec));
244}
245
246void GCMStatsRecorderImpl::RecordConnectionSuccess() {
247  DCHECK(!last_connection_initiation_time_.is_null());
248  UMA_HISTOGRAM_MEDIUM_TIMES(
249      "GCM.ConnectionLatency",
250      (base::TimeTicks::Now() - last_connection_initiation_time_));
251  last_connection_success_time_ = base::TimeTicks::Now();
252  last_connection_initiation_time_ = base::TimeTicks();
253  if (!is_recording_)
254    return;
255  RecordConnection("Connection succeeded", std::string());
256}
257
258void GCMStatsRecorderImpl::RecordConnectionFailure(int network_error) {
259  if (!is_recording_)
260    return;
261  RecordConnection("Connection failed",
262                   base::StringPrintf("With network error %d", network_error));
263}
264
265void GCMStatsRecorderImpl::RecordConnectionResetSignaled(
266      ConnectionFactory::ConnectionResetReason reason) {
267  if (!is_recording_)
268    return;
269  RecordConnection("Connection reset",
270                   GetConnectionResetReasonString(reason));
271}
272
273void GCMStatsRecorderImpl::RecordRegistration(
274    const std::string& app_id,
275    const std::string& sender_ids,
276    const std::string& event,
277    const std::string& details) {
278  RegistrationActivity data;
279  RegistrationActivity* inserted_data = InsertCircularBuffer(
280      &registration_activities_, data);
281  inserted_data->app_id = app_id;
282  inserted_data->sender_ids = sender_ids;
283  inserted_data->event = event;
284  inserted_data->details = details;
285  NotifyActivityRecorded();
286}
287
288void GCMStatsRecorderImpl::RecordRegistrationSent(
289    const std::string& app_id,
290    const std::string& sender_ids) {
291  UMA_HISTOGRAM_COUNTS("GCM.RegistrationRequest", 1);
292  if (!is_recording_)
293    return;
294  RecordRegistration(app_id, sender_ids,
295                     "Registration request sent", std::string());
296}
297
298void GCMStatsRecorderImpl::RecordRegistrationResponse(
299    const std::string& app_id,
300    const std::vector<std::string>& sender_ids,
301    RegistrationRequest::Status status) {
302  if (!is_recording_)
303    return;
304  RecordRegistration(app_id, JoinString(sender_ids, ","),
305                     "Registration response received",
306                     GetRegistrationStatusString(status));
307}
308
309void GCMStatsRecorderImpl::RecordRegistrationRetryRequested(
310    const std::string& app_id,
311    const std::vector<std::string>& sender_ids,
312    int retries_left) {
313  if (!is_recording_)
314    return;
315  RecordRegistration(app_id, JoinString(sender_ids, ","),
316                     "Registration retry requested",
317                     base::StringPrintf("Retries left: %d", retries_left));
318}
319
320void GCMStatsRecorderImpl::RecordUnregistrationSent(
321    const std::string& app_id) {
322  UMA_HISTOGRAM_COUNTS("GCM.UnregistrationRequest", 1);
323  if (!is_recording_)
324    return;
325  RecordRegistration(app_id, std::string(), "Unregistration request sent",
326                     std::string());
327}
328
329void GCMStatsRecorderImpl::RecordUnregistrationResponse(
330    const std::string& app_id,
331    UnregistrationRequest::Status status) {
332  if (!is_recording_)
333    return;
334  RecordRegistration(app_id,
335                     std::string(),
336                     "Unregistration response received",
337                     GetUnregistrationStatusString(status));
338}
339
340void GCMStatsRecorderImpl::RecordUnregistrationRetryDelayed(
341    const std::string& app_id,
342    int64 delay_msec) {
343  if (!is_recording_)
344    return;
345  RecordRegistration(app_id,
346                     std::string(),
347                     "Unregistration retry delayed",
348                     base::StringPrintf("Delayed for %" PRId64 " msec",
349                                        delay_msec));
350}
351
352void GCMStatsRecorderImpl::RecordReceiving(
353    const std::string& app_id,
354    const std::string& from,
355    int message_byte_size,
356    const std::string& event,
357    const std::string& details) {
358  ReceivingActivity data;
359  ReceivingActivity* inserted_data = InsertCircularBuffer(
360      &receiving_activities_, data);
361  inserted_data->app_id = app_id;
362  inserted_data->from = from;
363  inserted_data->message_byte_size = message_byte_size;
364  inserted_data->event = event;
365  inserted_data->details = details;
366  NotifyActivityRecorded();
367}
368
369void GCMStatsRecorderImpl::RecordDataMessageReceived(
370    const std::string& app_id,
371    const std::string& from,
372    int message_byte_size,
373    bool to_registered_app,
374    ReceivedMessageType message_type) {
375  if (to_registered_app)
376    UMA_HISTOGRAM_COUNTS("GCM.DataMessageReceived", 1);
377
378  base::TimeTicks new_timestamp = base::TimeTicks::Now();
379  if (last_received_data_message_burst_start_time_.is_null()) {
380    last_received_data_message_burst_start_time_ = new_timestamp;
381    last_received_data_message_time_within_burst_ = new_timestamp;
382    received_data_message_burst_size_ = 1;
383  } else if ((new_timestamp - last_received_data_message_burst_start_time_) >=
384             base::TimeDelta::FromSeconds(
385                 RECEIVED_DATA_MESSAGE_BURST_LENGTH_SECONDS)) {
386    UMA_HISTOGRAM_LONG_TIMES(
387        "GCM.DataMessageBurstReceivedInterval",
388        (new_timestamp - last_received_data_message_burst_start_time_));
389    UMA_HISTOGRAM_COUNTS("GCM.ReceivedDataMessageBurstSize",
390                         received_data_message_burst_size_);
391    last_received_data_message_burst_start_time_ = new_timestamp;
392    last_received_data_message_time_within_burst_ = new_timestamp;
393    received_data_message_burst_size_ = 1;
394  } else {
395    UMA_HISTOGRAM_TIMES(
396        "GCM.ReceivedDataMessageIntervalWithinBurst",
397        (new_timestamp - last_received_data_message_time_within_burst_));
398    last_received_data_message_time_within_burst_ = new_timestamp;
399    ++received_data_message_burst_size_;
400  }
401  if (!data_message_received_since_connected_) {
402    DCHECK(!last_connection_success_time_.is_null());
403    UMA_HISTOGRAM_TIMES("GCM.FirstReceivedDataMessageLatencyAfterConnection",
404                        (new_timestamp - last_connection_success_time_));
405    data_message_received_since_connected_ = true;
406  }
407
408  if (!is_recording_)
409    return;
410  if (!to_registered_app) {
411    RecordReceiving(app_id,
412                    from,
413                    message_byte_size,
414                    "Data msg received",
415                    "No such registered app found");
416  } else {
417    switch(message_type) {
418      case GCMStatsRecorderImpl::DATA_MESSAGE:
419        RecordReceiving(app_id, from, message_byte_size, "Data msg received",
420                        std::string());
421        break;
422      case GCMStatsRecorderImpl::DELETED_MESSAGES:
423        RecordReceiving(app_id, from, message_byte_size, "Data msg received",
424                        "Message has been deleted on server");
425        break;
426      default:
427        NOTREACHED();
428    }
429  }
430}
431
432void GCMStatsRecorderImpl::CollectActivities(
433    RecordedActivities* recorder_activities) const {
434  recorder_activities->checkin_activities.insert(
435      recorder_activities->checkin_activities.begin(),
436      checkin_activities_.begin(),
437      checkin_activities_.end());
438  recorder_activities->connection_activities.insert(
439      recorder_activities->connection_activities.begin(),
440      connection_activities_.begin(),
441      connection_activities_.end());
442  recorder_activities->registration_activities.insert(
443      recorder_activities->registration_activities.begin(),
444      registration_activities_.begin(),
445      registration_activities_.end());
446  recorder_activities->receiving_activities.insert(
447      recorder_activities->receiving_activities.begin(),
448      receiving_activities_.begin(),
449      receiving_activities_.end());
450  recorder_activities->sending_activities.insert(
451      recorder_activities->sending_activities.begin(),
452      sending_activities_.begin(),
453      sending_activities_.end());
454}
455
456void GCMStatsRecorderImpl::RecordSending(const std::string& app_id,
457                                         const std::string& receiver_id,
458                                         const std::string& message_id,
459                                         const std::string& event,
460                                         const std::string& details) {
461  SendingActivity data;
462  SendingActivity* inserted_data = InsertCircularBuffer(
463      &sending_activities_, data);
464  inserted_data->app_id = app_id;
465  inserted_data->receiver_id = receiver_id;
466  inserted_data->message_id = message_id;
467  inserted_data->event = event;
468  inserted_data->details = details;
469  NotifyActivityRecorded();
470}
471
472void GCMStatsRecorderImpl::RecordDataSentToWire(
473    const std::string& app_id,
474    const std::string& receiver_id,
475    const std::string& message_id,
476    int queued) {
477  if (!is_recording_)
478    return;
479  RecordSending(app_id, receiver_id, message_id, "Data msg sent to wire",
480                base::StringPrintf("Msg queued for %d seconds", queued));
481}
482
483void GCMStatsRecorderImpl::RecordNotifySendStatus(
484    const std::string& app_id,
485    const std::string& receiver_id,
486    const std::string& message_id,
487    gcm::MCSClient::MessageSendStatus status,
488    int byte_size,
489    int ttl) {
490  UMA_HISTOGRAM_ENUMERATION("GCM.SendMessageStatus", status,
491                            gcm::MCSClient::SEND_STATUS_COUNT);
492  if (!is_recording_)
493    return;
494  RecordSending(
495      app_id,
496      receiver_id,
497      message_id,
498      base::StringPrintf("SEND status: %s",
499                         GetMessageSendStatusString(status).c_str()),
500      base::StringPrintf("Msg size: %d bytes, TTL: %d", byte_size, ttl));
501}
502
503void GCMStatsRecorderImpl::RecordIncomingSendError(
504    const std::string& app_id,
505    const std::string& receiver_id,
506    const std::string& message_id) {
507  UMA_HISTOGRAM_COUNTS("GCM.IncomingSendErrors", 1);
508  if (!is_recording_)
509    return;
510  RecordSending(app_id, receiver_id, message_id, "Received 'send error' msg",
511                std::string());
512}
513
514}  // namespace gcm
515