track print jobs with lpstat + sqlite (#138)

* new sqlite thingy

* gitignore

* mount db + other stuff

* dockercompose

* added default file path

* no default

* syntax error fix

* fix errors

* fix errors again

* fix errors again

* updating completed jobs

* mocking

* gitignore

* dynamic job ids

* Refactor print job creation and add ID iterator

* removed thread that polls lpstat

* removed thread that polls lpstat

* DEBUG = False to pass unit tests

* printer returns None when error

* throw error for returncode != 0

* please work

* create_print_job returns different things for different things

* log exception & remove sqlite_helpers from gerard.py

* minor edits

* minor changes part 2

* tests work

* rename set

* moved updating jobs to sqlite_helpers

* sqlite unit tests

* update unit tests

* removed timestamp check in unit tests

* better unit testing

* bug fixes on unit tests

* v1 of lpstat unit tests

* changed names of update_completed -> update_jobs

* update_jobs

* acknowledged, not created

* i forgot to call the test

* trying with sqlite tests

* bug fixes

* trying with sqlite tests

* bug fixes

* logging + more fixes

* working lpstat tests + bug fixes in sqlite_helpers

* sqlite_test bug

* simplify unit tests

* renamed sqlite_test to test_sqlite

* unit test for gerard

* changed yaml file

* collector import bug

* removed useless test

* update imports for test_lpstat

* fixes

* sqlite test fixes

* lpstat test fixes

* format, remove rendudant lines in gerard and lpstat_helpers

* less noise in logs, mount files as volume

* add curl example, remove shell=True

* set -x in what.sh, log bytes written

* less diff

* tests should pass

* remove ghostscript, logging.exception

---------

Co-authored-by: evan <evanuxd@gmail.com>

Author: epicgdog

.github/workflows/unit-tests.yml

@@ -26,4 +26,7 @@ jobs:
 
     - name: Run tests
       run: |
-        python printer/test_server.py
+        python printer/test/test_gerard.py
+        python printer/test/test_lpstat.py
+        python printer/test/test_server.py
+        python printer/test/test_sqlite.py

.gitignore

@@ -16,3 +16,6 @@ config.json
 venv/
 
 tmp/
+
+*.db
+.python-version

README.md

@@ -53,3 +53,20 @@ sce link q
 ### its go time
 - just run `docker-compose up --build -d`
 - the logs of the server can be observed with `docker logs sce-printer --tail 300 -f`
+
+### example curl command to print a blank pdf
+```sh
+# get the full path of your folder
+pwd
+
+# download a blank pdf
+curl --output blank.pdf https://mag.wcoomd.org/uploads/2018/05/blank.pdf
+
+# curl the server
+curl -X POST \
+  -H "Content-Type: multipart/form-data" \
+  -F "file=@/full/path/to/blank.pdf" \
+  -F "copies=2" \
+  -F "sides=one-sided" \
+  http://localhost:9000/print
+```

docker-compose.yml

@@ -12,12 +12,18 @@ services:
       - ~/.ssh/id_ed25519-tunnel:/app/ssh_key
       - ~/.ssh/known_hosts:/app/known_hosts
       - "/etc/cups/ppd/:/etc/cups/ppd"
+      - ./config:/app/config
+      - ./printer:/app/printer
+      - quasar_data:/tmp/
     tty: true
 
 # we attach the print container to an external docker
 # network called "poweredge". we do this so a prometheus
 # container can pull metrics from the server over HTTP
 # and relay the metrics to a Grafana dashboard.
+volumes:
+  quasar_data:
+
 networks:
   default:
     external:

printer/Dockerfile

@@ -3,6 +3,7 @@
 FROM drpsychick/airprint-bridge:jammy
 
 WORKDIR /app
+
 RUN apt-get update
 
 RUN apt install -y python3 python3-pip python3-venv jq ssh
@@ -17,12 +18,6 @@ COPY ./printer/requirements.txt  /app/printer/requirements.txt
 
 RUN /opt/venv/bin/pip install -r /app/printer/requirements.txt
 
-COPY ./config/config.json /app/config/config.json
-
-COPY ./printer/what.sh /app/printer/what.sh
-
-COPY ./printer/*.py /app/printer/
-
 EXPOSE 9000
 
 # The below command runs the bash script that sets up the connection to the

printer/collector.py printer/modules/collector.pyprinter/collector.py renamed to printer/modules/collector.py

@@ -2,11 +2,10 @@
 import enum
 import logging
 import json
-import asyncio
 
 from pysnmp.hlapi import *
 
-from metrics import MetricsHandler
+from modules.metrics import MetricsHandler
 
 metrics_handler = MetricsHandler.instance()
 
@@ -46,15 +45,22 @@ def fetch_ips_from_config(config_file_path):
                 raise Exception("No printers defined in config file")
 
             ip_list = []
-            for printer in printer_configs:
-                if isinstance(printer_configs[printer], dict):
-                    ip = printer_configs[printer]["IP"]
-                    logging.info(f"Adding printer {printer} with IP {ip}")
-                    ip_list.append(ip)
+            for printer_name in printer_configs:
+                resolved_config = printer_configs.get(printer_name, {})
+                if not resolved_config.get("ENABLED"):
+                    logging.info(f"{printer_name} is not enabled, skipping")
+                    continue
+                ip = resolved_config.get("IP")
+                if not ip:
+                    logging.info(f"{printer_name} config {resolved_config} did not have an ip, skipping")
+                    continue
+
+                logging.info(f"found printer {printer_name} with IP {ip}")
+                ip_list.append(ip)
             return ip_list
 
-    except Exception as e:
-        logging.error(f"error opening config file: {e}")
+    except Exception:
+        logging.exception(f"error opening config file")
 
 
 def scrape_snmp(ip_list, sleep_duration_minutes=5):
@@ -83,7 +89,7 @@ def get_snmp_data(ip):
             metrics_handler.device_unreachable.set(1)
             continue
         if errorStatus:
-            logging.error(
+            logging.debug(
                 f"Error status from {ip} for metric {oid.metric_value}: {errorStatus.prettyPrint()}"
             )
             # SNMP OIDs related to errors often dissappear when

printer/modules/gerard.py

@@ -0,0 +1,84 @@
+"""this file is for parsing lp command output.
+epicgdog made these files so instead of calling it lp_helpers.py its gerard.py
+"""
+
+import logging
+import shlex
+import subprocess
+
+
+LP_COMMAND = """
+lp \
+    -n {num_copies} {maybe_page_range} \
+    -o sides={sides} \
+    -o media=na_letter_8.5x11in \
+    -d {printer_name} \
+    {file_path}
+"""
+
+logging.basicConfig(
+    # in mondo we trust
+    format="%(asctime)s.%(msecs)03dZ %(levelname)s:%(name)s:%(message)s",
+    datefmt="%Y-%m-%dT%H:%M:%S",
+    level=logging.INFO,
+)
+
+
+class IDIterator:
+    def __init__(self):
+        self._current = 0
+
+    def __next__(self):
+        id = self._current
+        self._current += 1
+        return id
+
+
+print_job_suffix = IDIterator()
+
+
+def create_print_job(
+    num_copies,
+    maybe_page_range,
+    sides,
+    printer_name,
+    file_path,
+    is_development_mode=False,
+):
+    command = LP_COMMAND.format(
+        num_copies=num_copies,
+        maybe_page_range=maybe_page_range,
+        sides=sides,
+        printer_name=printer_name,
+        file_path=file_path,
+    )
+
+    if is_development_mode:
+        logging.warning(
+            f"server is in development mode, command would've been `{command}`"
+        )
+        job_id = f"HP_LaserJet_p2015dn_Right-{next(print_job_suffix)}"
+        return job_id
+
+    args_list = shlex.split(command.strip())
+    logging.info(f"running command {command}")
+    print_job = subprocess.Popen(
+        args_list,
+        stdout=subprocess.PIPE,
+        stderr=subprocess.PIPE,
+        text=True,
+    )
+    print_job.wait(timeout=3)
+    if print_job.returncode != 0:
+        logging.error(
+            f"print job returned nonzero code {print_job.returncode} stderr: {print_job.stderr.read()} stdout: {print_job.stdout.read()}"
+        )
+        return None
+    try:
+        lp_command_output = print_job.stdout.read()
+        logging.info(f"lp command stdout was {lp_command_output}")
+        print_id = lp_command_output.split(" ")[3]
+        return print_id
+    except Exception:
+        logging.exception(f"unable to parse print job from stdout")
+        return ""

printer/modules/lpstat_helpers.py

@@ -0,0 +1,73 @@
+import logging
+import subprocess
+import time
+
+from modules import sqlite_helpers
+
+LPSTAT_CMD = "lpstat -o HP_LaserJet_p2015dn_Right"
+SLEEP_TIME = 2
+
+jobs_seen_last = set()
+
+logging.basicConfig(
+    # in mondo we trust
+    format="%(asctime)s.%(msecs)03dZ %(levelname)s:%(name)s:%(message)s",
+    datefmt="%Y-%m-%dT%H:%M:%S",
+    level=logging.INFO,
+)
+
+
+def query_lpstat():
+    global jobs_seen_last
+    global current_jobs
+    p = subprocess.Popen(
+        LPSTAT_CMD,
+        shell=True,
+        stdout=subprocess.PIPE,
+        stderr=subprocess.PIPE,
+        text=True,
+    )
+    p.wait()
+
+    if p.returncode != 0:
+        logging.error(
+            f"{LPSTAT_CMD} returned nonzero code {p.returncode} with stderr {p.stderr.read()}"
+        )
+        return
+
+    output = p.stdout.read().strip()
+    logging.debug(f"{LPSTAT_CMD} stdout: {output}")
+    if len(output) == 0:
+        return
+    # 2 things at once; add new jobs to new one while also retrieving current job_ids
+    jobs = output.split("\n")
+    for job in jobs:
+        # an example line of stdout looks like
+        # HP_LaserJet_p2015dn_Right-52 root              5120   Sat May 31 18:19:38 2025
+        try:
+            yield job.strip().split(" ")[0]
+        except:
+            logging.exception(f"unable to parse job id from line {job}")
+            return
+
+
+def poll_lpstat(sqlite_file):
+    global jobs_seen_last
+    while True:
+        try:
+            current_jobs = set(query_lpstat())
+            completed_jobs = jobs_seen_last - current_jobs
+
+            sqlite_helpers.mark_jobs_completed(
+                sqlite_file, [job for job in completed_jobs]
+            )
+            sqlite_helpers.mark_jobs_acknowledged(
+                sqlite_file, [job for job in current_jobs]
+            )
+
+            jobs_seen_last.clear()
+            jobs_seen_last.update(current_jobs)
+
+        except Exception:
+            logging.exception("what happened to query_lpstat?")
+        time.sleep(SLEEP_TIME)

printer/metrics.py printer/modules/metrics.pyprinter/metrics.py renamed to printer/modules/metrics.py

@@ -0,0 +1,74 @@
+from datetime import datetime
+import logging
+import sqlite3
+import datetime
+
+logging.basicConfig(
+    # in mondo we trust
+    format="%(asctime)s.%(msecs)03dZ %(levelname)s:%(name)s:%(message)s",
+    datefmt="%Y-%m-%dT%H:%M:%S",
+    level=logging.INFO,
+)
+
+
+def maybe_create_table(sqlite_file: str) -> bool:
+    db = sqlite3.connect(sqlite_file)
+    cursor = db.cursor()
+
+    try:
+        create_table_query = """
+        CREATE TABLE IF NOT EXISTS logs (
+            date        DATETIME DEFAULT CURRENT_TIMESTAMP, 
+            job_id      TEXT NOT NULL, 
+            status      TEXT CHECK (status IN ('created', 'acknowledged', 'completed')) NOT NULL DEFAULT 'created',
+            PRIMARY KEY (date, job_id)
+            )
+        """
+
+        cursor.execute(create_table_query)
+        db.commit()
+        return True
+    except Exception:
+        logging.exception("Unable to create printer table")
+        return False
+
+
+def insert_print_job(sqlite_file: str, job_id: str):
+    try:
+        with sqlite3.connect(sqlite_file, timeout=10.0) as db:
+            cursor = db.cursor()
+            timestamp = datetime.datetime.now()
+            db = sqlite3.connect(sqlite_file)
+            sql = "INSERT INTO logs (job_id) VALUES (?)"
+            cursor.execute(sql, (job_id,))
+            db.commit()
+            return timestamp
+    except sqlite3.IntegrityError:
+        return None
+    except Exception:
+        logging.exception("Inserting print job had an error")
+        return None
+
+
+def mark_jobs_with_status(sqlite_file, jobs, status):
+    db = sqlite3.connect(sqlite_file)
+    cursor = db.cursor()
+    job_ids = [(job_id,) for job_id in jobs]
+    if not job_ids:
+        return
+    logging.info(f"marking {job_ids} as {status} in sqlite")
+
+    sql_update = (
+        f"UPDATE logs SET status = '{status}' WHERE job_id = ?"
+    )
+    cursor.executemany(sql_update, job_ids)
+
+    db.commit()
+
+
+def mark_jobs_acknowledged(sqlite_file, jobs):
+    mark_jobs_with_status(sqlite_file, jobs, "acknowledged")
+
+
+def mark_jobs_completed(sqlite_file, jobs):
+    mark_jobs_with_status(sqlite_file, jobs, "completed")