Fixed an issue with flaky connections causing too many job fetches. The logic on losing or regaining XMPP connection has been simplified to just schedule a delayed job fetch in both cases. Also sent the reason for job fetches to the server as part of the query parameters.

    
BUG=NONE
TEST=Test Cloud Print proxy with flaky connection, should not cause fetch storm.


Review URL: http://codereview.chromium.org/5137006

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@66969 0039d316-1c4b-4281-b951-d872f2087c98

8 files changed, 86 insertions, 30 deletions

diff --git a/chrome/service/cloud_print/cloud_print_consts.cc b/chrome/service/cloud_print/cloud_print_consts.cc
index a5f1566..8227466 100644
--- a/chrome/service/cloud_print/cloud_print_consts.cc
+++ b/chrome/service/cloud_print/cloud_print_consts.cc
@@ -45,3 +45,14 @@ const char kCloudPrintAPIRetryPolicy[] = "cloudprint.google.com/api";
 const char kJobDataRetryPolicy[] = "cloudprint.google.com/jobdata";
 // The string to be appended to the user-agent for cloudprint requests.
 const char kCloudPrintUserAgent[] = "GoogleCloudPrintProxy";
+
+// Reasons for fetching print jobs.
+// Job fetch on proxy startup.
+const char kJobFetchReasonStartup[] = "startup";
+// Job fetch because we are polling.
+const char kJobFetchReasonPoll[] = "poll";
+// Job fetch on being notified by the server.
+const char kJobFetchReasonNotified[] = "notified";
+// Job fetch after a successful print to query for more jobs.
+const char kJobFetchReasonQueryMore[] = "querymore";
+
diff --git a/chrome/service/cloud_print/cloud_print_consts.h b/chrome/service/cloud_print/cloud_print_consts.h
index 7bd16a9..748a300 100644
--- a/chrome/service/cloud_print/cloud_print_consts.h
+++ b/chrome/service/cloud_print/cloud_print_consts.h
@@ -39,6 +39,10 @@ extern const char kChromeCloudPrintProxyHeader[];
 extern const char kCloudPrintAPIRetryPolicy[];
 extern const char kJobDataRetryPolicy[];
 extern const char kCloudPrintUserAgent[];
+extern const char kJobFetchReasonStartup[];
+extern const char kJobFetchReasonPoll[];
+extern const char kJobFetchReasonNotified[];
+extern const char kJobFetchReasonQueryMore[];
 
 // Max retry count for job data fetch requests.
 const int kJobDataMaxRetryCount = 5;
diff --git a/chrome/service/cloud_print/cloud_print_helpers.cc b/chrome/service/cloud_print/cloud_print_helpers.cc
index 6143e7a..865e05d 100644
--- a/chrome/service/cloud_print/cloud_print_helpers.cc
+++ b/chrome/service/cloud_print/cloud_print_helpers.cc
@@ -92,11 +92,14 @@ GURL CloudPrintHelpers::GetUrlForPrinterList(const GURL& cloud_print_server_url,
 }
 
 GURL CloudPrintHelpers::GetUrlForJobFetch(const GURL& cloud_print_server_url,
-                                          const std::string& printer_id) {
+                                          const std::string& printer_id,
+                                          const std::string& reason) {
   std::string path(AppendPathToUrl(cloud_print_server_url, "fetch"));
   GURL::Replacements replacements;
   replacements.SetPathStr(path);
-  std::string query = StringPrintf("printerid=%s", printer_id.c_str());
+  std::string query = StringPrintf("printerid=%s&deb=%s",
+                                   printer_id.c_str(),
+                                   reason.c_str());
   replacements.SetQueryStr(query);
   return cloud_print_server_url.ReplaceComponents(replacements);
 }
diff --git a/chrome/service/cloud_print/cloud_print_helpers.h b/chrome/service/cloud_print/cloud_print_helpers.h
index 8e51f7a..7061452 100644
--- a/chrome/service/cloud_print/cloud_print_helpers.h
+++ b/chrome/service/cloud_print/cloud_print_helpers.h
@@ -27,7 +27,8 @@ class CloudPrintHelpers {
   static GURL GetUrlForPrinterList(const GURL& cloud_print_server_url,
                                    const std::string& proxy_id);
   static GURL GetUrlForJobFetch(const GURL& cloud_print_server_url,
-                                const std::string& printer_id);
+                                const std::string& printer_id,
+                                const std::string& reason);
   static GURL GetUrlForJobStatusUpdate(const GURL& cloud_print_server_url,
                                        const std::string& job_id,
                                        cloud_print::PrintJobStatus status);
diff --git a/chrome/service/cloud_print/cloud_print_helpers_unittest.cc b/chrome/service/cloud_print/cloud_print_helpers_unittest.cc
index 08ec18b..7c55026 100644
--- a/chrome/service/cloud_print/cloud_print_helpers_unittest.cc
+++ b/chrome/service/cloud_print/cloud_print_helpers_unittest.cc
@@ -36,8 +36,10 @@ void CheckURLs(const GURL& server_base_url) {
                               expected_url_base.c_str());
   EXPECT_EQ(expected_url, url.spec());
 
-  url = CloudPrintHelpers::GetUrlForJobFetch(server_base_url, "myprinter");
-  expected_url = StringPrintf("%sfetch?printerid=myprinter",
+  url = CloudPrintHelpers::GetUrlForJobFetch(server_base_url,
+                                             "myprinter",
+                                             "nogoodreason");
+  expected_url = StringPrintf("%sfetch?printerid=myprinter&deb=nogoodreason",
                               expected_url_base.c_str());
   EXPECT_EQ(expected_url, url.spec());
 
diff --git a/chrome/service/cloud_print/cloud_print_proxy_backend.cc b/chrome/service/cloud_print/cloud_print_proxy_backend.cc
index 7d1d404..7dac83e 100644
--- a/chrome/service/cloud_print/cloud_print_proxy_backend.cc
+++ b/chrome/service/cloud_print/cloud_print_proxy_backend.cc
@@ -185,6 +185,9 @@ class CloudPrintProxyBackend::Core
   scoped_ptr<notifier::TalkMediator> talk_mediator_;
   // Indicates whether XMPP notifications are currently enabled.
   bool notifications_enabled_;
+  // The time when notifications were enabled. Valid only when
+  // notifications_enabled_ is true.
+  base::TimeTicks notifications_enabled_since_;
   // Indicates whether a task to poll for jobs has been scheduled.
   bool job_poll_scheduled_;
   // The channel we are interested in receiving push notifications for.
@@ -418,8 +421,8 @@ void CloudPrintProxyBackend::Core::DoShutdown() {
   // Important to delete the TalkMediator on this thread.
   talk_mediator_.reset();
   notifications_enabled_ = false;
+  notifications_enabled_since_ = base::TimeTicks();
   request_ = NULL;
-  MessageLoop::current()->QuitNow();
 }
 
 void CloudPrintProxyBackend::Core::DoRegisterSelectedPrinters(
@@ -529,7 +532,7 @@ void CloudPrintProxyBackend::Core::HandlePrinterNotification(
   VLOG(1) << "CP_PROXY: Handle printer notification, id: " << printer_id;
   JobHandlerMap::iterator index = job_handler_map_.find(printer_id);
   if (index != job_handler_map_.end())
-    index->second->NotifyJobAvailable();
+    index->second->CheckForJobs(kJobFetchReasonNotified);
 }
 
 void CloudPrintProxyBackend::Core::PollForJobs() {
@@ -537,7 +540,13 @@ void CloudPrintProxyBackend::Core::PollForJobs() {
   DCHECK(MessageLoop::current() == backend_->core_thread_.message_loop());
   for (JobHandlerMap::iterator index = job_handler_map_.begin();
        index != job_handler_map_.end(); index++) {
-    index->second->NotifyJobAvailable();
+    // If notifications are on, then we should poll for this printer only if
+    // the last time it fetched jobs was before notifications were last enabled.
+    bool should_poll =
+        !notifications_enabled_ ||
+        (index->second->last_job_fetch_time() <= notifications_enabled_since_);
+    if (should_poll)
+      index->second->CheckForJobs(kJobFetchReasonPoll);
   }
   job_poll_scheduled_ = false;
   // If we don't have notifications, poll again after a while.
@@ -724,18 +733,28 @@ bool CloudPrintProxyBackend::Core::RemovePrinterFromList(
 void CloudPrintProxyBackend::Core::OnNotificationStateChange(
     bool notification_enabled) {
   DCHECK(MessageLoop::current() == backend_->core_thread_.message_loop());
-  bool previously_enabled = notifications_enabled_;
+  bool state_changed = (notification_enabled != notifications_enabled_);
   notifications_enabled_ = notification_enabled;
-  // If we lost notifications, we want to schedule a job poll. Also if
-  // notifications just got re-enabled, we want to poll once for jobs we might
-  // have missed when we were dark.
+  if (notifications_enabled_) {
+    notifications_enabled_since_ = base::TimeTicks::Now();
+    VLOG(1) << "Notifications for proxy " << proxy_id_ << " were enabled at "
+            << notifications_enabled_since_.ToInternalValue();
+  } else {
+    VLOG(1) << "Notifications for proxy " << proxy_id_ << " disabled.";
+    notifications_enabled_since_ = base::TimeTicks();
+  }
+  // A state change means one of two cases.
+  // Case 1: We just lost notifications. This this case we want to schedule a
+  // job poll.
+  // Case 2: Notifications just got re-enabled. In this case we want to schedule
+  // a poll once for jobs we might have missed when we were dark. In reality
+  // this is only needed when notifications get enabled for the first time. In
+  // all other cases there would already be a scheduled task to poll in the
+  // queue.
   // Note that ScheduleJobPoll will not schedule again if a job poll task is
   // already scheduled.
-  if (!notifications_enabled_) {
+  if (state_changed)
     ScheduleJobPoll();
-  } else if (!previously_enabled) {
-    PollForJobs();
-  }
 }
 
 
diff --git a/chrome/service/cloud_print/printer_job_handler.cc b/chrome/service/cloud_print/printer_job_handler.cc
index e25faa4..e705762 100644
--- a/chrome/service/cloud_print/printer_job_handler.cc
+++ b/chrome/service/cloud_print/printer_job_handler.cc
@@ -38,7 +38,7 @@ PrinterJobHandler::PrinterJobHandler(
       job_handler_message_loop_proxy_(
           base::MessageLoopProxy::CreateForCurrentThread()),
       shutting_down_(false),
-      server_job_available_(false),
+      job_check_pending_(false),
       printer_update_pending_(true),
       printer_delete_pending_(false),
       task_in_progress_(false) {
@@ -50,7 +50,7 @@ bool PrinterJobHandler::Initialize() {
     printer_watcher_ = print_system_->CreatePrinterWatcher(
         printer_info_.printer_name);
     printer_watcher_->StartWatching(this);
-    NotifyJobAvailable();
+    CheckForJobs(kJobFetchReasonStartup);
   } else {
     // This printer does not exist any more. Delete it from the server.
     OnPrinterDeleted();
@@ -97,16 +97,22 @@ void PrinterJobHandler::Start() {
         printer_update_pending_ = false;
         task_in_progress_ = UpdatePrinterInfo();
       }
-      if (!task_in_progress_ && server_job_available_) {
+      if (!task_in_progress_ && job_check_pending_) {
         task_in_progress_ = true;
-        server_job_available_ = false;
+        job_check_pending_ = false;
         // We need to fetch any pending jobs for this printer
         SetNextJSONHandler(&PrinterJobHandler::HandleJobMetadataResponse);
         request_ = new CloudPrintURLFetcher;
         request_->StartGetRequest(
             CloudPrintHelpers::GetUrlForJobFetch(
-                cloud_print_server_url_, printer_info_cloud_.printer_id),
+                cloud_print_server_url_, printer_info_cloud_.printer_id,
+                job_fetch_reason_),
             this, auth_token_, kCloudPrintAPIRetryPolicy);
+        last_job_fetch_time_ = base::TimeTicks::Now();
+        VLOG(1) << "Last job fetch time for printer "
+                << printer_info_.printer_name.c_str() << " is "
+                << last_job_fetch_time_.ToInternalValue();
+        job_fetch_reason_.clear();
       }
     }
   }
@@ -123,11 +129,13 @@ void PrinterJobHandler::Stop() {
   }
 }
 
-void PrinterJobHandler::NotifyJobAvailable() {
-  VLOG(1) << "CP_PROXY: Notify job available, id: "
+void PrinterJobHandler::CheckForJobs(const std::string& reason) {
+  VLOG(1) << "CP_PROXY: CheckForJobs, id: "
           << printer_info_cloud_.printer_id
+          << ", reason: " << reason
           << ", task in progress: " << task_in_progress_;
-  server_job_available_ = true;
+  job_fetch_reason_ = reason;
+  job_check_pending_ = true;
   if (!task_in_progress_) {
     MessageLoop::current()->PostTask(
         FROM_HERE, NewRunnableMethod(this, &PrinterJobHandler::Start));
@@ -427,7 +435,7 @@ PrinterJobHandler::HandleSuccessStatusUpdateResponse(
                                    &JobStatusUpdater::UpdateStatus));
   if (succeeded) {
     // Since we just printed successfully, we want to look for more jobs.
-    server_job_available_ = true;
+    CheckForJobs(kJobFetchReasonQueryMore);
   }
   MessageLoop::current()->PostTask(
       FROM_HERE, NewRunnableMethod(this, &PrinterJobHandler::Stop));
@@ -535,8 +543,8 @@ void PrinterJobHandler::SetNextDataHandler(DataHandler handler) {
 }
 
 bool PrinterJobHandler::HavePendingTasks() {
-  return server_job_available_ || printer_update_pending_ ||
-         printer_delete_pending_;
+  return (job_check_pending_ || printer_update_pending_ ||
+          printer_delete_pending_);
 }
 
 void PrinterJobHandler::FailedFetchingJobData() {
diff --git a/chrome/service/cloud_print/printer_job_handler.h b/chrome/service/cloud_print/printer_job_handler.h
index 3290581..2b43545 100644
--- a/chrome/service/cloud_print/printer_job_handler.h
+++ b/chrome/service/cloud_print/printer_job_handler.h
@@ -13,6 +13,7 @@
 #include "base/ref_counted.h"
 #include "base/message_loop_proxy.h"
 #include "base/thread.h"
+#include "base/time.h"
 #include "chrome/service/cloud_print/cloud_print_url_fetcher.h"
 #include "chrome/service/cloud_print/job_status_updater.h"
 #include "googleurl/src/gurl.h"
@@ -111,10 +112,12 @@ class PrinterJobHandler : public base::RefCountedThreadSafe<PrinterJobHandler>,
                     Delegate* delegate);
   ~PrinterJobHandler();
   bool Initialize();
-  // Notifies the JobHandler that a job is available
-  void NotifyJobAvailable();
+  // Requests a job check. |reason| is the reason for fetching the job. Used
+  // for logging and diagnostc purposes.
+  void CheckForJobs(const std::string& reason);
   // Shutdown everything (the process is exiting).
   void Shutdown();
+  base::TimeTicks last_job_fetch_time() const { return last_job_fetch_time_; }
   // End public interface
 
   // Begin Delegate implementations
@@ -264,8 +267,11 @@ class PrinterJobHandler : public base::RefCountedThreadSafe<PrinterJobHandler>,
   // We set this flag so as to do nothing in those tasks.
   bool shutting_down_;
 
+  // A string indicating the reason we are fetching jobs from the server
+  // (used to specify the reason in the fetch URL).
+  std::string job_fetch_reason_;
   // Flags that specify various pending server updates
-  bool server_job_available_;
+  bool job_check_pending_;
   bool printer_update_pending_;
   bool printer_delete_pending_;
 
@@ -275,6 +281,8 @@ class PrinterJobHandler : public base::RefCountedThreadSafe<PrinterJobHandler>,
   typedef std::list< scoped_refptr<JobStatusUpdater> > JobStatusUpdaterList;
   JobStatusUpdaterList job_status_updater_list_;
 
+  base::TimeTicks last_job_fetch_time_;
+
   DISALLOW_COPY_AND_ASSIGN(PrinterJobHandler);
 };