diff --git a/i18n/de_frontend.json b/i18n/de_frontend.json index 3e8bb5b..5b6055c 100644 --- a/i18n/de_frontend.json +++ b/i18n/de_frontend.json @@ -4,6 +4,9 @@ "template_saved": "Template wurde gespeichert", "print_in_progress": "Foto wird gedruckt...", "printer_error": "Drucker wurde gestoppt", + "printer_no_paper": "Druckerpapier fehlt", + "printer_no_ink": "Druckertinte leer", + "printer_no_tray": "Drucker-Papierkassette fehlt", "check_camera": "Prüfe deine Kamera", "no_storage_found": "Kein Speichermedium gefunden", "storage_space_low": "Geringe Speicherkapazität: ", diff --git a/i18n/en_frontend.json b/i18n/en_frontend.json index 8c14944..6b95780 100644 --- a/i18n/en_frontend.json +++ b/i18n/en_frontend.json @@ -4,6 +4,9 @@ "template_saved": "Template saved successfully", "print_in_progress": "Printing in Progress...", "printer_error": "Printer Error!", + "printer_no_paper": "Printer out of paper", + "printer_no_ink": "Printer out of ink", + "printer_no_tray": "Printer's input tray is missing", "check_camera": "Please check your camera", "no_storage_found": "No USB Storage found", "storage_space_low": "Low Storage: ", diff --git a/i18n/fr_frontend.json b/i18n/fr_frontend.json index 245eecf..2cecf38 100644 --- a/i18n/fr_frontend.json +++ b/i18n/fr_frontend.json @@ -4,6 +4,9 @@ "template_saved": "Gabarit chargé avec succès.", "print_in_progress": "Impression en cours...", "printer_error": "Erreur d'impression !", + "printer_no_paper": "Papier d'imprimante épuisé", + "printer_no_ink": "Encre d'imprimante épuisé", + "printer_no_tray": "Bac à papier de l'imprimante absent", "check_camera": "Veuillez vérifier votre caméra.", "no_storage_found": "Clé USB introuvable.", "storage_space_low": "Clé USB pleine : ", diff --git a/src/logic/BoothLogic.cpp b/src/logic/BoothLogic.cpp index e1c9931..ebd377d 100644 --- a/src/logic/BoothLogic.cpp +++ b/src/logic/BoothLogic.cpp @@ -43,10 +43,11 @@ bool BoothLogic::start() { return false; // Start the threads - isLogicThreadRunning = isCameraThreadRunning = isPrinterThreadRunning = true; + isLogicThreadRunning = isCameraThreadRunning = isPrinterThreadRunning = isPrintMonitoringThreadRunning = true; logicThreadHandle = boost::thread(boost::bind(&BoothLogic::logicThread, this)); cameraThreadHandle = boost::thread(boost::bind(&BoothLogic::cameraThread, this)); printThreadHandle = boost::thread(boost::bind(&BoothLogic::printerThread, this)); + printMonitoringThreadHandle = boost::thread(boost::bind(&BoothLogic::printMonitoringThread, this)); return true; } @@ -94,6 +95,11 @@ void BoothLogic::stop(bool update_mode) { LOG_D(TAG, "waiting for print"); printThreadHandle.join(); } + isPrintMonitoringThreadRunning = false; + if (printMonitoringThreadHandle.joinable()) { + LOG_D(TAG, "waiting for print monitoring"); + printMonitoringThreadHandle.join(); + } if (gui != nullptr) { gui->stop(); @@ -368,6 +374,11 @@ void BoothLogic::printerThread() { LOG_D(TAG, "[Printer Thread] Processing image. Printing enabled: ", std::to_string(do_print));; if (do_print) { + ImagePrintMetrics metrics = {}; + metrics.jobState = JOB_STATE_UNKNOWN; + metrics.printerNeededAttention = false; + clock_gettime(CLOCK_REALTIME, &metrics.processingTs); + // We need the final jpeg image. So lock the mutex { boost::unique_lock lk(jpegImageMutex); @@ -396,6 +407,8 @@ void BoothLogic::printerThread() { LOG_D(TAG, "[Printer Thread] Prepared"); } + clock_gettime(CLOCK_REALTIME, &metrics.awaitUserDecisionTs); + { LOG_D(TAG, "[Printer Thread] Waiting for user to decide if they want to print"); boost::unique_lock lk(printerStateMutex); @@ -404,6 +417,7 @@ void BoothLogic::printerThread() { } } + clock_gettime(CLOCK_REALTIME, &metrics.gotUserDecisionTs); // We need the info if the user wants to print or not if (printConfirmationEnabled) { @@ -411,10 +425,11 @@ void BoothLogic::printerThread() { boost::unique_lock lk(cancelOrConfirmPrintMutex); if (printConfirmed) { LOG_D(TAG, "[Printer Thread] Printing (user explicitely confirmed)"); - printerManager.printImage(); + metrics.cupsJobId = printerManager.printImage(); } else { LOG_D(TAG, "[Printer Thread] Print not confirmed (auto-canceling)!"); printerManager.cancelPrint(); + metrics.cupsJobId = -1; } } else { @@ -422,12 +437,20 @@ void BoothLogic::printerThread() { boost::unique_lock lk(cancelOrConfirmPrintMutex); if (!printCanceled) { LOG_D(TAG, "[Printer Thread] Printing (user did not cancel)"); - printerManager.printImage(); + metrics.cupsJobId = printerManager.printImage(); } else { LOG_D(TAG, "[Printer Thread] Print canceled by user!"); printerManager.cancelPrint(); + metrics.cupsJobId = -1; } } + + // if job ID > 0, add this job to the list of jobs monitored by the print monitoring thread; + // otherwise the already known timing values could be logged here (don't seem relevant at the moment) + if(metrics.cupsJobId > 0) { + boost::unique_lock lk(printMetricsMutex); + printMetrics.push_back(metrics); + } } else { // We need the final jpeg image. So lock the mutex { @@ -469,6 +492,129 @@ void BoothLogic::printerThread() { } } +#define CTIME_NO_NL(x) strtok(ctime(x), "\n") + +int BoothLogic::difftimeSeconds(time_t later, time_t earlier) { + // starting epoch timestamp is zero (i.e. has not been set) indicate invalid timediff + if (earlier == 0) + return -1; + + // replace missing timestamp with "now" + // please note that this may not be accurate and depends on the period time of the thread + if (later == 0) { + timespec tnow; + clock_gettime(CLOCK_REALTIME, &tnow); + later = tnow.tv_sec; + } + + return difftime(later, earlier); +} + +void BoothLogic::printMonitoringThread() { + LOG_D(TAG, "Starting Print Monitoring Thread"); + + while (isPrintMonitoringThreadRunning) { + size_t listLength = 0; + { + boost::unique_lock lk(printMetricsMutex); + + unsigned int printerAttentionFlags = 0; // reset flags + + std::list::iterator it = printMetrics.begin(); + while (it != printMetrics.end()) { + int jobId = it->cupsJobId; + + PrinterJobState jobState; + + time_t cupsCreationTs, cupsProcessingTs, cupsCompletedTs; + + bool gotJobDetails = printerManager.getJobDetails(jobId, jobState, cupsCreationTs, + cupsProcessingTs, cupsCompletedTs); + + if (gotJobDetails) { + // copy job details from printer manager + it->jobState = jobState; + it->cupsCreationTs = cupsCreationTs; + it->cupsProcessingTs = cupsProcessingTs; + it->cupsCompletedTs = cupsCompletedTs; + + // "now" is a good reference timestamp + timespec tnow; + clock_gettime(CLOCK_REALTIME, &tnow); + + LOG_D(TAG, "[Print Mon Thread] CUPS job #", std::to_string(jobId) + + " in state: " + std::string(printerManager.printerJobStateToString(it->jobState))); + + if (JOB_STATE_UNKNOWN == jobState || JOB_STATE_CANCELED == jobState || + JOB_STATE_ABORTED == jobState || JOB_STATE_COMPLETED == jobState) { + // job is in a state where it is no longer monitored ("stopped" is excluded on purpose) + LOG_D(TAG, "[Print Mon Thread] Erasing print job from metrics list: #", std::to_string(jobId)); + LOG_D(TAG, "[Print Mon Thread] CUPS creation timestamp: ", std::string(CTIME_NO_NL(&cupsCreationTs))); + + // finally, it's time to emit (log) the collected metrics; + // let's use full seconds only (values are floor'ed not rounded for sake of simplicity! + // CUPS timestamps have second granularity anyway) + int durationCupsCreation2CupsProc = difftimeSeconds(cupsProcessingTs, cupsCreationTs); + int durationCupsProc2CupsCompl = difftimeSeconds(cupsCompletedTs, cupsProcessingTs); + + std::string csvLine = std::to_string(jobId) + + ";\"" + std::string(CTIME_NO_NL(&cupsCreationTs)) + + "\";\"" + std::string(printerManager.printerJobStateToString(it->jobState)) + + "\";" + std::to_string(durationCupsCreation2CupsProc) + ";" + + std::to_string(durationCupsProc2CupsCompl) + ";" + + std::to_string(it->printerNeededAttention); + LOG_D(TAG, "[Print Mon Thread] CSV>", csvLine); + + printMetrics.erase(it++); + } else { + // job is in a state where it will be still monitored + + if (JOB_STATE_PROCESSING == jobState) { + // when the job is being processed, we can check if the printer needs attention + // e.g. has run out of paper or ink or the input tray is missing; + // we could also let the user know that the processing duration has exceeded a certain threshold + int durationProcessing = difftime(tnow.tv_sec, cupsProcessingTs); + LOG_D(TAG, "[Print Mon Thread] CUPS job has been processing for [seconds]: ", std::to_string(durationProcessing)); + unsigned int currentPrinterAttentionFlags = 0; + printerManager.checkPrinterAttentionFromJob(jobId, currentPrinterAttentionFlags); + printerAttentionFlags |= currentPrinterAttentionFlags; + + if (currentPrinterAttentionFlags != 0) { + it->printerNeededAttention = true; // set sticky flag + } + } + + ++it; + } + } else { + // didn't get job details but need to increment the iterator anyway + ++it; + } + } + listLength = printMetrics.size(); + //LOG_D(TAG, "[Print Mon Thread] Length of metrics list: ", std::to_string(listLength)); + //LOG_D(TAG, "[Print Mon Thread] Printer attention flags: ", std::to_string(printerAttentionFlags)); + + if ((printerAttentionFlags != 0) && printerEnabled) { + // as only one flag is checked at a time, they are ordered by attention relevance + // or "level of attention/action/expertise", i.e. changing the ink cartridge may be "harder" to do + if (printerAttentionFlags & PRINTER_ATTN_NO_INK) { + gui->addAlert(ALERT_PRINTER_JOB_HINT, getTranslation("frontend.printer_no_ink")); + } else if(printerAttentionFlags & PRINTER_ATTN_NO_TRAY) { + gui->addAlert(ALERT_PRINTER_JOB_HINT, getTranslation("frontend.printer_no_tray")); + } else if(printerAttentionFlags & PRINTER_ATTN_NO_PAPER) { + gui->addAlert(ALERT_PRINTER_JOB_HINT, getTranslation("frontend.printer_no_paper")); + } + } else { + gui->removeAlert(ALERT_PRINTER_JOB_HINT); + } + } + + // this thread keeps polling periodically + boost::this_thread::sleep(boost::posix_time::milliseconds(5000)); + } +} + int BoothLogic::getFreeStorageSpaceMB() { if (imageDir.empty()) { LOG_E(TAG, "No image dir specified!"); diff --git a/src/logic/BoothLogic.h b/src/logic/BoothLogic.h index 603df5e..6f07fb3 100644 --- a/src/logic/BoothLogic.h +++ b/src/logic/BoothLogic.h @@ -57,6 +57,27 @@ namespace selfomat { PRINTER_STATE_WORKING = 3 }; + struct ImagePrintMetrics { + // Timestamp when processing in printer thread has started + timespec processingTs; + // Timestamp when processing in printer thread has finished and waiting for user decision started + timespec awaitUserDecisionTs; + // Timestamp when user decision (confirmation or cancellation) has arrived in printer thread + timespec gotUserDecisionTs; + // Job ID returned from CUPS (or 0 on CUPS error or when print has been canceled) + int cupsJobId; + // Timestamp when the CUPS job was created + time_t cupsCreationTs; + // Timestamp when the CUPS job was processed + time_t cupsProcessingTs; + // Timestamp when the CUPS job was completed + time_t cupsCompletedTs; + // Job state returned by CUPS and converted to PrinterManager-specific type + PrinterJobState jobState; + // Boolean flag indicating that the printer needed attention during this job + bool printerNeededAttention; + }; + class BoothLogic : public ILogicController { public: explicit BoothLogic(ICamera *camera, IGui *gui, bool has_button, const string &button_port, bool has_flash, @@ -115,7 +136,7 @@ namespace selfomat { PrinterManager printerManager; ImageProcessor imageProcessor; - bool isLogicThreadRunning, isCameraThreadRunning, isPrinterThreadRunning; + bool isLogicThreadRunning, isCameraThreadRunning, isPrinterThreadRunning, isPrintMonitoringThreadRunning; boost::mutex triggerMutex; bool triggered; @@ -153,6 +174,7 @@ namespace selfomat { boost::thread logicThreadHandle; boost::thread cameraThreadHandle; boost::thread printThreadHandle; + boost::thread printMonitoringThreadHandle; int filterChoice = 0; double filterGain = 1.0; @@ -165,11 +187,10 @@ namespace selfomat { void logicThread(); - - - void printerThread(); + void printMonitoringThread(); + void triggerFlash(); int getFreeStorageSpaceMB(); @@ -181,7 +202,12 @@ namespace selfomat { FILTER getFilter(); + int difftimeSeconds(time_t later, time_t earlier); + timespec triggerStart; + + std::list printMetrics; + boost::mutex printMetricsMutex; public: bool isStopped(); void trigger(); @@ -209,6 +235,9 @@ namespace selfomat { if (printThreadHandle.joinable()) { printThreadHandle.join(); } + if (printMonitoringThreadHandle.joinable()) { + printMonitoringThreadHandle.join(); + } if (returnCode == -1) { reboot(LINUX_REBOOT_CMD_POWER_OFF); diff --git a/src/logic/PrinterManager.cpp b/src/logic/PrinterManager.cpp index 749b211..7493a0a 100644 --- a/src/logic/PrinterManager.cpp +++ b/src/logic/PrinterManager.cpp @@ -1,4 +1,5 @@ #include +#include // // Created by clemens on 12.02.19. @@ -178,6 +179,8 @@ bool PrinterManager::resumePrinter() { LOG_E(TAG, "Cannot enable printer:", cupsLastErrorString()); + httpClose(http); + return false; } @@ -188,6 +191,8 @@ bool PrinterManager::resumePrinter() { ippDelete(cupsDoRequest(http, request, "/admin/")); + httpClose(http); + if (cupsLastError() > IPP_STATUS_OK_CONFLICTING) { LOG_E(TAG, "Cannot resume printer:", cupsLastErrorString()); @@ -200,25 +205,24 @@ bool PrinterManager::resumePrinter() { return true; } -bool PrinterManager::printImage() { +int PrinterManager::printImage() { if(!hasImagePrepared || printer_name.empty()) - return false; + return 0; resumePrinter(); + // Job ID or 0 on error int job_id = cupsCreateJob(CUPS_HTTP_DEFAULT, printer_name.c_str(), "self-o-mat", 0, nullptr); if (job_id > 0) { LOG_D(TAG, "successfully created the print job"); cupsStartDocument(CUPS_HTTP_DEFAULT, printer_name.c_str(), job_id, "my_image", "image/png", 1); - cupsWriteRequestData(CUPS_HTTP_DEFAULT, (const char *) imageTmpBuffer, sizeOfPreparedImage); cupsFinishDocument(CUPS_HTTP_DEFAULT, printer_name.c_str()); - return true; } - return false; + return job_id; } PrinterManager::PrinterManager(ILogger *logger) : logger(logger) { @@ -249,3 +253,150 @@ bool PrinterManager::cancelPrint() { return true; } +bool PrinterManager::getJobDetails(int jobId, PrinterJobState &state, time_t &creationTs, time_t &processingTs, time_t &completedTs) { + if(jobId <= 0) + return false; + + boost::unique_lock lk(printerStateMutex); + + cups_job_t *cupsJobs; + int cupsJobCount = cupsGetJobs2(CUPS_HTTP_DEFAULT, &cupsJobs, NULL, 0, CUPS_WHICHJOBS_ALL); + //LOG_D(TAG, "Number of print jobs: ", std::to_string(cupsJobCount)); + + for(int i = 0; i < cupsJobCount; i++) { + if (cupsJobs[i].id == jobId) { + //LOG_D(TAG, "Found print job with ID #", std::to_string(jobId)); + + creationTs = cupsJobs[i].creation_time; + processingTs = cupsJobs[i].processing_time; + completedTs = cupsJobs[i].completed_time; + + switch(cupsJobs[i].state) + { + // map known values + case IPP_JOB_PENDING: + state = JOB_STATE_PENDING; + break; + case IPP_JOB_HELD: + state = JOB_STATE_HELD; + break; + case IPP_JOB_PROCESSING: + state = JOB_STATE_PROCESSING; + break; + case IPP_JOB_STOPPED: + state = JOB_STATE_STOPPED; + break; + case IPP_JOB_CANCELLED: + state = JOB_STATE_CANCELED; + break; + case IPP_JOB_ABORTED: + state = JOB_STATE_ABORTED; + break; + case IPP_JOB_COMPLETED: + state = JOB_STATE_COMPLETED; + break; + default: + state = JOB_STATE_UNKNOWN; + break; + } + return true; + } + } + + return false; +} + +const char* PrinterManager::printerJobStateToString(PrinterJobState &state) { + switch(state) + { + // map known values + case JOB_STATE_PENDING: + return "pending"; + case JOB_STATE_HELD: + return "held"; + case JOB_STATE_PROCESSING: + return "processing"; + case JOB_STATE_STOPPED: + return "stopped"; + case JOB_STATE_CANCELED: + return "canceled"; + case JOB_STATE_ABORTED: + return "aborted"; + case JOB_STATE_COMPLETED: + return "completed"; + case JOB_STATE_UNKNOWN: + default: + return "unknown"; + } +} + +void PrinterManager::checkPrinterAttentionFromJob(int jobId, unsigned int &flags) { + if(jobId <= 0) + return; + + boost::unique_lock lk(printerStateMutex); + + //LOG_D(TAG, "Querying attributes for print job with ID #", std::to_string(jobId)); + + http_t *http; + ipp_t *request; + ipp_t *response; + char uri[HTTP_MAX_URI]; + char job_printer_state_reasons[2048]; + ipp_attribute_t *attr; + + http = httpConnect2(cupsServer(), + ippPort(), + NULL, + AF_UNSPEC, + cupsEncryption(), + 1, + 30000, + NULL); + + + httpAssembleURIf(HTTP_URI_CODING_ALL, uri, sizeof(uri), "ipp", NULL, "localhost", ippPort(), "/printers/%s", printer_name.c_str()); + + request = ippNewRequest(IPP_OP_GET_JOB_ATTRIBUTES); + ippAddString(request, IPP_TAG_OPERATION, IPP_TAG_URI, "printer-uri", NULL, uri); + ippAddInteger(request, IPP_TAG_OPERATION, IPP_TAG_INTEGER, "job-id", jobId); + ippAddString(request, IPP_TAG_OPERATION, IPP_TAG_NAME, "requesting-user-name", NULL, cupsUser()); + ippAddString(request, IPP_TAG_OPERATION, IPP_TAG_KEYWORD, "requested-attributes", NULL, "job-printer-state-reasons"); + + response = cupsDoRequest(http, request, "/admin"); + + job_printer_state_reasons[0] = '\0'; + if ((attr = ippFindAttribute(response, "job-printer-state-reasons", IPP_TAG_KEYWORD)) != NULL) { + ippAttributeString(attr, job_printer_state_reasons, sizeof(job_printer_state_reasons)); + } + + ippDelete(response); + + httpClose(http); + + std::vector needsPaperReasons = {"media-empty-error", "media-needed"}; + std::vector needsInkReasons = {"marker-supply-empty-error"}; + std::string inputTrayMissingReason = "input-tray-missing"; + std::vector reasons; + + boost::split(reasons, + job_printer_state_reasons, + boost::is_any_of(", "), + boost::token_compress_on); + + for (std::vector::iterator r = reasons.begin(); r != reasons.end(); ++r) { + LOG_D(TAG, "Job printer state reason: ", *r); + if (std::find(needsPaperReasons.begin(), needsPaperReasons.end(), *r) != needsPaperReasons.end()) { + LOG_D(TAG, "Printer needs paper!"); + flags |= PRINTER_ATTN_NO_PAPER; + } + if (std::find(needsInkReasons.begin(), needsInkReasons.end(), *r) != needsInkReasons.end()) { + LOG_D(TAG, "Printer needs ink!"); + flags |= PRINTER_ATTN_NO_INK; + } + if (inputTrayMissingReason.compare(*r) == 0) { + LOG_D(TAG, "Printer needs input tray!"); + flags |= PRINTER_ATTN_NO_TRAY; + } + } +} diff --git a/src/logic/PrinterManager.h b/src/logic/PrinterManager.h index a0979c9..671fb4b 100644 --- a/src/logic/PrinterManager.h +++ b/src/logic/PrinterManager.h @@ -30,6 +30,23 @@ namespace selfomat { STATE_STOPPED }; + enum PrinterJobState { + JOB_STATE_UNKNOWN, + JOB_STATE_PENDING, + JOB_STATE_HELD, + JOB_STATE_PROCESSING, + JOB_STATE_STOPPED, + JOB_STATE_CANCELED, + JOB_STATE_ABORTED, + JOB_STATE_COMPLETED + }; + + enum PrinterAttentionFlag { + PRINTER_ATTN_NO_PAPER = (1 << 0), + PRINTER_ATTN_NO_INK = (1 << 1), + PRINTER_ATTN_NO_TRAY = (1 << 2) + }; + class PrinterManager { private: static std::string TAG; @@ -74,11 +91,15 @@ namespace selfomat { bool resumePrinter(); - bool printImage(); + int printImage(); bool cancelPrint(); + bool getJobDetails(int jobId, PrinterJobState &state, time_t &creationTs, time_t &processingTs, time_t &completedTs); + + static const char* printerJobStateToString(PrinterJobState &state); + void checkPrinterAttentionFromJob(int jobId, unsigned int &flags); }; } } diff --git a/src/ui/IGui.h b/src/ui/IGui.h index 0c49cd1..63deedf 100644 --- a/src/ui/IGui.h +++ b/src/ui/IGui.h @@ -36,6 +36,7 @@ namespace selfomat { ALERT_CAMERA, ALERT_PRINTER, ALERT_PRINTER_HINT, + ALERT_PRINTER_JOB_HINT, ALERT_STORAGE, ALERT_STORAGE_ERROR, ALERT_CAMERA_HINT, @@ -86,6 +87,7 @@ namespace selfomat { (ALERT_CAMERA, "C") (ALERT_PRINTER, "P") (ALERT_PRINTER_HINT, "P") + (ALERT_PRINTER_JOB_HINT, "P") (ALERT_STORAGE, "U") (ALERT_STORAGE_ERROR, "U") (ALERT_CAMERA_HINT, "C")