src/lib/job.cc

   1 /*
   2     Copyright (C) 2012-2019 Carl Hetherington <cth@carlh.net>
   3
   4     This file is part of DCP-o-matic.
   5
   6     DCP-o-matic is free software; you can redistribute it and/or modify
   7     it under the terms of the GNU General Public License as published by
   8     the Free Software Foundation; either version 2 of the License, or
   9     (at your option) any later version.
  10
  11     DCP-o-matic is distributed in the hope that it will be useful,
  12     but WITHOUT ANY WARRANTY; without even the implied warranty of
  13     MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  14     GNU General Public License for more details.
  15
  16     You should have received a copy of the GNU General Public License
  17     along with DCP-o-matic.  If not, see <http://www.gnu.org/licenses/>.
  18
  19 */
  20
  21 /** @file  src/job.cc
  22  *  @brief A parent class to represent long-running tasks which are run in their own thread.
  23  */
  24
  25 #include "job.h"
  26 #include "util.h"
  27 #include "cross.h"
  28 #include "exceptions.h"
  29 #include "film.h"
  30 #include "log.h"
  31 #include "dcpomatic_log.h"
  32 #include "compose.hpp"
  33 #include <dcp/exceptions.h>
  34 #include <sub/exceptions.h>
  35 #include <boost/thread.hpp>
  36 #include <boost/filesystem.hpp>
  37 #include <boost/foreach.hpp>
  38 #include <boost/date_time/posix_time/posix_time.hpp>
  39 #include <iostream>
  40
  41 #include "i18n.h"
  42
  43 using std::string;
  44 using std::list;
  45 using std::cout;
  46 using boost::shared_ptr;
  47 using boost::optional;
  48 using boost::function;
  49 using namespace dcpomatic;
  50
  51 /** @param film Associated film, or 0 */
  52 Job::Job (shared_ptr<const Film> film)
  53         : _film (film)
  54         , _thread (0)
  55         , _state (NEW)
  56         , _start_time (0)
  57         , _sub_start_time (0)
  58         , _progress (0)
  59         , _ran_for (0)
  60 {
  61
  62 }
  63
  64 Job::~Job ()
  65 {
  66         if (_thread) {
  67                 _thread->interrupt ();
  68                 /* We can't use DCPOMATIC_ASSERT here as it may throw an exception */
  69                 if (_thread->joinable ()) {
  70                         try {
  71                                 _thread->join ();
  72                         } catch (...) {
  73                                 /* Too late to do anything about this */
  74                         }
  75                 }
  76         }
  77
  78         delete _thread;
  79 }
  80
  81 /** Start the job in a separate thread, returning immediately */
  82 void
  83 Job::start ()
  84 {
  85         set_state (RUNNING);
  86         _start_time = time (0);
  87         _sub_start_time = time (0);
  88         _thread = new boost::thread (boost::bind (&Job::run_wrapper, this));
  89 #ifdef DCPOMATIC_LINUX
  90         pthread_setname_np (_thread->native_handle(), "job-wrapper");
  91 #endif
  92 }
  93
  94 /** A wrapper for the ::run() method to catch exceptions */
  95 void
  96 Job::run_wrapper ()
  97 {
  98         try {
  99
 100                 run ();
 101
 102         } catch (dcp::FileError& e) {
 103
 104                 string m = String::compose (_("An error occurred whilst handling the file %1."), boost::filesystem::path (e.filename()).leaf());
 105
 106                 try {
 107                         boost::filesystem::space_info const s = boost::filesystem::space (e.filename());
 108                         if (s.available < pow (1024, 3)) {
 109                                 m += N_("\n\n");
 110                                 m += _("The drive that the film is stored on is low in disc space.  Free some more space and try again.");
 111                         }
 112                 } catch (...) {
 113
 114                 }
 115
 116                 set_error (e.what(), m);
 117                 set_progress (1);
 118                 set_state (FINISHED_ERROR);
 119
 120         } catch (OpenFileError& e) {
 121
 122                 set_error (
 123                         String::compose (_("Could not open %1"), e.file().string()),
 124                         String::compose (
 125                                 _("DCP-o-matic could not open the file %1 (%2).  Perhaps it does not exist or is in an unexpected format."),
 126                                 boost::filesystem::absolute (e.file()).string(),
 127                                 e.what()
 128                                 )
 129                         );
 130
 131                 set_progress (1);
 132                 set_state (FINISHED_ERROR);
 133
 134         } catch (boost::filesystem::filesystem_error& e) {
 135
 136                 if (e.code() == boost::system::errc::no_such_file_or_directory) {
 137                         set_error (
 138                                 String::compose (_("Could not open %1"), e.path1().string ()),
 139                                 String::compose (
 140                                         _("DCP-o-matic could not open the file %1 (%2).  Perhaps it does not exist or is in an unexpected format."),
 141                                         boost::filesystem::absolute (e.path1()).string(),
 142                                         e.what()
 143                                         )
 144                                 );
 145                 } else {
 146                         set_error (
 147                                 e.what (),
 148                                 string (_("It is not known what caused this error.")) + "  " + REPORT_PROBLEM
 149                                 );
 150                 }
 151
 152                 set_progress (1);
 153                 set_state (FINISHED_ERROR);
 154
 155         } catch (boost::thread_interrupted &) {
 156
 157                 set_state (FINISHED_CANCELLED);
 158
 159         } catch (sub::SubripError& e) {
 160
 161                 string extra = "Error is near:\n";
 162                 BOOST_FOREACH (string i, e.context()) {
 163                         extra += i + "\n";
 164                 }
 165
 166                 set_error (e.what (), extra);
 167                 set_progress (1);
 168                 set_state (FINISHED_ERROR);
 169
 170         } catch (std::bad_alloc& e) {
 171
 172                 set_error (_("Out of memory"), _("There was not enough memory to do this.  If you are running a 32-bit operating system try reducing the number of encoding threads in the General tab of Preferences."));
 173                 set_progress (1);
 174                 set_state (FINISHED_ERROR);
 175
 176         } catch (dcp::MissingAssetError& e) {
 177
 178                 set_error (e.message(), e.path().string());
 179                 set_progress (1);
 180                 set_state (FINISHED_ERROR);
 181
 182         } catch (dcp::DCPReadError& e) {
 183
 184                 set_error (e.message(), e.detail().get_value_or(""));
 185                 set_progress (1);
 186                 set_state (FINISHED_ERROR);
 187
 188         } catch (KDMError& e) {
 189
 190                 set_error (e.summary(), e.detail());
 191                 set_progress (1);
 192                 set_state (FINISHED_ERROR);
 193
 194         } catch (FileError& e) {
 195
 196                 set_error (e.what(), e.what());
 197                 set_progress (1);
 198                 set_state (FINISHED_ERROR);
 199
 200         } catch (std::exception& e) {
 201
 202                 set_error (
 203                         e.what (),
 204                         string (_("It is not known what caused this error.")) + "  " + REPORT_PROBLEM
 205                         );
 206
 207                 set_progress (1);
 208                 set_state (FINISHED_ERROR);
 209
 210         } catch (...) {
 211
 212                 set_error (
 213                         _("Unknown error"),
 214                         string (_("It is not known what caused this error.")) + "  " + REPORT_PROBLEM
 215                         );
 216
 217                 set_progress (1);
 218                 set_state (FINISHED_ERROR);
 219         }
 220 }
 221
 222 /** @return true if this job is new (ie has not started running) */
 223 bool
 224 Job::is_new () const
 225 {
 226         boost::mutex::scoped_lock lm (_state_mutex);
 227         return _state == NEW;
 228 }
 229
 230 /** @return true if the job is running */
 231 bool
 232 Job::running () const
 233 {
 234         boost::mutex::scoped_lock lm (_state_mutex);
 235         return _state == RUNNING;
 236 }
 237
 238 /** @return true if the job has finished (either successfully or unsuccessfully) */
 239 bool
 240 Job::finished () const
 241 {
 242         boost::mutex::scoped_lock lm (_state_mutex);
 243         return _state == FINISHED_OK || _state == FINISHED_ERROR || _state == FINISHED_CANCELLED;
 244 }
 245
 246 /** @return true if the job has finished successfully */
 247 bool
 248 Job::finished_ok () const
 249 {
 250         boost::mutex::scoped_lock lm (_state_mutex);
 251         return _state == FINISHED_OK;
 252 }
 253
 254 /** @return true if the job has finished unsuccessfully */
 255 bool
 256 Job::finished_in_error () const
 257 {
 258         boost::mutex::scoped_lock lm (_state_mutex);
 259         return _state == FINISHED_ERROR;
 260 }
 261
 262 bool
 263 Job::finished_cancelled () const
 264 {
 265         boost::mutex::scoped_lock lm (_state_mutex);
 266         return _state == FINISHED_CANCELLED;
 267 }
 268
 269 bool
 270 Job::paused_by_user () const
 271 {
 272         boost::mutex::scoped_lock lm (_state_mutex);
 273         return _state == PAUSED_BY_USER;
 274 }
 275
 276 bool
 277 Job::paused_by_priority () const
 278 {
 279         boost::mutex::scoped_lock lm (_state_mutex);
 280         return _state == PAUSED_BY_PRIORITY;
 281 }
 282
 283 /** Set the state of this job.
 284  *  @param s New state.
 285  */
 286 void
 287 Job::set_state (State s)
 288 {
 289         bool finished = false;
 290
 291         {
 292                 boost::mutex::scoped_lock lm (_state_mutex);
 293                 _state = s;
 294
 295                 if (_state == FINISHED_OK || _state == FINISHED_ERROR || _state == FINISHED_CANCELLED) {
 296                         _ran_for = time(0) - _start_time;
 297                         finished = true;
 298                         _sub_name.clear ();
 299                 }
 300         }
 301
 302         if (finished) {
 303                 emit (boost::bind (boost::ref (Finished)));
 304                 FinishedImmediate ();
 305         }
 306 }
 307
 308 /** @return DCPTime (in seconds) that this sub-job has been running */
 309 int
 310 Job::elapsed_sub_time () const
 311 {
 312         if (_sub_start_time == 0) {
 313                 return 0;
 314         }
 315
 316         return time (0) - _sub_start_time;
 317 }
 318
 319 /** Check to see if this job has been interrupted or paused */
 320 void
 321 Job::check_for_interruption_or_pause ()
 322 {
 323         boost::this_thread::interruption_point ();
 324
 325         boost::mutex::scoped_lock lm (_state_mutex);
 326         while (_state == PAUSED_BY_USER || _state == PAUSED_BY_PRIORITY) {
 327                 emit (boost::bind (boost::ref (Progress)));
 328                 _pause_changed.wait (lm);
 329         }
 330 }
 331
 332 /** Set the progress of the current part of the job.
 333  *  @param p Progress (from 0 to 1)
 334  *  @param force Do not ignore this update, even if it hasn't been long since the last one.
 335  */
 336 void
 337 Job::set_progress (float p, bool force)
 338 {
 339         check_for_interruption_or_pause ();
 340
 341         if (!force) {
 342                 /* Check for excessively frequent progress reporting */
 343                 boost::mutex::scoped_lock lm (_progress_mutex);
 344                 struct timeval now;
 345                 gettimeofday (&now, 0);
 346                 if (_last_progress_update && _last_progress_update->tv_sec > 0) {
 347                         double const elapsed = (now.tv_sec + now.tv_usec / 1000000.0)
 348                                 - (_last_progress_update->tv_sec + _last_progress_update->tv_usec / 1000000.0);
 349                         if (elapsed < 0.5) {
 350                                 return;
 351                         }
 352                 }
 353                 _last_progress_update = now;
 354         }
 355
 356         set_progress_common (p);
 357 }
 358
 359 void
 360 Job::set_progress_common (optional<float> p)
 361 {
 362         {
 363                 boost::mutex::scoped_lock lm (_progress_mutex);
 364                 _progress = p;
 365         }
 366
 367         emit (boost::bind (boost::ref (Progress)));
 368 }
 369
 370 /** @return fractional progress of the current sub-job, if known */
 371 optional<float>
 372 Job::progress () const
 373 {
 374         boost::mutex::scoped_lock lm (_progress_mutex);
 375         return _progress;
 376 }
 377
 378 void
 379 Job::sub (string n)
 380 {
 381         {
 382                 boost::mutex::scoped_lock lm (_progress_mutex);
 383                 LOG_GENERAL ("Sub-job %1 starting", n);
 384                 _sub_name = n;
 385         }
 386
 387         set_progress (0, true);
 388         _sub_start_time = time (0);
 389 }
 390
 391 string
 392 Job::error_details () const
 393 {
 394         boost::mutex::scoped_lock lm (_state_mutex);
 395         return _error_details;
 396 }
 397
 398 /** @return A summary of any error that the job has generated */
 399 string
 400 Job::error_summary () const
 401 {
 402         boost::mutex::scoped_lock lm (_state_mutex);
 403         return _error_summary;
 404 }
 405
 406 /** Set the current error string.
 407  *  @param s New error string.
 408  *  @param d New error detail string.
 409  */
 410 void
 411 Job::set_error (string s, string d)
 412 {
 413         if (_film) {
 414                 _film->log()->log (String::compose ("Error in job: %1 (%2)", s, d), LogEntry::TYPE_ERROR);
 415         }
 416
 417         boost::mutex::scoped_lock lm (_state_mutex);
 418         _error_summary = s;
 419         _error_details = d;
 420 }
 421
 422 /** Say that this job's progress will be unknown until further notice */
 423 void
 424 Job::set_progress_unknown ()
 425 {
 426         check_for_interruption_or_pause ();
 427         set_progress_common (optional<float> ());
 428 }
 429
 430 /** @return Human-readable status of this job */
 431 string
 432 Job::status () const
 433 {
 434         optional<float> p = progress ();
 435         int const t = elapsed_sub_time ();
 436         int const r = remaining_time ();
 437
 438         string s;
 439         if (!finished () && p) {
 440                 int pc = lrintf (p.get() * 100);
 441                 if (pc == 100) {
 442                         /* 100% makes it sound like we've finished when we haven't */
 443                         pc = 99;
 444                 }
 445
 446                 char buffer[64];
 447                 snprintf (buffer, sizeof(buffer), "%d%%", pc);
 448                 s += buffer;
 449
 450                 if (t > 10 && r > 0) {
 451                         boost::posix_time::ptime now = boost::posix_time::second_clock::local_time();
 452                         boost::posix_time::ptime finish = now + boost::posix_time::seconds(r);
 453                         char finish_string[16];
 454                         snprintf (finish_string, sizeof(finish_string), "%02d:%02d", int(finish.time_of_day().hours()), int(finish.time_of_day().minutes()));
 455                         string day;
 456                         if (now.date() != finish.date()) {
 457                                 /// TRANSLATORS: the %1 in this string will be filled in with a day of the week
 458                                 /// to say what day a job will finish.
 459                                 day = String::compose (_(" on %1"), day_of_week_to_string(finish.date().day_of_week()));
 460                         }
 461                         /// TRANSLATORS: "remaining; finishing at" here follows an amount of time that is remaining
 462                         /// on an operation; after it is an estimated wall-clock completion time.
 463                         s += String::compose(
 464                                 _("; %1 remaining; finishing at %2%3"),
 465                                 seconds_to_approximate_hms(r), finish_string, day
 466                                 );
 467                 }
 468         } else if (finished_ok ()) {
 469                 s = String::compose (_("OK (ran for %1)"), seconds_to_hms (_ran_for));
 470         } else if (finished_in_error ()) {
 471                 s = String::compose (_("Error: %1"), error_summary ());
 472         } else if (finished_cancelled ()) {
 473                 s = _("Cancelled");
 474         }
 475
 476         return s;
 477 }
 478
 479 string
 480 Job::json_status () const
 481 {
 482         boost::mutex::scoped_lock lm (_state_mutex);
 483
 484         switch (_state) {
 485         case NEW:
 486                 return N_("new");
 487         case RUNNING:
 488                 return N_("running");
 489         case PAUSED_BY_USER:
 490         case PAUSED_BY_PRIORITY:
 491                 return N_("paused");
 492         case FINISHED_OK:
 493                 return N_("finished_ok");
 494         case FINISHED_ERROR:
 495                 return N_("finished_error");
 496         case FINISHED_CANCELLED:
 497                 return N_("finished_cancelled");
 498         }
 499
 500         return "";
 501 }
 502
 503 /** @return An estimate of the remaining time for this sub-job, in seconds */
 504 int
 505 Job::remaining_time () const
 506 {
 507         if (progress().get_value_or(0) == 0) {
 508                 return elapsed_sub_time ();
 509         }
 510
 511         return elapsed_sub_time() / progress().get() - elapsed_sub_time();
 512 }
 513
 514 void
 515 Job::cancel ()
 516 {
 517         if (!_thread) {
 518                 return;
 519         }
 520
 521         if (paused_by_user() || paused_by_priority()) {
 522                 resume ();
 523         }
 524
 525         _thread->interrupt ();
 526         DCPOMATIC_ASSERT (_thread->joinable ());
 527         _thread->join ();
 528         delete _thread;
 529         _thread = 0;
 530 }
 531
 532 /** @return true if the job was paused, false if it was not running */
 533 bool
 534 Job::pause_by_user ()
 535 {
 536         bool paused = false;
 537         {
 538                 boost::mutex::scoped_lock lm (_state_mutex);
 539                 /* We can set _state here directly because we have a lock and we aren't
 540                    setting the job to FINISHED_*
 541                 */
 542                 if (_state == RUNNING) {
 543                         paused = true;
 544                         _state = PAUSED_BY_USER;
 545                 }
 546         }
 547
 548         if (paused) {
 549                 _pause_changed.notify_all ();
 550         }
 551
 552         return paused;
 553 }
 554
 555 void
 556 Job::pause_by_priority ()
 557 {
 558         if (running ()) {
 559                 set_state (PAUSED_BY_PRIORITY);
 560                 _pause_changed.notify_all ();
 561         }
 562 }
 563
 564 void
 565 Job::resume ()
 566 {
 567         if (paused_by_user() || paused_by_priority()) {
 568                 set_state (RUNNING);
 569                 _pause_changed.notify_all ();
 570         }
 571 }
 572
 573 void
 574 Job::when_finished (boost::signals2::connection& connection, function<void()> finished)
 575 {
 576         boost::mutex::scoped_lock lm (_state_mutex);
 577         if (_state == FINISHED_OK || _state == FINISHED_ERROR || _state == FINISHED_CANCELLED) {
 578                 finished ();
 579         } else {
 580                 connection = Finished.connect (finished);
 581         }
 582 }
 583
 584 optional<string>
 585 Job::message () const
 586 {
 587         boost::mutex::scoped_lock lm (_state_mutex);
 588         return _message;
 589 }
 590
 591 void
 592 Job::set_message (string m)
 593 {
 594         boost::mutex::scoped_lock lm (_state_mutex);
 595         _message = m;
 596 }