src/lib/job.cc

   1 /*
   2     Copyright (C) 2012-2021 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
  22 /** @file  src/job.cc
  23  *  @brief A parent class to represent long-running tasks which are run in their own thread.
  24  */
  25
  26
  27 #include "compose.hpp"
  28 #include "constants.h"
  29 #include "cross.h"
  30 #include "dcpomatic_log.h"
  31 #include "exceptions.h"
  32 #include "film.h"
  33 #include "job.h"
  34 #include "log.h"
  35 #include "util.h"
  36 #include <dcp/exceptions.h>
  37 #include <sub/exceptions.h>
  38 #include <boost/date_time/posix_time/posix_time.hpp>
  39 #include <boost/filesystem.hpp>
  40 #include <boost/thread.hpp>
  41 #include <time.h>
  42 #include <iostream>
  43
  44 #include "i18n.h"
  45
  46
  47 using std::cout;
  48 using std::function;
  49 using std::list;
  50 using std::shared_ptr;
  51 using std::string;
  52 using boost::optional;
  53 using namespace dcpomatic;
  54
  55
  56 /** @param film Associated film, or 0 */
  57 Job::Job (shared_ptr<const Film> film)
  58         : _film (film)
  59         , _state (NEW)
  60         , _sub_start_time (0)
  61         , _progress (0)
  62 {
  63
  64 }
  65
  66
  67 Job::~Job ()
  68 {
  69 #ifdef DCPOMATIC_DEBUG
  70         /* Any subclass should have called stop_thread in its destructor */
  71         assert (!_thread.joinable());
  72 #endif
  73 }
  74
  75
  76 void
  77 Job::stop_thread ()
  78 {
  79         boost::this_thread::disable_interruption dis;
  80
  81         _thread.interrupt ();
  82         try {
  83                 _thread.join ();
  84         } catch (...) {}
  85 }
  86
  87
  88 /** Start the job in a separate thread, returning immediately */
  89 void
  90 Job::start ()
  91 {
  92         set_state (RUNNING);
  93         _start_time = time (0);
  94         _sub_start_time = time (0);
  95         _thread = boost::thread (boost::bind(&Job::run_wrapper, this));
  96 #ifdef DCPOMATIC_LINUX
  97         pthread_setname_np (_thread.native_handle(), "job-wrapper");
  98 #endif
  99 }
 100
 101
 102 /** A wrapper for the ::run() method to catch exceptions */
 103 void
 104 Job::run_wrapper ()
 105 {
 106         start_of_thread (String::compose("Job-%1", json_name()));
 107
 108         try {
 109
 110                 run ();
 111
 112         } catch (dcp::FileError& e) {
 113
 114                 string m = String::compose (_("An error occurred whilst handling the file %1."), boost::filesystem::path (e.filename()).leaf());
 115
 116                 try {
 117                         auto const s = boost::filesystem::space (e.filename());
 118                         if (s.available < pow (1024, 3)) {
 119                                 m += N_("\n\n");
 120                                 m += _("The drive that the film is stored on is low in disc space.  Free some more space and try again.");
 121                         }
 122                 } catch (...) {
 123
 124                 }
 125
 126                 set_error (e.what(), m);
 127                 set_progress (1);
 128                 set_state (FINISHED_ERROR);
 129
 130         } catch (dcp::StartCompressionError& e) {
 131
 132                 bool done = false;
 133
 134 #ifdef DCPOMATIC_WINDOWS
 135 #if (__GNUC__ && !__x86_64__)
 136                 /* 32-bit */
 137                 set_error (
 138                         _("Failed to encode the DCP."),
 139                         _("This error has probably occurred because you are running the 32-bit version of DCP-o-matic and "
 140                           "trying to use too many encoding threads.  Please reduce the 'number of threads DCP-o-matic should "
 141                           "use' in the General tab of Preferences and try again.")
 142                         );
 143                 done = true;
 144 #else
 145                 /* 64-bit */
 146                 if (running_32_on_64()) {
 147                         set_error (
 148                                 _("Failed to encode the DCP."),
 149                                 _("This error has probably occurred because you are running the 32-bit version of DCP-o-matic.  Please re-install DCP-o-matic with the 64-bit installer and try again.")
 150                                 );
 151                         done = true;
 152                 }
 153 #endif
 154 #endif
 155
 156                 if (!done) {
 157                         set_error (
 158                                 e.what (),
 159                                 string (_("It is not known what caused this error.")) + "  " + REPORT_PROBLEM
 160                                 );
 161                 }
 162
 163                 set_progress (1);
 164                 set_state (FINISHED_ERROR);
 165
 166         } catch (OpenFileError& e) {
 167
 168                 set_error (
 169                         String::compose (_("Could not open %1"), e.file().string()),
 170                         String::compose (
 171                                 _("DCP-o-matic could not open the file %1 (%2).  Perhaps it does not exist or is in an unexpected format."),
 172                                 boost::filesystem::absolute (e.file()).string(),
 173                                 e.what()
 174                                 )
 175                         );
 176
 177                 set_progress (1);
 178                 set_state (FINISHED_ERROR);
 179
 180         } catch (boost::filesystem::filesystem_error& e) {
 181
 182                 if (e.code() == boost::system::errc::no_such_file_or_directory) {
 183                         set_error (
 184                                 String::compose (_("Could not open %1"), e.path1().string ()),
 185                                 String::compose (
 186                                         _("DCP-o-matic could not open the file %1 (%2).  Perhaps it does not exist or is in an unexpected format."),
 187                                         boost::filesystem::absolute (e.path1()).string(),
 188                                         e.what()
 189                                         )
 190                                 );
 191                 } else {
 192                         set_error (
 193                                 e.what (),
 194                                 string (_("It is not known what caused this error.")) + "  " + REPORT_PROBLEM
 195                                 );
 196                 }
 197
 198                 set_progress (1);
 199                 set_state (FINISHED_ERROR);
 200
 201         } catch (boost::thread_interrupted &) {
 202                 /* The job was cancelled; there's nothing else we need to do here */
 203         } catch (sub::SubripError& e) {
 204
 205                 string extra = "Error is near:\n";
 206                 for (auto i: e.context()) {
 207                         extra += i + "\n";
 208                 }
 209
 210                 set_error (e.what (), extra);
 211                 set_progress (1);
 212                 set_state (FINISHED_ERROR);
 213
 214         } catch (std::bad_alloc& e) {
 215
 216                 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."));
 217                 set_progress (1);
 218                 set_state (FINISHED_ERROR);
 219
 220         } catch (dcp::ReadError& e) {
 221
 222                 set_error (e.message(), e.detail().get_value_or(""));
 223                 set_progress (1);
 224                 set_state (FINISHED_ERROR);
 225
 226         } catch (KDMError& e) {
 227
 228                 set_error (e.summary(), e.detail());
 229                 set_progress (1);
 230                 set_state (FINISHED_ERROR);
 231
 232         } catch (FileError& e) {
 233
 234                 set_error (e.what(), e.what());
 235                 set_progress (1);
 236                 set_state (FINISHED_ERROR);
 237
 238         } catch (CPLNotFoundError& e) {
 239
 240                 set_error(e.what());
 241                 set_progress(1);
 242                 set_state(FINISHED_ERROR);
 243
 244         } catch (std::exception& e) {
 245
 246                 set_error (
 247                         e.what (),
 248                         string (_("It is not known what caused this error.")) + "  " + REPORT_PROBLEM
 249                         );
 250
 251                 set_progress (1);
 252                 set_state (FINISHED_ERROR);
 253
 254         } catch (...) {
 255
 256                 set_error (
 257                         _("Unknown error"),
 258                         string (_("It is not known what caused this error.")) + "  " + REPORT_PROBLEM
 259                         );
 260
 261                 set_progress (1);
 262                 set_state (FINISHED_ERROR);
 263         }
 264 }
 265
 266
 267 /** @return true if this job is new (ie has not started running) */
 268 bool
 269 Job::is_new () const
 270 {
 271         boost::mutex::scoped_lock lm (_state_mutex);
 272         return _state == NEW;
 273 }
 274
 275
 276 /** @return true if the job is running */
 277 bool
 278 Job::running () const
 279 {
 280         boost::mutex::scoped_lock lm (_state_mutex);
 281         return _state == RUNNING;
 282 }
 283
 284
 285 /** @return true if the job has finished (either successfully or unsuccessfully) */
 286 bool
 287 Job::finished () const
 288 {
 289         boost::mutex::scoped_lock lm (_state_mutex);
 290         return _state == FINISHED_OK || _state == FINISHED_ERROR || _state == FINISHED_CANCELLED;
 291 }
 292
 293
 294 /** @return true if the job has finished successfully */
 295 bool
 296 Job::finished_ok () const
 297 {
 298         boost::mutex::scoped_lock lm (_state_mutex);
 299         return _state == FINISHED_OK;
 300 }
 301
 302
 303 /** @return true if the job has finished unsuccessfully */
 304 bool
 305 Job::finished_in_error () const
 306 {
 307         boost::mutex::scoped_lock lm (_state_mutex);
 308         return _state == FINISHED_ERROR;
 309 }
 310
 311
 312 bool
 313 Job::finished_cancelled () const
 314 {
 315         boost::mutex::scoped_lock lm (_state_mutex);
 316         return _state == FINISHED_CANCELLED;
 317 }
 318
 319
 320 bool
 321 Job::paused_by_user () const
 322 {
 323         boost::mutex::scoped_lock lm (_state_mutex);
 324         return _state == PAUSED_BY_USER;
 325 }
 326
 327
 328 bool
 329 Job::paused_by_priority () const
 330 {
 331         boost::mutex::scoped_lock lm (_state_mutex);
 332         return _state == PAUSED_BY_PRIORITY;
 333 }
 334
 335
 336 /** Set the state of this job.
 337  *  @param s New state.
 338  */
 339 void
 340 Job::set_state (State s)
 341 {
 342         bool finished = false;
 343
 344         {
 345                 boost::mutex::scoped_lock lm (_state_mutex);
 346                 if (_state == s) {
 347                         return;
 348                 }
 349
 350                 _state = s;
 351
 352                 if (_state == FINISHED_OK || _state == FINISHED_ERROR || _state == FINISHED_CANCELLED) {
 353                         _finish_time = time(nullptr);
 354                         finished = true;
 355                         _sub_name.clear ();
 356                 }
 357         }
 358
 359         if (finished) {
 360                 auto const result = state_to_result(s);
 361                 emit(boost::bind(boost::ref(Finished), result));
 362                 FinishedImmediate(result);
 363         }
 364 }
 365
 366
 367 Job::Result
 368 Job::state_to_result(State state) const
 369 {
 370         switch (state) {
 371         case FINISHED_OK:
 372                 return Result::RESULT_OK;
 373         case FINISHED_ERROR:
 374                 return Result::RESULT_ERROR;
 375         case FINISHED_CANCELLED:
 376                 return Result::RESULT_CANCELLED;
 377         default:
 378                 DCPOMATIC_ASSERT(false);
 379         };
 380
 381         DCPOMATIC_ASSERT(false);
 382 }
 383
 384
 385 /** @return DCPTime (in seconds) that this sub-job has been running */
 386 int
 387 Job::elapsed_sub_time () const
 388 {
 389         if (_sub_start_time == 0) {
 390                 return 0;
 391         }
 392
 393         return time (0) - _sub_start_time;
 394 }
 395
 396
 397 /** Check to see if this job has been interrupted or paused */
 398 void
 399 Job::check_for_interruption_or_pause ()
 400 {
 401         boost::this_thread::interruption_point ();
 402
 403         boost::mutex::scoped_lock lm (_state_mutex);
 404         while (_state == PAUSED_BY_USER || _state == PAUSED_BY_PRIORITY) {
 405                 emit (boost::bind (boost::ref (Progress)));
 406                 _pause_changed.wait (lm);
 407         }
 408 }
 409
 410
 411 optional<float>
 412 Job::seconds_since_last_progress_update () const
 413 {
 414         boost::mutex::scoped_lock lm (_progress_mutex);
 415         if (!_last_progress_update) {
 416                 return {};
 417         }
 418
 419         struct timeval now;
 420         gettimeofday (&now, 0);
 421
 422         return seconds(now) - seconds(*_last_progress_update);
 423 }
 424
 425
 426 /** Set the progress of the current part of the job.
 427  *  @param p Progress (from 0 to 1)
 428  *  @param force Do not ignore this update, even if it hasn't been long since the last one.
 429  */
 430 void
 431 Job::set_progress (float p, bool force)
 432 {
 433         check_for_interruption_or_pause ();
 434
 435         if (!force) {
 436                 /* Check for excessively frequent progress reporting */
 437                 boost::mutex::scoped_lock lm (_progress_mutex);
 438                 struct timeval now;
 439                 gettimeofday (&now, 0);
 440                 if (_last_progress_update && _last_progress_update->tv_sec > 0) {
 441                         double const elapsed = seconds(now) - seconds(*_last_progress_update);
 442                         if (elapsed < 0.5) {
 443                                 return;
 444                         }
 445                 }
 446                 _last_progress_update = now;
 447         }
 448
 449         set_progress_common (p);
 450 }
 451
 452
 453 void
 454 Job::set_progress_common (optional<float> p)
 455 {
 456         {
 457                 boost::mutex::scoped_lock lm (_progress_mutex);
 458                 _progress = p;
 459         }
 460
 461         emit (boost::bind (boost::ref (Progress)));
 462 }
 463
 464
 465 /** @return fractional progress of the current sub-job, if known */
 466 optional<float>
 467 Job::progress () const
 468 {
 469         boost::mutex::scoped_lock lm (_progress_mutex);
 470         return _progress;
 471 }
 472
 473
 474 void
 475 Job::sub (string n)
 476 {
 477         {
 478                 boost::mutex::scoped_lock lm (_progress_mutex);
 479                 LOG_GENERAL ("Sub-job %1 starting", n);
 480                 _sub_name = n;
 481         }
 482
 483         set_progress (0, true);
 484         _sub_start_time = time (0);
 485 }
 486
 487
 488 string
 489 Job::error_details () const
 490 {
 491         boost::mutex::scoped_lock lm (_state_mutex);
 492         return _error_details;
 493 }
 494
 495
 496 /** @return A summary of any error that the job has generated */
 497 string
 498 Job::error_summary () const
 499 {
 500         boost::mutex::scoped_lock lm (_state_mutex);
 501         return _error_summary;
 502 }
 503
 504
 505 /** Set the current error string.
 506  *  @param s New error string.
 507  *  @param d New error detail string.
 508  */
 509 void
 510 Job::set_error (string s, string d)
 511 {
 512         if (_film) {
 513                 _film->log()->log (String::compose ("Error in job: %1 (%2)", s, d), LogEntry::TYPE_ERROR);
 514         }
 515
 516         boost::mutex::scoped_lock lm (_state_mutex);
 517         _error_summary = s;
 518         _error_details = d;
 519 }
 520
 521
 522 /** Say that this job's progress will be unknown until further notice */
 523 void
 524 Job::set_progress_unknown ()
 525 {
 526         check_for_interruption_or_pause ();
 527         set_progress_common (optional<float> ());
 528 }
 529
 530
 531 /** @return Human-readable status of this job */
 532 string
 533 Job::status () const
 534 {
 535         optional<float> p = progress ();
 536         int const t = elapsed_sub_time ();
 537         int const r = remaining_time ();
 538
 539         auto day_of_week_to_string = [](boost::gregorian::greg_weekday d) -> std::string {
 540                 switch (d.as_enum()) {
 541                 case boost::date_time::Sunday:
 542                         return _("Sunday");
 543                 case boost::date_time::Monday:
 544                         return _("Monday");
 545                 case boost::date_time::Tuesday:
 546                         return _("Tuesday");
 547                 case boost::date_time::Wednesday:
 548                         return _("Wednesday");
 549                 case boost::date_time::Thursday:
 550                         return _("Thursday");
 551                 case boost::date_time::Friday:
 552                         return _("Friday");
 553                 case boost::date_time::Saturday:
 554                         return _("Saturday");
 555                 }
 556
 557                 return d.as_long_string();
 558         };
 559
 560         string s;
 561         if (!finished () && p) {
 562                 int pc = lrintf (p.get() * 100);
 563                 if (pc == 100) {
 564                         /* 100% makes it sound like we've finished when we haven't */
 565                         pc = 99;
 566                 }
 567
 568                 char buffer[64];
 569                 snprintf (buffer, sizeof(buffer), "%d%%", pc);
 570                 s += buffer;
 571
 572                 if (t > 10 && r > 0) {
 573                         auto now = boost::posix_time::second_clock::local_time();
 574                         auto finish = now + boost::posix_time::seconds(r);
 575                         char finish_string[16];
 576                         snprintf (finish_string, sizeof(finish_string), "%02d:%02d", int(finish.time_of_day().hours()), int(finish.time_of_day().minutes()));
 577                         string day;
 578                         if (now.date() != finish.date()) {
 579                                 /// TRANSLATORS: the %1 in this string will be filled in with a day of the week
 580                                 /// to say what day a job will finish.
 581                                 day = String::compose (_(" on %1"), day_of_week_to_string(finish.date().day_of_week()));
 582                         }
 583                         /// TRANSLATORS: "remaining; finishing at" here follows an amount of time that is remaining
 584                         /// on an operation; after it is an estimated wall-clock completion time.
 585                         s += String::compose(
 586                                 _("; %1 remaining; finishing at %2%3"),
 587                                 seconds_to_approximate_hms(r), finish_string, day
 588                                 );
 589                 }
 590         } else if (finished_ok ()) {
 591                 auto time_string = [](time_t time) {
 592                         auto tm = localtime(&time);
 593                         char buffer[8];
 594                         snprintf(buffer, sizeof(buffer), "%02d:%02d", tm->tm_hour, tm->tm_min);
 595                         return string(buffer);
 596                 };
 597                 auto const duration = _finish_time - _start_time;
 598                 if (duration < 10) {
 599                         /* It took less than 10 seconds; it doesn't seem worth saying how long it took */
 600                         s = _("OK");
 601                 } else if (duration < 600) {
 602                         /* It took less than 10 minutes; it doesn't seem worth saying when it started and finished */
 603                         s = String::compose(_("OK (ran for %1)"), seconds_to_hms(duration));
 604                 } else {
 605                         s = String::compose(_("OK (ran for %1 from %2 to %3)"),  seconds_to_hms(duration), time_string(_start_time), time_string(_finish_time));
 606                 }
 607         } else if (finished_in_error ()) {
 608                 s = String::compose (_("Error: %1"), error_summary ());
 609         } else if (finished_cancelled ()) {
 610                 s = _("Cancelled");
 611         }
 612
 613         return s;
 614 }
 615
 616
 617 string
 618 Job::json_status () const
 619 {
 620         boost::mutex::scoped_lock lm (_state_mutex);
 621
 622         switch (_state) {
 623         case NEW:
 624                 return N_("new");
 625         case RUNNING:
 626                 return N_("running");
 627         case PAUSED_BY_USER:
 628         case PAUSED_BY_PRIORITY:
 629                 return N_("paused");
 630         case FINISHED_OK:
 631                 return N_("finished_ok");
 632         case FINISHED_ERROR:
 633                 return N_("finished_error");
 634         case FINISHED_CANCELLED:
 635                 return N_("finished_cancelled");
 636         }
 637
 638         return "";
 639 }
 640
 641
 642 /** @return An estimate of the remaining time for this sub-job, in seconds */
 643 int
 644 Job::remaining_time () const
 645 {
 646         if (progress().get_value_or(0) == 0) {
 647                 return elapsed_sub_time ();
 648         }
 649
 650         return elapsed_sub_time() / progress().get() - elapsed_sub_time();
 651 }
 652
 653
 654 void
 655 Job::cancel ()
 656 {
 657         if (_thread.joinable()) {
 658                 resume();
 659
 660                 _thread.interrupt ();
 661                 _thread.join ();
 662         }
 663
 664         set_state (FINISHED_CANCELLED);
 665 }
 666
 667
 668 /** @return true if the job was paused, false if it was not running */
 669 bool
 670 Job::pause_by_user ()
 671 {
 672         bool paused = false;
 673         {
 674                 boost::mutex::scoped_lock lm (_state_mutex);
 675                 /* We can set _state here directly because we have a lock and we aren't
 676                    setting the job to FINISHED_*
 677                 */
 678                 if (_state == RUNNING) {
 679                         paused = true;
 680                         _state = PAUSED_BY_USER;
 681                 }
 682         }
 683
 684         if (paused) {
 685                 _pause_changed.notify_all ();
 686         }
 687
 688         return paused;
 689 }
 690
 691
 692 void
 693 Job::pause_by_priority ()
 694 {
 695         if (running ()) {
 696                 set_state (PAUSED_BY_PRIORITY);
 697                 _pause_changed.notify_all ();
 698         }
 699 }
 700
 701
 702 void
 703 Job::resume ()
 704 {
 705         if (paused_by_user() || paused_by_priority()) {
 706                 set_state (RUNNING);
 707                 _pause_changed.notify_all ();
 708         }
 709 }
 710
 711
 712 void
 713 Job::when_finished(boost::signals2::connection& connection, function<void(Result)> finished)
 714 {
 715         boost::mutex::scoped_lock lm (_state_mutex);
 716         if (_state == FINISHED_OK || _state == FINISHED_ERROR || _state == FINISHED_CANCELLED) {
 717                 finished(state_to_result(_state));
 718         } else {
 719                 connection = Finished.connect (finished);
 720         }
 721 }
 722
 723
 724 optional<string>
 725 Job::message () const
 726 {
 727         boost::mutex::scoped_lock lm (_state_mutex);
 728         return _message;
 729 }
 730
 731
 732 void
 733 Job::set_message (string m)
 734 {
 735         boost::mutex::scoped_lock lm (_state_mutex);
 736         _message = m;
 737 }