Add logging

Close #5

2 files changed, 66 insertions, 26 deletions

diff --git a/service.py b/service.py
index 9d5394f..2033713 100755
--- a/service.py
+++ b/service.py
@@ -1,6 +1,7 @@
 #!/usr/bin/env python3
 import argparse
 import json
+import logging
 import signal
 import time
 from threading import Thread
@@ -12,9 +13,12 @@ import dbus.service
 from session import Session
 from trigger import TriggerServerThread
 
+logging.basicConfig(format="%(asctime)s %(levelname)s: %(message)s", level=logging.INFO)
+
 ONE_TIME_SERVICE = False
 ALLOW_ONLY_ONE_SESSION = True
 
+
 class RWAService(dbus.service.Object):
     def __init__(self, loop, mockup_mode: bool = False):
         self.loop = loop
@@ -30,10 +34,16 @@ class RWAService(dbus.service.Object):
         self.sessions = {}
         super().__init__(name, "/RWA")
 
+        logging.info("DBus service has been started.")
+
     @dbus.service.method("org.ArcticaProject.RWA", out_signature="s")
     def start(self):
         """Start a new remote session."""
         if ALLOW_ONLY_ONE_SESSION and len(self.sessions.values()) > 0:
+            logging.warning(
+                "There is already one session running and the service is configured to allow only one "
+                "session, so this session won't be started."
+            )
             return json.dumps({"status": "error"})
 
         # Start session
@@ -48,6 +58,8 @@ class RWAService(dbus.service.Object):
         return_json = session.client_meta
         return_json["status"] = "success"
 
+        logging.info(f"New session #{session.pid} was started with meta {return_json}.")
+
         return json.dumps(return_json)
 
     @dbus.service.method("org.ArcticaProject.RWA", in_signature="i", out_signature="s")
@@ -86,29 +98,31 @@ class RWAService(dbus.service.Object):
 
     def _update_session(self, pid: int):
         """Update the status of a session."""
+        logging.info(f"Update status for session #{pid} …")
+
         try:
             session = self.sessions[pid]
         except KeyError:
-            print(f"Session #{pid}")
-            print("Session is dead.")
+            logging.warning("  Session is dead.")
             return
 
-        print(f"Session #{session.pid}")
-
         # Check if VNC process is still running
         running = session.vnc_process_running
         if running:
-            print("Session is running")
+            logging.info("  Session is running.")
         elif session.status_text == "stopped" and session.pid in self.sessions:
+            logging.warning("  Session is dead.")
+
             del self.sessions[session.pid]
         else:
-            print("Session is dead.")
+            logging.warning("  VNC was stopped, so session is dead.")
 
             session.stop()
             del self.sessions[session.pid]
 
     def _update_sessions(self):
         """Go through all running sessions and update their status using ``_update_session``."""
+        logging.info("Started update service for sessions.")
         while len(self.sessions.values()) > 0:
             for session in list(self.sessions.values()):
                 self._update_session(session.pid)
@@ -116,23 +130,26 @@ class RWAService(dbus.service.Object):
             time.sleep(2)
 
         self.update_service_running = False
+        logging.info("Stopped update service for sessions.")
         if ONE_TIME_SERVICE:
             self._stop_all()
 
     def _trigger(self, token: str) -> bool:
         """Trigger a specific session via trigger token."""
-        print("Triggered with token", token)
+        logging.info(f"Triggered with token {token}")
 
         for session in self.sessions.values():
             if token == session.trigger_token:
-                print("Trigger session", session)
+                logging.info(f"Session #{session.pid} matches the token.")
                 session.trigger()
                 return True
 
+        logging.warning("  No matching session found for this token.")
         return False
 
     def _stop_all(self):
         """Stop all sessions and this daemon."""
+        logging.info("Stop all sessions and exit service.")
         for session in list(self.sessions.values()):
             session.stop()
             del self.sessions[session.pid]
@@ -172,7 +189,10 @@ if __name__ == "__main__":
     mockup_mode = args.mockup_mode
 
     if mockup_mode:
-        print("All API responses are faked and should NOT BE USED IN " + "PRODUCTION!")
+        logging.warning(
+            "All API responses are faked and should NOT BE USED IN PRODUCTION!"
+        )
+
     import dbus.mainloop.glib
     from gi.repository import GLib
 
@@ -182,7 +202,7 @@ if __name__ == "__main__":
     object = RWAService(loop, mockup_mode)
 
     def signal_handler(sig, frame):
-        print("You pressed Ctrl+C!")
+        logging.info("Service was terminated.")
         object._stop_all()
 
     signal.signal(signal.SIGINT, signal_handler)
diff --git a/session.py b/session.py
index b57bf57..af71c6a 100644
--- a/session.py
+++ b/session.py
@@ -1,3 +1,4 @@
+import logging
 import os
 import random
 import secrets
@@ -75,11 +76,15 @@ class Session:
         if not self.mockup_session:
             self.pw_filename = save_password(self.password)
 
+        logging.info("The password for the session has been generated.")
+
     def _start_vnc(self):
         """Start x11vnc server if not in mockup_session mode."""
         if not self.mockup_session:
             process_info = run_vnc(self.pw_filename)
 
+            logging.info("The VNC server has been started.")
+
             self.vnc_pid = process_info["vnc"]["pid"]
             self.vnc_port = process_info["vnc"]["port"]
             self.ws_pid = process_info["ws"]["pid"]
@@ -91,6 +96,8 @@ class Session:
             self.ws_pid = int(random_digits(5))
             self.vnc_pid = int(random_digits(5))
 
+            logging.info("The lock file for mocking a VNC server has been created.")
+
             # Create a temporary file to indicate that this process is still 'Running'
             filename = f"/tmp/rwa/{str(self.ws_port) + str(self.vnc_port) + str(self.ws_pid) + str(self.vnc_pid)}.lock"
             new_file = open(filename, "w")
@@ -109,14 +116,18 @@ class Session:
                     "trigger_token": self.trigger_token,
                 },
             )
-            print(r)
+
+            logging.info(
+                f"The session has been registered in RWA with status code {r.status_code} and response {r.content.decode()}."
+            )
+
             self.meta = r.json()
             self.session_id = self.meta["session_id"]
             self.web_url = self.meta["url"]
             self.api_token = self.meta["token"]
             self.pin = self.meta["pin"]
         else:
-            print('"Registered" in RWA')
+            logging.info(f"The session has pretended that he had created a session.")
             self.meta = {}
             self.session_id = int(random_digits(10))
             self.web_url = "testhostname:" + random_digits(5) + "/RWA/test/"
@@ -125,7 +136,6 @@ class Session:
 
     def trigger(self):
         """Event triggered by Django."""
-        print("Triggered")
         self.pull()
 
     def pull(self):
@@ -135,6 +145,10 @@ class Session:
                 STATUS_URL, params={"id": self.session_id}, headers=self._api_headers
             )
 
+            logging.info(
+                f"The session has received its status from RWA with status code {r.status_code} and response {r.content.decode()}."
+            )
+
             if r.status_code in (401, 402, 403, 404, 405):
                 # Session doesn't exist anymore, so stop it local
                 self.stop(triggered=True)
@@ -153,17 +167,23 @@ class Session:
 
     def _do_file_job(self, job):
         """Download a file from server to the user's desktop."""
+        logging.info(
+            f"The session has received a file job and is downloading it now ({job}):"
+        )
         subprocess.Popen(["wget", job["file"], "-P", self.desktop_dir])
         self._mark_job_as_done(job)
 
     def _mark_job_as_done(self, job):
         """Mark a job as done (in this service and on the server)."""
         self.done_jobs.append(job["job_id"])
-        requests.post(
+        r = requests.post(
             MARK_JOB_AS_DONE_URL,
             params={"id": job["job_id"]},
             headers=self._api_headers,
         )
+        logging.info(
+            f"The session has marked the job {job} as done in RWA with status code {r.status_code} and response {r.content.decode()}."
+        )
 
     def push(self):
         """Update status: Push status to Django."""
@@ -172,6 +192,7 @@ class Session:
     def stop(self, triggered: bool = False):
         """Stop session and clean up."""
         if self.mockup_session:
+            logging.info("Mock session has been stopped by deleting its lock file.")
             filename = f"/tmp/rwa/{str(self.ws_port) + str(self.vnc_port) + str(self.ws_pid) + str(self.vnc_pid)}.lock"
             if os.path.isfile(filename):
                 os.remove(filename)
@@ -180,31 +201,30 @@ class Session:
             del self
             return
 
-        # Kill VNC
-        if self.vnc_pid in psutil.pids():
-            print("Kill VNC.")
-            os.kill(self.vnc_pid, signal.SIGTERM)
-
         # Kill websockify
         if self.ws_pid in psutil.pids():
-            print("Kill websockify.")
             os.kill(self.ws_pid, signal.SIGTERM)
+            logging.info("The websockify server has been terminated.")
+
+        # Kill VNC
+        if self.vnc_pid in psutil.pids():
+            os.kill(self.vnc_pid, signal.SIGTERM)
+            logging.info("The VNC server has been terminated.")
 
         # Delete PW file
         if os.path.exists(self.pw_filename):
-            print("Delete password file")
             os.remove(self.pw_filename)
-
-        if hasattr(self, "trigger_thread"):
-            print("Kill trigger service.")
-            self.trigger_thread.shutdown()
+            logging.info("The VNC server password file has been removed.")
 
         self.push()
 
         if not triggered:
-            requests.post(
+            r = requests.post(
                 STOP_URL, params={"id": self.session_id}, headers=self._api_headers
             )
+            logging.info(
+                f"The stop action has been registered in RWA with status code {r.status_code} and response {r.content.decode()}."
+            )
 
         self.status_text = "stopped"