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