chrome/service/cloud_print/printer_job_handler.cc

   1 // Copyright (c) 2012 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 "chrome/service/cloud_print/printer_job_handler.h"
   6
   7 #include "base/bind.h"
   8 #include "base/bind_helpers.h"
   9 #include "base/files/file_util.h"
  10 #include "base/json/json_reader.h"
  11 #include "base/md5.h"
  12 #include "base/metrics/histogram.h"
  13 #include "base/strings/stringprintf.h"
  14 #include "base/strings/utf_string_conversions.h"
  15 #include "base/values.h"
  16 #include "chrome/common/cloud_print/cloud_print_constants.h"
  17 #include "chrome/common/cloud_print/cloud_print_helpers.h"
  18 #include "chrome/grit/generated_resources.h"
  19 #include "chrome/service/cloud_print/cloud_print_service_helpers.h"
  20 #include "chrome/service/cloud_print/job_status_updater.h"
  21 #include "net/base/mime_util.h"
  22 #include "net/http/http_response_headers.h"
  23 #include "net/http/http_status_code.h"
  24 #include "printing/printing_utils.h"
  25 #include "ui/base/l10n/l10n_util.h"
  26 #include "url/gurl.h"
  27
  28 namespace cloud_print {
  29
  30 namespace {
  31
  32 base::subtle::Atomic32 g_total_jobs_started = 0;
  33 base::subtle::Atomic32 g_total_jobs_done = 0;
  34
  35 enum PrinterJobHandlerEvent {
  36   JOB_HANDLER_CHECK_FOR_JOBS,
  37   JOB_HANDLER_START,
  38   JOB_HANDLER_PENDING_TASK,
  39   JOB_HANDLER_PRINTER_UPDATE,
  40   JOB_HANDLER_JOB_CHECK,
  41   JOB_HANDLER_JOB_STARTED,
  42   JOB_HANDLER_VALID_TICKET,
  43   JOB_HANDLER_DATA,
  44   JOB_HANDLER_SET_IN_PROGRESS,
  45   JOB_HANDLER_SET_START_PRINTING,
  46   JOB_HANDLER_START_SPOOLING,
  47   JOB_HANDLER_SPOOLED,
  48   JOB_HANDLER_JOB_COMPLETED,
  49   JOB_HANDLER_INVALID_TICKET,
  50   JOB_HANDLER_INVALID_DATA,
  51   JOB_HANDLER_MAX,
  52 };
  53
  54 }  // namespace
  55
  56 PrinterJobHandler::PrinterInfoFromCloud::PrinterInfoFromCloud()
  57     : current_xmpp_timeout(0), pending_xmpp_timeout(0) {
  58 }
  59
  60 PrinterJobHandler::PrinterJobHandler(
  61     const printing::PrinterBasicInfo& printer_info,
  62     const PrinterInfoFromCloud& printer_info_cloud,
  63     const GURL& cloud_print_server_url,
  64     PrintSystem* print_system,
  65     Delegate* delegate)
  66     : print_system_(print_system),
  67       printer_info_(printer_info),
  68       printer_info_cloud_(printer_info_cloud),
  69       cloud_print_server_url_(cloud_print_server_url),
  70       delegate_(delegate),
  71       local_job_id_(-1),
  72       next_json_data_handler_(NULL),
  73       next_data_handler_(NULL),
  74       print_thread_("Chrome_CloudPrintJobPrintThread"),
  75       job_handler_message_loop_proxy_(
  76           base::MessageLoopProxy::current()),
  77       shutting_down_(false),
  78       job_check_pending_(false),
  79       printer_update_pending_(true),
  80       task_in_progress_(false),
  81       weak_ptr_factory_(this) {
  82 }
  83
  84 bool PrinterJobHandler::Initialize() {
  85   if (!print_system_->IsValidPrinter(printer_info_.printer_name))
  86     return false;
  87
  88   printer_watcher_ = print_system_->CreatePrinterWatcher(
  89       printer_info_.printer_name);
  90   printer_watcher_->StartWatching(this);
  91   CheckForJobs(kJobFetchReasonStartup);
  92   return true;
  93 }
  94
  95 std::string PrinterJobHandler::GetPrinterName() const {
  96   return printer_info_.printer_name;
  97 }
  98
  99 void PrinterJobHandler::CheckForJobs(const std::string& reason) {
 100   VLOG(1) << "CP_CONNECTOR: Checking for jobs"
 101           << ", printer id: " << printer_info_cloud_.printer_id
 102           << ", reason: " << reason
 103           << ", task in progress: " << task_in_progress_;
 104   UMA_HISTOGRAM_ENUMERATION("CloudPrint.JobHandlerEvent",
 105                             JOB_HANDLER_CHECK_FOR_JOBS, JOB_HANDLER_MAX);
 106   job_fetch_reason_ = reason;
 107   job_check_pending_ = true;
 108   if (!task_in_progress_) {
 109     base::MessageLoop::current()->PostTask(
 110         FROM_HERE, base::Bind(&PrinterJobHandler::Start, this));
 111   }
 112 }
 113
 114 void PrinterJobHandler::Shutdown() {
 115   VLOG(1) << "CP_CONNECTOR: Shutting down printer job handler"
 116           << ", printer id: " << printer_info_cloud_.printer_id;
 117   Reset();
 118   shutting_down_ = true;
 119   while (!job_status_updater_list_.empty()) {
 120     // Calling Stop() will cause the OnJobCompleted to be called which will
 121     // remove the updater object from the list.
 122     job_status_updater_list_.front()->Stop();
 123   }
 124 }
 125
 126 // CloudPrintURLFetcher::Delegate implementation.
 127 CloudPrintURLFetcher::ResponseAction PrinterJobHandler::HandleRawResponse(
 128     const net::URLFetcher* source,
 129     const GURL& url,
 130     const net::URLRequestStatus& status,
 131     int response_code,
 132     const net::ResponseCookies& cookies,
 133     const std::string& data) {
 134   // 415 (Unsupported media type) error while fetching data from the server
 135   // means data conversion error. Stop fetching process and mark job as error.
 136   if (next_data_handler_ == (&PrinterJobHandler::HandlePrintDataResponse) &&
 137       response_code == net::HTTP_UNSUPPORTED_MEDIA_TYPE) {
 138     VLOG(1) << "CP_CONNECTOR: Job failed (unsupported media type)";
 139     base::MessageLoop::current()->PostTask(
 140         FROM_HERE,
 141         base::Bind(&PrinterJobHandler::JobFailed, this, JOB_DOWNLOAD_FAILED));
 142     return CloudPrintURLFetcher::STOP_PROCESSING;
 143   }
 144   return CloudPrintURLFetcher::CONTINUE_PROCESSING;
 145 }
 146
 147 CloudPrintURLFetcher::ResponseAction PrinterJobHandler::HandleRawData(
 148     const net::URLFetcher* source,
 149     const GURL& url,
 150     const std::string& data) {
 151   if (!next_data_handler_)
 152     return CloudPrintURLFetcher::CONTINUE_PROCESSING;
 153   return (this->*next_data_handler_)(source, url, data);
 154 }
 155
 156 CloudPrintURLFetcher::ResponseAction PrinterJobHandler::HandleJSONData(
 157     const net::URLFetcher* source,
 158     const GURL& url,
 159     base::DictionaryValue* json_data,
 160     bool succeeded) {
 161   DCHECK(next_json_data_handler_);
 162   return (this->*next_json_data_handler_)(source, url, json_data, succeeded);
 163 }
 164
 165 // Mark the job fetch as failed and check if other jobs can be printed
 166 void PrinterJobHandler::OnRequestGiveUp() {
 167   if (job_queue_handler_.JobFetchFailed(job_details_.job_id_)) {
 168     VLOG(1) << "CP_CONNECTOR: Job failed to load (scheduling retry)";
 169     CheckForJobs(kJobFetchReasonFailure);
 170     base::MessageLoop::current()->PostTask(
 171         FROM_HERE, base::Bind(&PrinterJobHandler::Stop, this));
 172   } else {
 173     VLOG(1) << "CP_CONNECTOR: Job failed (giving up after " <<
 174         kNumRetriesBeforeAbandonJob << " retries)";
 175     base::MessageLoop::current()->PostTask(
 176         FROM_HERE,
 177         base::Bind(&PrinterJobHandler::JobFailed, this, JOB_DOWNLOAD_FAILED));
 178   }
 179 }
 180
 181 CloudPrintURLFetcher::ResponseAction PrinterJobHandler::OnRequestAuthError() {
 182   // We got an Auth error and have no idea how long it will take to refresh
 183   // auth information (may take forever). We'll drop current request and
 184   // propagate this error to the upper level. After auth issues will be
 185   // resolved, GCP connector will restart.
 186   OnAuthError();
 187   return CloudPrintURLFetcher::STOP_PROCESSING;
 188 }
 189
 190 std::string PrinterJobHandler::GetAuthHeader() {
 191   return GetCloudPrintAuthHeaderFromStore();
 192 }
 193
 194 // JobStatusUpdater::Delegate implementation
 195 bool PrinterJobHandler::OnJobCompleted(JobStatusUpdater* updater) {
 196   UMA_HISTOGRAM_ENUMERATION("CloudPrint.JobHandlerEvent",
 197                             JOB_HANDLER_JOB_COMPLETED, JOB_HANDLER_MAX);
 198   UMA_HISTOGRAM_LONG_TIMES("CloudPrint.PrintingTime",
 199                            base::Time::Now() - updater->start_time());
 200   bool ret = false;
 201   base::subtle::NoBarrier_AtomicIncrement(&g_total_jobs_done, 1);
 202   job_queue_handler_.JobDone(job_details_.job_id_);
 203
 204   for (JobStatusUpdaterList::iterator index = job_status_updater_list_.begin();
 205        index != job_status_updater_list_.end(); index++) {
 206     if (index->get() == updater) {
 207       job_status_updater_list_.erase(index);
 208       ret = true;
 209       break;
 210     }
 211   }
 212   return ret;
 213 }
 214
 215 void PrinterJobHandler::OnAuthError() {
 216   base::MessageLoop::current()->PostTask(
 217       FROM_HERE, base::Bind(&PrinterJobHandler::Stop, this));
 218   if (delegate_)
 219     delegate_->OnAuthError();
 220 }
 221
 222 void PrinterJobHandler::OnPrinterDeleted() {
 223   if (delegate_)
 224     delegate_->OnPrinterDeleted(printer_info_cloud_.printer_id);
 225 }
 226
 227 void PrinterJobHandler::OnPrinterChanged() {
 228   printer_update_pending_ = true;
 229   if (!task_in_progress_) {
 230     base::MessageLoop::current()->PostTask(
 231         FROM_HERE, base::Bind(&PrinterJobHandler::Start, this));
 232   }
 233 }
 234
 235 void PrinterJobHandler::OnJobChanged() {
 236   // Some job on the printer changed. Loop through all our JobStatusUpdaters
 237   // and have them check for updates.
 238   for (JobStatusUpdaterList::iterator index = job_status_updater_list_.begin();
 239        index != job_status_updater_list_.end(); index++) {
 240     base::MessageLoop::current()->PostTask(
 241         FROM_HERE, base::Bind(&JobStatusUpdater::UpdateStatus, index->get()));
 242   }
 243 }
 244
 245 void PrinterJobHandler::OnJobSpoolSucceeded(const PlatformJobId& job_id) {
 246   DCHECK(base::MessageLoop::current() == print_thread_.message_loop());
 247   job_spooler_->AddRef();
 248   print_thread_.message_loop()->ReleaseSoon(FROM_HERE, job_spooler_.get());
 249   job_spooler_ = NULL;
 250   job_handler_message_loop_proxy_->PostTask(
 251       FROM_HERE, base::Bind(&PrinterJobHandler::JobSpooled, this, job_id));
 252 }
 253
 254 void PrinterJobHandler::OnJobSpoolFailed() {
 255   DCHECK(base::MessageLoop::current() == print_thread_.message_loop());
 256   job_spooler_->AddRef();
 257   print_thread_.message_loop()->ReleaseSoon(FROM_HERE, job_spooler_.get());
 258   job_spooler_ = NULL;
 259   VLOG(1) << "CP_CONNECTOR: Job failed (spool failed)";
 260   job_handler_message_loop_proxy_->PostTask(
 261       FROM_HERE, base::Bind(&PrinterJobHandler::JobFailed, this, JOB_FAILED));
 262 }
 263
 264 // static
 265 void PrinterJobHandler::ReportsStats() {
 266   base::subtle::Atomic32 started =
 267       base::subtle::NoBarrier_AtomicExchange(&g_total_jobs_started, 0);
 268   base::subtle::Atomic32 done =
 269       base::subtle::NoBarrier_AtomicExchange(&g_total_jobs_done, 0);
 270   UMA_HISTOGRAM_COUNTS_100("CloudPrint.JobsStartedPerInterval", started);
 271   UMA_HISTOGRAM_COUNTS_100("CloudPrint.JobsDonePerInterval", done);
 272 }
 273
 274 PrinterJobHandler::~PrinterJobHandler() {
 275   if (printer_watcher_.get())
 276     printer_watcher_->StopWatching();
 277 }
 278
 279 // Begin Response handlers
 280 CloudPrintURLFetcher::ResponseAction
 281 PrinterJobHandler::HandlePrinterUpdateResponse(
 282     const net::URLFetcher* source,
 283     const GURL& url,
 284     base::DictionaryValue* json_data,
 285     bool succeeded) {
 286   VLOG(1) << "CP_CONNECTOR: Handling printer update response"
 287           << ", printer id: " << printer_info_cloud_.printer_id;
 288   // We are done here. Go to the Stop state
 289   VLOG(1) << "CP_CONNECTOR: Stopping printer job handler"
 290           << ", printer id: " << printer_info_cloud_.printer_id;
 291   base::MessageLoop::current()->PostTask(
 292       FROM_HERE, base::Bind(&PrinterJobHandler::Stop, this));
 293   return CloudPrintURLFetcher::STOP_PROCESSING;
 294 }
 295
 296 CloudPrintURLFetcher::ResponseAction
 297 PrinterJobHandler::HandleJobMetadataResponse(
 298     const net::URLFetcher* source,
 299     const GURL& url,
 300     base::DictionaryValue* json_data,
 301     bool succeeded) {
 302   VLOG(1) << "CP_CONNECTOR: Handling job metadata response"
 303           << ", printer id: " << printer_info_cloud_.printer_id;
 304   bool job_available = false;
 305   if (succeeded) {
 306     std::vector<JobDetails> jobs;
 307     job_queue_handler_.GetJobsFromQueue(json_data, &jobs);
 308     if (!jobs.empty()) {
 309       if (jobs[0].time_remaining_ == base::TimeDelta()) {
 310         job_available = true;
 311         job_details_ = jobs[0];
 312         job_start_time_ = base::Time::Now();
 313         base::subtle::NoBarrier_AtomicIncrement(&g_total_jobs_started, 1);
 314         UMA_HISTOGRAM_ENUMERATION("CloudPrint.JobHandlerEvent",
 315                                   JOB_HANDLER_JOB_STARTED, JOB_HANDLER_MAX);
 316         SetNextDataHandler(&PrinterJobHandler::HandlePrintTicketResponse);
 317         request_ = CloudPrintURLFetcher::Create();
 318         if (print_system_->UseCddAndCjt()) {
 319           request_->StartGetRequest(
 320               CloudPrintURLFetcher::REQUEST_TICKET,
 321               GetUrlForJobCjt(cloud_print_server_url_, job_details_.job_id_,
 322                               job_fetch_reason_),
 323               this, kJobDataMaxRetryCount, std::string());
 324         } else {
 325           request_->StartGetRequest(
 326               CloudPrintURLFetcher::REQUEST_TICKET,
 327               GURL(job_details_.print_ticket_url_), this, kJobDataMaxRetryCount,
 328               std::string());
 329         }
 330       } else {
 331         job_available = false;
 332         base::MessageLoop::current()->PostDelayedTask(
 333             FROM_HERE,
 334             base::Bind(&PrinterJobHandler::RunScheduledJobCheck, this),
 335             jobs[0].time_remaining_);
 336       }
 337     }
 338   }
 339
 340   if (!job_available) {
 341     // If no jobs are available, go to the Stop state.
 342     VLOG(1) << "CP_CONNECTOR: Stopping printer job handler"
 343             << ", printer id: " << printer_info_cloud_.printer_id;
 344     base::MessageLoop::current()->PostTask(
 345         FROM_HERE, base::Bind(&PrinterJobHandler::Stop, this));
 346   }
 347   return CloudPrintURLFetcher::STOP_PROCESSING;
 348 }
 349
 350 CloudPrintURLFetcher::ResponseAction
 351 PrinterJobHandler::HandlePrintTicketResponse(const net::URLFetcher* source,
 352                                              const GURL& url,
 353                                              const std::string& data) {
 354   VLOG(1) << "CP_CONNECTOR: Handling print ticket response"
 355           << ", printer id: " << printer_info_cloud_.printer_id;
 356   std::string mime_type;
 357   source->GetResponseHeaders()->GetMimeType(&mime_type);
 358   if (print_system_->ValidatePrintTicket(printer_info_.printer_name, data,
 359                                          mime_type)) {
 360     UMA_HISTOGRAM_ENUMERATION("CloudPrint.JobHandlerEvent",
 361                               JOB_HANDLER_VALID_TICKET, JOB_HANDLER_MAX);
 362     job_details_.print_ticket_ = data;
 363     job_details_.print_ticket_mime_type_ = mime_type;
 364     SetNextDataHandler(&PrinterJobHandler::HandlePrintDataResponse);
 365     request_ = CloudPrintURLFetcher::Create();
 366     std::string accept_headers = "Accept: ";
 367     accept_headers += print_system_->GetSupportedMimeTypes();
 368     request_->StartGetRequest(CloudPrintURLFetcher::REQUEST_DATA,
 369         GURL(job_details_.print_data_url_), this, kJobDataMaxRetryCount,
 370         accept_headers);
 371   } else {
 372     UMA_HISTOGRAM_ENUMERATION("CloudPrint.JobHandlerEvent",
 373                               JOB_HANDLER_INVALID_TICKET, JOB_HANDLER_MAX);
 374     // The print ticket was not valid. We are done here.
 375     ValidatePrintTicketFailed();
 376   }
 377   return CloudPrintURLFetcher::STOP_PROCESSING;
 378 }
 379
 380 CloudPrintURLFetcher::ResponseAction
 381 PrinterJobHandler::HandlePrintDataResponse(const net::URLFetcher* source,
 382                                            const GURL& url,
 383                                            const std::string& data) {
 384   VLOG(1) << "CP_CONNECTOR: Handling print data response"
 385           << ", printer id: " << printer_info_cloud_.printer_id;
 386   if (base::CreateTemporaryFile(&job_details_.print_data_file_path_)) {
 387     UMA_HISTOGRAM_ENUMERATION("CloudPrint.JobHandlerEvent", JOB_HANDLER_DATA,
 388                               JOB_HANDLER_MAX);
 389     int ret = base::WriteFile(job_details_.print_data_file_path_,
 390                               data.c_str(), data.length());
 391     source->GetResponseHeaders()->GetMimeType(
 392         &job_details_.print_data_mime_type_);
 393     DCHECK(ret == static_cast<int>(data.length()));
 394     if (ret == static_cast<int>(data.length())) {
 395       UpdateJobStatus(PRINT_JOB_STATUS_IN_PROGRESS, JOB_SUCCESS);
 396       return CloudPrintURLFetcher::STOP_PROCESSING;
 397     }
 398   }
 399   UMA_HISTOGRAM_ENUMERATION("CloudPrint.JobHandlerEvent",
 400                             JOB_HANDLER_INVALID_DATA, JOB_HANDLER_MAX);
 401
 402   // If we are here, then there was an error in saving the print data, bail out
 403   // here.
 404   VLOG(1) << "CP_CONNECTOR: Error saving print data"
 405           << ", printer id: " << printer_info_cloud_.printer_id;
 406   base::MessageLoop::current()->PostTask(
 407       FROM_HERE, base::Bind(&PrinterJobHandler::JobFailed, this,
 408                             JOB_DOWNLOAD_FAILED));
 409   return CloudPrintURLFetcher::STOP_PROCESSING;
 410 }
 411
 412 CloudPrintURLFetcher::ResponseAction
 413 PrinterJobHandler::HandleInProgressStatusUpdateResponse(
 414     const net::URLFetcher* source,
 415     const GURL& url,
 416     base::DictionaryValue* json_data,
 417     bool succeeded) {
 418   VLOG(1) << "CP_CONNECTOR: Handling success status update response"
 419           << ", printer id: " << printer_info_cloud_.printer_id;
 420   base::MessageLoop::current()->PostTask(
 421       FROM_HERE, base::Bind(&PrinterJobHandler::StartPrinting, this));
 422   return CloudPrintURLFetcher::STOP_PROCESSING;
 423 }
 424
 425 CloudPrintURLFetcher::ResponseAction
 426 PrinterJobHandler::HandleFailureStatusUpdateResponse(
 427     const net::URLFetcher* source,
 428     const GURL& url,
 429     base::DictionaryValue* json_data,
 430     bool succeeded) {
 431   VLOG(1) << "CP_CONNECTOR: Handling failure status update response"
 432           << ", printer id: " << printer_info_cloud_.printer_id;
 433   base::MessageLoop::current()->PostTask(
 434       FROM_HERE, base::Bind(&PrinterJobHandler::Stop, this));
 435   return CloudPrintURLFetcher::STOP_PROCESSING;
 436 }
 437
 438 void PrinterJobHandler::Start() {
 439   VLOG(1) << "CP_CONNECTOR: Starting printer job handler"
 440           << ", printer id: " << printer_info_cloud_.printer_id
 441           << ", task in progress: " << task_in_progress_;
 442   UMA_HISTOGRAM_ENUMERATION("CloudPrint.JobHandlerEvent",
 443                             JOB_HANDLER_START, JOB_HANDLER_MAX);
 444   if (task_in_progress_) {
 445     // Multiple Starts can get posted because of multiple notifications
 446     // We want to ignore the other ones that happen when a task is in progress.
 447     return;
 448   }
 449   Reset();
 450   if (!shutting_down_) {
 451     // Check if we have work to do.
 452     if (HavePendingTasks()) {
 453       UMA_HISTOGRAM_ENUMERATION("CloudPrint.JobHandlerEvent",
 454                                 JOB_HANDLER_PENDING_TASK, JOB_HANDLER_MAX);
 455       if (!task_in_progress_ && printer_update_pending_) {
 456         UMA_HISTOGRAM_ENUMERATION("CloudPrint.JobHandlerEvent",
 457                                   JOB_HANDLER_PRINTER_UPDATE, JOB_HANDLER_MAX);
 458         printer_update_pending_ = false;
 459         task_in_progress_ = UpdatePrinterInfo();
 460         VLOG(1) << "CP_CONNECTOR: Changed task in progress"
 461                 << ", printer id: " << printer_info_cloud_.printer_id
 462                 << ", task in progress: " << task_in_progress_;
 463       }
 464       if (!task_in_progress_ && job_check_pending_) {
 465         UMA_HISTOGRAM_ENUMERATION("CloudPrint.JobHandlerEvent",
 466                                   JOB_HANDLER_JOB_CHECK, JOB_HANDLER_MAX);
 467         task_in_progress_ = true;
 468         VLOG(1) << "CP_CONNECTOR: Changed task in progress"
 469                 ", printer id: " << printer_info_cloud_.printer_id
 470                 << ", task in progress: " << task_in_progress_;
 471         job_check_pending_ = false;
 472         // We need to fetch any pending jobs for this printer
 473         SetNextJSONHandler(&PrinterJobHandler::HandleJobMetadataResponse);
 474         request_ = CloudPrintURLFetcher::Create();
 475         request_->StartGetRequest(
 476             CloudPrintURLFetcher::REQUEST_JOB_FETCH,
 477             GetUrlForJobFetch(
 478                 cloud_print_server_url_, printer_info_cloud_.printer_id,
 479                 job_fetch_reason_),
 480             this,
 481             kCloudPrintAPIMaxRetryCount,
 482             std::string());
 483         last_job_fetch_time_ = base::TimeTicks::Now();
 484         VLOG(1) << "CP_CONNECTOR: Last job fetch time"
 485                 << ", printer name: " << printer_info_.printer_name.c_str()
 486                 << ", timestamp: " << last_job_fetch_time_.ToInternalValue();
 487         job_fetch_reason_.clear();
 488       }
 489     }
 490   }
 491 }
 492
 493 void PrinterJobHandler::Stop() {
 494   VLOG(1) << "CP_CONNECTOR: Stopping printer job handler"
 495           << ", printer id: " << printer_info_cloud_.printer_id;
 496   task_in_progress_ = false;
 497   VLOG(1) << "CP_CONNECTOR: Changed task in progress"
 498           << ", printer id: " << printer_info_cloud_.printer_id
 499           << ", task in progress: " << task_in_progress_;
 500   Reset();
 501   if (HavePendingTasks()) {
 502     base::MessageLoop::current()->PostTask(
 503         FROM_HERE, base::Bind(&PrinterJobHandler::Start, this));
 504   }
 505 }
 506
 507 void PrinterJobHandler::StartPrinting() {
 508   VLOG(1) << "CP_CONNECTOR: Starting printing"
 509           << ", printer id: " << printer_info_cloud_.printer_id;
 510   UMA_HISTOGRAM_ENUMERATION("CloudPrint.JobHandlerEvent",
 511                             JOB_HANDLER_SET_START_PRINTING, JOB_HANDLER_MAX);
 512   // We are done with the request object for now.
 513   request_ = NULL;
 514   if (!shutting_down_) {
 515 #if defined(OS_WIN)
 516     print_thread_.init_com_with_mta(true);
 517 #endif
 518     if (!print_thread_.Start()) {
 519       VLOG(1) << "CP_CONNECTOR: Failed to start print thread"
 520               << ", printer id: " << printer_info_cloud_.printer_id;
 521       JobFailed(JOB_FAILED);
 522     } else {
 523       print_thread_.message_loop()->PostTask(
 524           FROM_HERE, base::Bind(&PrinterJobHandler::DoPrint, this, job_details_,
 525                                 printer_info_.printer_name));
 526     }
 527   }
 528 }
 529
 530 void PrinterJobHandler::Reset() {
 531   job_details_.Clear();
 532   request_ = NULL;
 533   print_thread_.Stop();
 534 }
 535
 536 void PrinterJobHandler::UpdateJobStatus(PrintJobStatus status,
 537                                         PrintJobError error) {
 538   VLOG(1) << "CP_CONNECTOR: Updating job status"
 539           << ", printer id: " << printer_info_cloud_.printer_id
 540           << ", job id: " << job_details_.job_id_
 541           << ", job status: " << status;
 542   if (shutting_down_) {
 543     VLOG(1) << "CP_CONNECTOR: Job status update aborted (shutting down)"
 544             << ", printer id: " << printer_info_cloud_.printer_id
 545             << ", job id: " << job_details_.job_id_;
 546     return;
 547   }
 548   if (job_details_.job_id_.empty()) {
 549     VLOG(1) << "CP_CONNECTOR: Job status update aborted (empty job id)"
 550             << ", printer id: " << printer_info_cloud_.printer_id;
 551     return;
 552   }
 553
 554   UMA_HISTOGRAM_ENUMERATION("CloudPrint.JobStatus", error, JOB_MAX);
 555
 556   if (error == JOB_SUCCESS) {
 557     DCHECK_EQ(status, PRINT_JOB_STATUS_IN_PROGRESS);
 558     UMA_HISTOGRAM_ENUMERATION("CloudPrint.JobHandlerEvent",
 559                               JOB_HANDLER_SET_IN_PROGRESS, JOB_HANDLER_MAX);
 560     SetNextJSONHandler(
 561         &PrinterJobHandler::HandleInProgressStatusUpdateResponse);
 562   } else {
 563     SetNextJSONHandler(
 564         &PrinterJobHandler::HandleFailureStatusUpdateResponse);
 565   }
 566   request_ = CloudPrintURLFetcher::Create();
 567   request_->StartGetRequest(
 568       CloudPrintURLFetcher::REQUEST_UPDATE_JOB,
 569       GetUrlForJobStatusUpdate(cloud_print_server_url_, job_details_.job_id_,
 570                                status, error),
 571       this, kCloudPrintAPIMaxRetryCount, std::string());
 572 }
 573
 574 void PrinterJobHandler::RunScheduledJobCheck() {
 575   CheckForJobs(kJobFetchReasonRetry);
 576 }
 577
 578 void PrinterJobHandler::SetNextJSONHandler(JSONDataHandler handler) {
 579   next_json_data_handler_ = handler;
 580   next_data_handler_ = NULL;
 581 }
 582
 583 void PrinterJobHandler::SetNextDataHandler(DataHandler handler) {
 584   next_data_handler_ = handler;
 585   next_json_data_handler_ = NULL;
 586 }
 587
 588 void PrinterJobHandler::JobFailed(PrintJobError error) {
 589   VLOG(1) << "CP_CONNECTOR: Job failed"
 590           << ", printer id: " << printer_info_cloud_.printer_id
 591           << ", job id: " << job_details_.job_id_
 592           << ", error: " << error;
 593   if (!shutting_down_) {
 594     UpdateJobStatus(PRINT_JOB_STATUS_ERROR, error);
 595     // This job failed, but others may be pending.  Schedule a check.
 596     job_check_pending_ = true;
 597     job_fetch_reason_ = kJobFetchReasonFailure;
 598   }
 599 }
 600
 601 void PrinterJobHandler::JobSpooled(PlatformJobId local_job_id) {
 602   VLOG(1) << "CP_CONNECTOR: Job spooled"
 603           << ", printer id: " << printer_info_cloud_.printer_id
 604           << ", job id: " << local_job_id;
 605   UMA_HISTOGRAM_ENUMERATION("CloudPrint.JobHandlerEvent", JOB_HANDLER_SPOOLED,
 606                             JOB_HANDLER_MAX);
 607   UMA_HISTOGRAM_LONG_TIMES("CloudPrint.SpoolingTime",
 608                            base::Time::Now() - spooling_start_time_);
 609   if (shutting_down_)
 610     return;
 611
 612   local_job_id_ = local_job_id;
 613   print_thread_.Stop();
 614
 615   // The print job has been spooled locally. We now need to create an object
 616   // that monitors the status of the job and updates the server.
 617   scoped_refptr<JobStatusUpdater> job_status_updater(
 618       new JobStatusUpdater(printer_info_.printer_name, job_details_.job_id_,
 619                             local_job_id_, cloud_print_server_url_,
 620                             print_system_.get(), this));
 621   job_status_updater_list_.push_back(job_status_updater);
 622   base::MessageLoop::current()->PostTask(
 623       FROM_HERE,
 624       base::Bind(&JobStatusUpdater::UpdateStatus, job_status_updater.get()));
 625
 626   CheckForJobs(kJobFetchReasonQueryMore);
 627
 628   VLOG(1) << "CP_CONNECTOR: Stopping printer job handler"
 629           << ", printer id: " << printer_info_cloud_.printer_id;
 630   base::MessageLoop::current()->PostTask(
 631       FROM_HERE, base::Bind(&PrinterJobHandler::Stop, this));
 632 }
 633
 634 bool PrinterJobHandler::UpdatePrinterInfo() {
 635   if (!printer_watcher_.get()) {
 636     LOG(ERROR) << "CP_CONNECTOR: Printer watcher is missing."
 637                << " Check printer server url for printer id: "
 638                << printer_info_cloud_.printer_id;
 639     return false;
 640   }
 641
 642   VLOG(1) << "CP_CONNECTOR: Updating printer info"
 643           << ", printer id: " << printer_info_cloud_.printer_id;
 644   // We need to update the parts of the printer info that have changed
 645   // (could be printer name, description, status or capabilities).
 646   // First asynchronously fetch the capabilities.
 647   printing::PrinterBasicInfo printer_info;
 648   printer_watcher_->GetCurrentPrinterInfo(&printer_info);
 649
 650   // Asynchronously fetch the printer caps and defaults. The story will
 651   // continue in OnReceivePrinterCaps.
 652   print_system_->GetPrinterCapsAndDefaults(
 653       printer_info.printer_name.c_str(),
 654       base::Bind(&PrinterJobHandler::OnReceivePrinterCaps,
 655                  weak_ptr_factory_.GetWeakPtr()));
 656
 657   // While we are waiting for the data, pretend we have work to do and return
 658   // true.
 659   return true;
 660 }
 661
 662 bool PrinterJobHandler::HavePendingTasks() {
 663   return (job_check_pending_ || printer_update_pending_);
 664 }
 665
 666 void PrinterJobHandler::ValidatePrintTicketFailed() {
 667   if (!shutting_down_) {
 668     LOG(ERROR) << "CP_CONNECTOR: Failed validating print ticket"
 669                << ", printer name: " << printer_info_.printer_name
 670                << ", job id: " << job_details_.job_id_;
 671     JobFailed(JOB_VALIDATE_TICKET_FAILED);
 672   }
 673 }
 674
 675 void PrinterJobHandler::OnReceivePrinterCaps(
 676     bool succeeded,
 677     const std::string& printer_name,
 678     const printing::PrinterCapsAndDefaults& caps_and_defaults) {
 679   printing::PrinterBasicInfo printer_info;
 680   if (printer_watcher_.get())
 681     printer_watcher_->GetCurrentPrinterInfo(&printer_info);
 682
 683   std::string post_data;
 684   std::string mime_boundary;
 685   CreateMimeBoundaryForUpload(&mime_boundary);
 686
 687   if (succeeded) {
 688     std::string caps_hash =
 689         base::MD5String(caps_and_defaults.printer_capabilities);
 690     if (caps_hash != printer_info_cloud_.caps_hash) {
 691       // Hashes don't match, we need to upload new capabilities (the defaults
 692       // go for free along with the capabilities)
 693       printer_info_cloud_.caps_hash = caps_hash;
 694       if (caps_and_defaults.caps_mime_type == kContentTypeJSON) {
 695         DCHECK(print_system_->UseCddAndCjt());
 696         net::AddMultipartValueForUpload(kUseCDD, "true", mime_boundary,
 697                                         std::string(), &post_data);
 698       }
 699       net::AddMultipartValueForUpload(kPrinterCapsValue,
 700           caps_and_defaults.printer_capabilities, mime_boundary,
 701           caps_and_defaults.caps_mime_type, &post_data);
 702       net::AddMultipartValueForUpload(kPrinterDefaultsValue,
 703           caps_and_defaults.printer_defaults, mime_boundary,
 704           caps_and_defaults.defaults_mime_type, &post_data);
 705       net::AddMultipartValueForUpload(kPrinterCapsHashValue,
 706           caps_hash, mime_boundary, std::string(), &post_data);
 707     }
 708   } else {
 709     LOG(ERROR) << "Failed to get printer caps and defaults"
 710                << ", printer name: " << printer_name;
 711   }
 712
 713   std::string tags_hash = GetHashOfPrinterInfo(printer_info);
 714   if (tags_hash != printer_info_cloud_.tags_hash) {
 715     printer_info_cloud_.tags_hash = tags_hash;
 716     post_data += GetPostDataForPrinterInfo(printer_info, mime_boundary);
 717     // Remove all the existing proxy tags.
 718     std::string cp_tag_wildcard(kCloudPrintServiceProxyTagPrefix);
 719     cp_tag_wildcard += ".*";
 720     net::AddMultipartValueForUpload(kPrinterRemoveTagValue,
 721         cp_tag_wildcard, mime_boundary, std::string(), &post_data);
 722
 723     if (!last_caps_update_time_.is_null()) {
 724       UMA_HISTOGRAM_CUSTOM_TIMES(
 725           "CloudPrint.CapsUpdateInterval",
 726           base::Time::Now() - last_caps_update_time_,
 727           base::TimeDelta::FromMilliseconds(1),
 728           base::TimeDelta::FromDays(7), 50);
 729     }
 730     last_caps_update_time_ = base::Time::Now();
 731   }
 732
 733   if (printer_info.printer_name != printer_info_.printer_name) {
 734     net::AddMultipartValueForUpload(kPrinterNameValue,
 735         printer_info.printer_name, mime_boundary, std::string(), &post_data);
 736   }
 737   if (printer_info.printer_description != printer_info_.printer_description) {
 738     net::AddMultipartValueForUpload(kPrinterDescValue,
 739       printer_info.printer_description, mime_boundary,
 740       std::string(), &post_data);
 741   }
 742   if (printer_info.printer_status != printer_info_.printer_status) {
 743     net::AddMultipartValueForUpload(kPrinterStatusValue,
 744         base::StringPrintf("%d", printer_info.printer_status), mime_boundary,
 745         std::string(), &post_data);
 746   }
 747
 748   // Add local_settings with a current XMPP ping interval.
 749   if (printer_info_cloud_.pending_xmpp_timeout != 0) {
 750     DCHECK(kMinXmppPingTimeoutSecs <= printer_info_cloud_.pending_xmpp_timeout);
 751     net::AddMultipartValueForUpload(kPrinterLocalSettingsValue,
 752         base::StringPrintf(kUpdateLocalSettingsXmppPingFormat,
 753             printer_info_cloud_.current_xmpp_timeout),
 754         mime_boundary, std::string(), &post_data);
 755   }
 756
 757   printer_info_ = printer_info;
 758   if (!post_data.empty()) {
 759     net::AddMultipartFinalDelimiterForUpload(mime_boundary, &post_data);
 760     std::string mime_type("multipart/form-data; boundary=");
 761     mime_type += mime_boundary;
 762     SetNextJSONHandler(&PrinterJobHandler::HandlePrinterUpdateResponse);
 763     request_ = CloudPrintURLFetcher::Create();
 764     request_->StartPostRequest(
 765         CloudPrintURLFetcher::REQUEST_UPDATE_PRINTER,
 766         GetUrlForPrinterUpdate(
 767             cloud_print_server_url_, printer_info_cloud_.printer_id),
 768         this,
 769         kCloudPrintAPIMaxRetryCount,
 770         mime_type,
 771         post_data,
 772         std::string());
 773   } else {
 774     // We are done here. Go to the Stop state
 775     VLOG(1) << "CP_CONNECTOR: Stopping printer job handler"
 776             << ", printer name: " << printer_name;
 777     base::MessageLoop::current()->PostTask(
 778         FROM_HERE, base::Bind(&PrinterJobHandler::Stop, this));
 779   }
 780 }
 781
 782 // The following methods are called on |print_thread_|. It is not safe to
 783 // access any members other than |job_handler_message_loop_proxy_|,
 784 // |job_spooler_| and |print_system_|.
 785 void PrinterJobHandler::DoPrint(const JobDetails& job_details,
 786                                 const std::string& printer_name) {
 787   job_spooler_ = print_system_->CreateJobSpooler();
 788   UMA_HISTOGRAM_LONG_TIMES("CloudPrint.PrepareTime",
 789                            base::Time::Now() - job_start_time_);
 790   DCHECK(job_spooler_.get());
 791   if (!job_spooler_.get())
 792     return;
 793   base::string16 document_name = printing::SimplifyDocumentTitle(
 794       base::UTF8ToUTF16(job_details.job_title_));
 795   if (document_name.empty()) {
 796     document_name = printing::SimplifyDocumentTitle(
 797         l10n_util::GetStringUTF16(IDS_DEFAULT_PRINT_DOCUMENT_TITLE));
 798   }
 799   UMA_HISTOGRAM_ENUMERATION("CloudPrint.JobHandlerEvent",
 800                             JOB_HANDLER_START_SPOOLING, JOB_HANDLER_MAX);
 801   spooling_start_time_ = base::Time::Now();
 802   if (!job_spooler_->Spool(job_details.print_ticket_,
 803                            job_details.print_ticket_mime_type_,
 804                            job_details.print_data_file_path_,
 805                            job_details.print_data_mime_type_,
 806                            printer_name,
 807                            base::UTF16ToUTF8(document_name),
 808                            job_details.tags_,
 809                            this)) {
 810     OnJobSpoolFailed();
 811   }
 812 }
 813
 814 }  // namespace cloud_print