Image print metrics and advanced printer alarms

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: ",

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: ",

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 : ",

src/logic/BoothLogic.cpp

@@ -1,3 +1,4 @@
+
 //
 // Created by clemens on 21.01.19.
 //
@@ -43,10 +44,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 +96,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 +375,10 @@ 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;
+            clock_gettime(CLOCK_REALTIME, &metrics.processingTs);
+
             // We need the final jpeg image. So lock the mutex
             {
                 boost::unique_lock<boost::mutex> 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<boost::mutex> lk(printerStateMutex);
@@ -404,30 +417,43 @@ void BoothLogic::printerThread() {
                 }
             }
 
+            clock_gettime(CLOCK_REALTIME, &metrics.gotUserDecisionTs);
 
             // We need the info if the user wants to print or not
             if (printConfirmationEnabled) {
                 // only print with user confirmation (auto-cancling)
                 boost::unique_lock<boost::mutex> 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 {
                 // only print when not print request is not canceled by user (auto-print)
                 boost::unique_lock<boost::mutex> 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, start checking this job from the metrics thread
+            // (append to list and activate thread if not already active);
+            // otherwise the already known timing values could be logged
+            if(metrics.cupsJobId > 0) {
+                boost::unique_lock<boost::mutex> lk(printMetricsMutex);
+                printMetrics.push_back(metrics);
+                // explicitely activate print monitoring thread
+                printMetricsSem.post();
+            }
         } else {
             // We need the final jpeg image. So lock the mutex
             {
@@ -469,6 +495,120 @@ void BoothLogic::printerThread() {
     }
 }
 
+#define CTIME_NO_NL(x) strtok(ctime(x), "\n")
+
+void BoothLogic::printMonitoringThread() {
+    LOG_D(TAG, "Starting Print Monitoring Thread");
+
+    // boolean flag which indicates whether to wait for external activation of this thread
+    // from the printer thread
+    bool waitForActivation = true;
+
+    while (isPrintMonitoringThreadRunning) {
+        if (waitForActivation) {
+            // blocking wait: only accept activation from printer thread (no periodic execution of this thread)
+            LOG_D(TAG, "[Print Mon Thread] Waiting for activation from printer thread (going to sleep...)");
+            printMetricsSem.wait();
+            LOG_D(TAG, "[Print Mon Thread] Activated from printer thread (slept before)");
+        } else {
+            // blocking wait for period time; but also activate earlier if the semaphore has been posted by the printer thread
+            boost::system_time const timeout = boost::get_system_time() + boost::posix_time::milliseconds(5000);
+            bool semPosted = printMetricsSem.timed_wait(timeout);
+            if (semPosted) {
+                LOG_D(TAG, "[Print Mon Thread] Activated from print thread (already active before)");
+            } else {
+                LOG_D(TAG, "[Print Mon Thread] Periodic execution (wait for semaphore timeout)");
+            }
+        }
+
+        size_t listLength = 0;
+        {
+            boost::unique_lock<boost::mutex> lk(printMetricsMutex);
+
+            unsigned int printerAttentionFlags = 0; // reset flags
+
+            std::list<ImagePrintMetrics>::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;
+
+                    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] Processing timestamp:          ", std::string(CTIME_NO_NL(&it->processingTs.tv_sec)));
+                        //LOG_D(TAG, "[Print Mon Thread] Await user decision timestamp: ", std::string(CTIME_NO_NL(&it->awaitUserDecisionTs.tv_sec)));
+                        //LOG_D(TAG, "[Print Mon Thread] Got user decision timestamp:   ", std::string(CTIME_NO_NL(&it->gotUserDecisionTs.tv_sec)));
+                        LOG_D(TAG, "[Print Mon Thread] CUPS creation timestamp:       ", std::string(CTIME_NO_NL(&cupsCreationTs)));
+                        LOG_D(TAG, "[Print Mon Thread] CUPS processing timestamp:     ", std::string(CTIME_NO_NL(&cupsProcessingTs)));
+                        LOG_D(TAG, "[Print Mon Thread] CUPS completed timestamp:      ", std::string(CTIME_NO_NL(&cupsCompletedTs)));
+                        LOG_D(TAG, "[Print Mon Thread] CUPS state                     ", std::string(printerManager.printerJobStateToString(it->jobState)));
+                        if(JOB_STATE_COMPLETED == jobState) {
+ 			    // finally, it's time to emit (log) the collected metrics
+			    double durationUntilProc = difftime(cupsProcessingTs, cupsCreationTs);
+			    double durationProcCompl = difftime(cupsCompletedTs, cupsProcessingTs);
+			    LOG_D(TAG, "[Print Mon Thread] Duration CUPS creation -> processing:   ", std::to_string(durationUntilProc));
+			    LOG_D(TAG, "[Print Mon Thread] Duration CUPS processing -> completion: ", std::to_string(durationProcCompl));
+                        }
+                        printMetrics.erase(it++);
+                    } else {
+                        // job is in a state where it will be still monitored
+                        LOG_D(TAG, "[Print Mon Thread] CUPS state                     ", std::string(printerManager.printerJobStateToString(it->jobState)));
+                        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
+			    timespec tnow;
+                            clock_gettime(CLOCK_REALTIME, &tnow);
+                            double durationProcessing = difftime(tnow.tv_sec, cupsProcessingTs);
+                            LOG_D(TAG, "[Print Mon Thread] CUPS job has been processing for [seconds]: ", std::to_string(durationProcessing));
+                            printerManager.checkPrinterAttentionFromJob(jobId, printerAttentionFlags);
+			}
+                        ++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);
+            }
+
+            // execute periodically if there's still some job to be monitored or a print job alarm active (any flag set);
+            // otherwise wait for activation from print thread
+            waitForActivation = (listLength == 0) && (printerAttentionFlags == 0);
+        }
+    }
+}
+
 int BoothLogic::getFreeStorageSpaceMB() {
     if (imageDir.empty()) {
         LOG_E(TAG, "No image dir specified!");

src/logic/BoothLogic.h

@@ -14,6 +14,7 @@
 #include <boost/asio/streambuf.hpp>
 #include <boost/asio.hpp>
 #include <boost/lexical_cast.hpp>
+#include <boost/interprocess/sync/interprocess_semaphore.hpp>
 
 #include <unistd.h>
 #include <linux/reboot.h>
@@ -57,6 +58,25 @@ 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;
+        };
+
         class BoothLogic : public ILogicController {
         public:
             explicit BoothLogic(ICamera *camera, IGui *gui, bool has_button, const string &button_port, bool has_flash,
@@ -70,7 +90,8 @@ namespace selfomat {
                                                                         selfomatController(),
                                                                         force_image_dir_mountpoint(force_image_dir_mountpoint),
                                                                         show_led_setup(show_led_setup),
-                                                                        autofocus_before_trigger(autofocus_before_trigger) {
+                                                                        autofocus_before_trigger(autofocus_before_trigger),
+ 								        printMetricsSem(0) {
                 selfomatController.setLogic(this);
                 this->triggered = false;
                 this->disable_watchdog = disable_watchdog;
@@ -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();
@@ -182,6 +203,10 @@ namespace selfomat {
             FILTER getFilter();
 
             timespec triggerStart;
+
+            std::list<ImagePrintMetrics> printMetrics;
+            boost::mutex printMetricsMutex;
+	    boost::interprocess::interprocess_semaphore printMetricsSem;
         public:
             bool isStopped();
             void trigger();
@@ -209,6 +234,9 @@ namespace selfomat {
                 if (printThreadHandle.joinable()) {
                     printThreadHandle.join();
                 }
+                if (printMonitoringThreadHandle.joinable()) {
+                    printMonitoringThreadHandle.join();
+                }
 
                 if (returnCode == -1) {
                     reboot(LINUX_REBOOT_CMD_POWER_OFF);