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 "cross.h"
  29 #include "dcpomatic_log.h"
  30 #include "exceptions.h"
  31 #include "film.h"
  32 #include "job.h"
  33 #include "log.h"
  34 #include "util.h"
  35 #include <dcp/exceptions.h>
  36 #include <sub/exceptions.h>
  37 #include <boost/date_time/posix_time/posix_time.hpp>
  38 #include <boost/filesystem.hpp>
  39 #include <boost/thread.hpp>
  40 #include <iostream>
  41
  42 #include "i18n.h"
  43
  44
  45 using std::cout;
  46 using std::function;
  47 using std::list;
  48 using std::shared_ptr;
  49 using std::string;
  50 using boost::optional;
  51 using namespace dcpomatic;
  52
  53
  54 /** @param film Associated film, or 0 */
  55 Job::Job (shared_ptr<const Film> film)
  56         : _film (film)
  57         , _state (NEW)
  58         , _start_time (0)
  59         , _sub_start_time (0)
  60         , _progress (0)
  61         , _ran_for (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                 _state = s;
 347
 348                 if (_state == FINISHED_OK || _state == FINISHED_ERROR || _state == FINISHED_CANCELLED) {
 349                         _ran_for = time(0) - _start_time;
 350                         finished = true;
 351                         _sub_name.clear ();
 352                 }
 353         }
 354
 355         if (finished) {
 356                 emit (boost::bind (boost::ref (Finished)));
 357                 FinishedImmediate ();
 358         }
 359 }
 360
 361
 362 /** @return DCPTime (in seconds) that this sub-job has been running */
 363 int
 364 Job::elapsed_sub_time () const
 365 {
 366         if (_sub_start_time == 0) {
 367                 return 0;
 368         }
 369
 370         return time (0) - _sub_start_time;
 371 }
 372
 373
 374 /** Check to see if this job has been interrupted or paused */
 375 void
 376 Job::check_for_interruption_or_pause ()
 377 {
 378         boost::this_thread::interruption_point ();
 379
 380         boost::mutex::scoped_lock lm (_state_mutex);
 381         while (_state == PAUSED_BY_USER || _state == PAUSED_BY_PRIORITY) {
 382                 emit (boost::bind (boost::ref (Progress)));
 383                 _pause_changed.wait (lm);
 384         }
 385 }
 386
 387
 388 optional<float>
 389 Job::seconds_since_last_progress_update () const
 390 {
 391         boost::mutex::scoped_lock lm (_progress_mutex);
 392         if (!_last_progress_update) {
 393                 return {};
 394         }
 395
 396         struct timeval now;
 397         gettimeofday (&now, 0);
 398
 399         return seconds(now) - seconds(*_last_progress_update);
 400 }
 401
 402
 403 /** Set the progress of the current part of the job.
 404  *  @param p Progress (from 0 to 1)
 405  *  @param force Do not ignore this update, even if it hasn't been long since the last one.
 406  */
 407 void
 408 Job::set_progress (float p, bool force)
 409 {
 410         check_for_interruption_or_pause ();
 411
 412         if (!force) {
 413                 /* Check for excessively frequent progress reporting */
 414                 boost::mutex::scoped_lock lm (_progress_mutex);
 415                 struct timeval now;
 416                 gettimeofday (&now, 0);
 417                 if (_last_progress_update && _last_progress_update->tv_sec > 0) {
 418                         double const elapsed = seconds(now) - seconds(*_last_progress_update);
 419                         if (elapsed < 0.5) {
 420                                 return;
 421                         }
 422                 }
 423                 _last_progress_update = now;
 424         }
 425
 426         set_progress_common (p);
 427 }
 428
 429
 430 void
 431 Job::set_progress_common (optional<float> p)
 432 {
 433         {
 434                 boost::mutex::scoped_lock lm (_progress_mutex);
 435                 _progress = p;
 436         }
 437
 438         emit (boost::bind (boost::ref (Progress)));
 439 }
 440
 441
 442 /** @return fractional progress of the current sub-job, if known */
 443 optional<float>
 444 Job::progress () const
 445 {
 446         boost::mutex::scoped_lock lm (_progress_mutex);
 447         return _progress;
 448 }
 449
 450
 451 void
 452 Job::sub (string n)
 453 {
 454         {
 455                 boost::mutex::scoped_lock lm (_progress_mutex);
 456                 LOG_GENERAL ("Sub-job %1 starting", n);
 457                 _sub_name = n;
 458         }
 459
 460         set_progress (0, true);
 461         _sub_start_time = time (0);
 462 }
 463
 464
 465 string
 466 Job::error_details () const
 467 {
 468         boost::mutex::scoped_lock lm (_state_mutex);
 469         return _error_details;
 470 }
 471
 472
 473 /** @return A summary of any error that the job has generated */
 474 string
 475 Job::error_summary () const
 476 {
 477         boost::mutex::scoped_lock lm (_state_mutex);
 478         return _error_summary;
 479 }
 480
 481
 482 /** Set the current error string.
 483  *  @param s New error string.
 484  *  @param d New error detail string.
 485  */
 486 void
 487 Job::set_error (string s, string d)
 488 {
 489         if (_film) {
 490                 _film->log()->log (String::compose ("Error in job: %1 (%2)", s, d), LogEntry::TYPE_ERROR);
 491         }
 492
 493         boost::mutex::scoped_lock lm (_state_mutex);
 494         _error_summary = s;
 495         _error_details = d;
 496 }
 497
 498
 499 /** Say that this job's progress will be unknown until further notice */
 500 void
 501 Job::set_progress_unknown ()
 502 {
 503         check_for_interruption_or_pause ();
 504         set_progress_common (optional<float> ());
 505 }
 506
 507
 508 /** @return Human-readable status of this job */
 509 string
 510 Job::status () const
 511 {
 512         optional<float> p = progress ();
 513         int const t = elapsed_sub_time ();
 514         int const r = remaining_time ();
 515
 516         string s;
 517         if (!finished () && p) {
 518                 int pc = lrintf (p.get() * 100);
 519                 if (pc == 100) {
 520                         /* 100% makes it sound like we've finished when we haven't */
 521                         pc = 99;
 522                 }
 523
 524                 char buffer[64];
 525                 snprintf (buffer, sizeof(buffer), "%d%%", pc);
 526                 s += buffer;
 527
 528                 if (t > 10 && r > 0) {
 529                         auto now = boost::posix_time::second_clock::local_time();
 530                         auto finish = now + boost::posix_time::seconds(r);
 531                         char finish_string[16];
 532                         snprintf (finish_string, sizeof(finish_string), "%02d:%02d", int(finish.time_of_day().hours()), int(finish.time_of_day().minutes()));
 533                         string day;
 534                         if (now.date() != finish.date()) {
 535                                 /// TRANSLATORS: the %1 in this string will be filled in with a day of the week
 536                                 /// to say what day a job will finish.
 537                                 day = String::compose (_(" on %1"), day_of_week_to_string(finish.date().day_of_week()));
 538                         }
 539                         /// TRANSLATORS: "remaining; finishing at" here follows an amount of time that is remaining
 540                         /// on an operation; after it is an estimated wall-clock completion time.
 541                         s += String::compose(
 542                                 _("; %1 remaining; finishing at %2%3"),
 543                                 seconds_to_approximate_hms(r), finish_string, day
 544                                 );
 545                 }
 546         } else if (finished_ok ()) {
 547                 s = String::compose (_("OK (ran for %1)"), seconds_to_hms (_ran_for));
 548         } else if (finished_in_error ()) {
 549                 s = String::compose (_("Error: %1"), error_summary ());
 550         } else if (finished_cancelled ()) {
 551                 s = _("Cancelled");
 552         }
 553
 554         return s;
 555 }
 556
 557
 558 string
 559 Job::json_status () const
 560 {
 561         boost::mutex::scoped_lock lm (_state_mutex);
 562
 563         switch (_state) {
 564         case NEW:
 565                 return N_("new");
 566         case RUNNING:
 567                 return N_("running");
 568         case PAUSED_BY_USER:
 569         case PAUSED_BY_PRIORITY:
 570                 return N_("paused");
 571         case FINISHED_OK:
 572                 return N_("finished_ok");
 573         case FINISHED_ERROR:
 574                 return N_("finished_error");
 575         case FINISHED_CANCELLED:
 576                 return N_("finished_cancelled");
 577         }
 578
 579         return "";
 580 }
 581
 582
 583 /** @return An estimate of the remaining time for this sub-job, in seconds */
 584 int
 585 Job::remaining_time () const
 586 {
 587         if (progress().get_value_or(0) == 0) {
 588                 return elapsed_sub_time ();
 589         }
 590
 591         return elapsed_sub_time() / progress().get() - elapsed_sub_time();
 592 }
 593
 594
 595 void
 596 Job::cancel ()
 597 {
 598         if (_thread.joinable()) {
 599                 resume();
 600
 601                 _thread.interrupt ();
 602                 _thread.join ();
 603         }
 604
 605         set_state (FINISHED_CANCELLED);
 606 }
 607
 608
 609 /** @return true if the job was paused, false if it was not running */
 610 bool
 611 Job::pause_by_user ()
 612 {
 613         bool paused = false;
 614         {
 615                 boost::mutex::scoped_lock lm (_state_mutex);
 616                 /* We can set _state here directly because we have a lock and we aren't
 617                    setting the job to FINISHED_*
 618                 */
 619                 if (_state == RUNNING) {
 620                         paused = true;
 621                         _state = PAUSED_BY_USER;
 622                 }
 623         }
 624
 625         if (paused) {
 626                 _pause_changed.notify_all ();
 627         }
 628
 629         return paused;
 630 }
 631
 632
 633 void
 634 Job::pause_by_priority ()
 635 {
 636         if (running ()) {
 637                 set_state (PAUSED_BY_PRIORITY);
 638                 _pause_changed.notify_all ();
 639         }
 640 }
 641
 642
 643 void
 644 Job::resume ()
 645 {
 646         if (paused_by_user() || paused_by_priority()) {
 647                 set_state (RUNNING);
 648                 _pause_changed.notify_all ();
 649         }
 650 }
 651
 652
 653 void
 654 Job::when_finished (boost::signals2::connection& connection, function<void()> finished)
 655 {
 656         boost::mutex::scoped_lock lm (_state_mutex);
 657         if (_state == FINISHED_OK || _state == FINISHED_ERROR || _state == FINISHED_CANCELLED) {
 658                 finished ();
 659         } else {
 660                 connection = Finished.connect (finished);
 661         }
 662 }
 663
 664
 665 optional<string>
 666 Job::message () const
 667 {
 668         boost::mutex::scoped_lock lm (_state_mutex);
 669         return _message;
 670 }
 671
 672
 673 void
 674 Job::set_message (string m)
 675 {
 676         boost::mutex::scoped_lock lm (_state_mutex);
 677         _message = m;
 678 }