How to debug a Python program running as a service?

Question

I have a python script which works well when run in the console. However, when using pywin32 in order to let it run as a service, the service gets installed and starts okay but the desired output is not produced. So something must be going wrong -- but I can't see what's happening to find out the reason.

---

The script does the following:

1. Searches for *.csv files in a given input dir
2. If no such files are found it waits 1 minute. If one is found it uses it as input for step 3. If multiple csv files are found it uses the first one.
3. Does some transformation on the order of the columns
4. Writes the transformed content into an output csv
5. Moves the input csv into a subdirectory and renames it.

Let me first show you the code of the version that is implemented as a service:

#!/usr/bin/env python3

import sys
import os
import csv
from pathlib import Path
import time
import win32service
import win32serviceutil
import win32event


def reorder_AT_csv(ifile, ofile):
    "Öffnet die CSV Datei, überführt sie in das neue Format und exportiert sie."

    print('[i] Lese aus ' + ifile.name + ' und schreibe in ' +
          ofile.name)
    with open(
            ifile, mode='r') as infile, open(
                ofile, mode='w') as outfile:
        reader = csv.DictReader(
            infile,
            fieldnames=[
                'Post Nummer', 'Sendungsnummer', 'Referenz1', 'Referenz2',
                'Gewicht', 'Empf.Name1', 'Empf.Adresse', 'Empf.PLZ',
                'Empf.Ort', 'Kostenstelle', 'Produkt'
            ],
            delimiter=';')
        fn = [
            'Post Nummer', 'Referenz1', 'Referenz2', 'Sendungsnummer',
            'Gewicht', 'Empf.Name1', 'Empf.Adresse', 'Empf.PLZ', 'Empf.Ort',
            'Kostenstelle', 'Produkt'
        ]
        writer = csv.DictWriter(
            outfile, extrasaction='ignore', fieldnames=fn, delimiter=';')
        # reorder the header first
        try:
            for row in reader:
                # writes the reordered rows to the new file
                writer.writerow(row)
        except Exception as e:
            print('[!] Fehler bei der Bearbeitung der CSV Datei:')
            print('[!] ' + str(e))
            print(
                '[!] Bitte ueberpruefen, ob es sich um eine korrekte CSV Datei handelt!'
            )
            sys.exit(1)


def checkInputFromUser(path):
    "Überprüfe ob das Verzeichnis existiert."

    if not path.exists():
        print(
            '[!] Die Eingabe ist kein Verzeichnis. Bitte ein gueltiges Verzeichnis eingeben.'
        )
        sys.exit(1)

    return True


def findCSVFile(path):
    "Finde alle CSV Dateien im Verzeichnis path."

    all_files = []
    all_files.extend(Path(path).glob('*.csv'))
    if len(all_files) == 0:
        # print('[!] Keine CSV Dateien gefunden. Bitte Pfad überprüfen.')
        # sys.exit(1)
        return None
    elif len(all_files) > 1:
        print('[i] Mehrere CSV Dateien gefunden. Nehme ersten Fund:')
        return all_files[0]


def moveInputFile(input):
    "Verschiebe Input Datei in Unterordner und füge Suffix hinzu."

    movepath = Path(input.parent / 'processed')
    targetname = input.with_suffix(input.suffix + '.success')
    fulltarget = movepath / targetname.name
    input.replace(fulltarget)


class CSVConvertSvc(win32serviceutil.ServiceFramework):
    # you can NET START/STOP the service by the following name
    _svc_name_ = "blub"
    # this text shows up as the service name in the Service
    # Control Manager (SCM)
    _svc_display_name_ = "bar der AT CSV Dateien."
    # this text shows up as the description in the SCM
    _svc_description_ = "Dieser Dienst öffnet die AT CSV Datei und überführt sie in das DPD Format."

    def __init__(self, args):
        win32serviceutil.ServiceFramework.__init__(self, args)
        # create an event to listen for stop requests on
        self.hWaitStop = win32event.CreateEvent(None, 0, 0, None)

    # core logic of the service
    def SvcDoRun(self):
        import servicemanager

        rc = None
        inputpath = Path(r'C:\Users\Dennis\Documents')
        outputpath = Path(r'C:\Users\Dennis\Desktop')
        file = None

        # if the stop event hasn't been fired keep looping
        while rc != win32event.WAIT_OBJECT_0:

            checkInputFromUser(inputpath)

            while file is None:
                file = findCSVFile(inputpath)
                if file is None:
                    time.sleep(60)

            inputfile = file
            outputfile = outputpath / 'out.csv'
            reorder_AT_csv(inputfile, outputfile)
            moveInputFile(inputfile)

            # block for 5 seconds and listen for a stop event
            rc = win32event.WaitForSingleObject(self.hWaitStop, 5000)

    # called when we're being shut down
    def SvcStop(self):
        # tell the SCM we're shutting down
        self.ReportServiceStatus(win32service.SERVICE_STOP_PENDING)
        # fire the stop event
        win32event.SetEvent(self.hWaitStop)


if __name__ == '__main__':
    win32serviceutil.HandleCommandLine(CSVConvertSvc)

This version does not do what it is supposed to do. However, I started with this could as a non-service version, but rather a simple python script, which does what it is supposed to do:

#!/usr/bin/env python3

import sys
import os
import csv
import time
from pathlib import Path




def reorder_AT_csv(ifile, ofile):
    "Öffnet die CSV Datei, überführt sie in das neue Format und exportiert sie."

    print('[i] Lese aus ' + ifile.name + ' und schreibe in ' +
          ofile.name)
    with open(
            ifile, mode='r') as infile, open(
                ofile, mode='w') as outfile:
        reader = csv.DictReader(
            infile,
            fieldnames=[
                'Post Nummer', 'Sendungsnummer', 'Referenz1', 'Referenz2',
                'Gewicht', 'Empf.Name1', 'Empf.Adresse', 'Empf.PLZ',
                'Empf.Ort', 'Kostenstelle', 'Produkt'
            ],
            delimiter=';')
        fn = [
            'Post Nummer', 'Referenz1', 'Referenz2', 'Sendungsnummer',
            'Gewicht', 'Empf.Name1', 'Empf.Adresse', 'Empf.PLZ', 'Empf.Ort',
            'Kostenstelle', 'Produkt'
        ]
        writer = csv.DictWriter(
            outfile, extrasaction='ignore', fieldnames=fn, delimiter=';')
        # reorder the header first
        try:
            for row in reader:
                # writes the reordered rows to the new file
                writer.writerow(row)
        except Exception as e:
            print('[!] Fehler bei der Bearbeitung der CSV Datei:')
            print('[!] ' + str(e))
            print(
                '[!] Bitte ueberpruefen, ob es sich um eine korrekte CSV Datei handelt!'
            )
            sys.exit(1)


def checkInputFromUser(path):
    "Überprüfe ob das Verzeichnis existiert."

    if not path.exists():
        print(
            '[!] Die Eingabe ist kein Verzeichnis. Bitte ein gueltiges Verzeichnis eingeben.'
        )
        sys.exit(1)

    return True


def findCSVFile(path):
    "Finde alle CSV Dateien im Verzeichnis path."

    all_files = []
    all_files.extend(Path(path).glob('*.csv'))
    if len(all_files) == 0:
        # print('[!] Keine CSV Dateien gefunden. Bitte Pfad überprüfen.')
        # sys.exit(1)
        return None
    elif len(all_files) > 1:
        print('[i] Mehrere CSV Dateien gefunden. Nehme ersten Fund:')
    return all_files[0]


def moveInputFile(input):

    movepath = Path(input.parent / 'processed')
    targetname = input.with_suffix(input.suffix + '.success')
    fulltarget = movepath / targetname.name
    input.replace(fulltarget)


def main():

    inputpath = Path(r'C:\Users\Dennis\Documents')
    outputpath = Path(r'C:\Users\Dennis\Desktop')
    file = None

    checkInputFromUser(inputpath)

    while file is None:
        file = findCSVFile(inputpath)
        if file is None:
            time.sleep(60)

    inputfile = file
    outputfile = outputpath / 'out.csv'
    reorder_AT_csv(inputfile, outputfile)
    moveInputFile(inputfile)


if __name__ == '__main__':
    main()

Being very new to Python, I can't figure out what I am missing. The service is installed correctly and also starts without a problem. I am using ActiveState Python 3.6 which is shipped with pywin32 libs.

Answer 1

One Problem is that

# core logic of the service
def SvcDoRun(self):

has its own exception handler. So even if you redirect std out and err to a file, you would not see an unhandeled exception being printed there. But there is a solution:

# core logic of the service
def SvcDoRun(self):
    try:
        self.server = MyLauncher()
        self.server.run()
    except:
        import traceback
        print(traceback.format_exc())

The changed excepthook like mentioned in another answer did not work in my case:

Answer 2

Use logging to report on the program's progress and do debug printing. This way, you'll see what the program is doing and where it's stuck.

_{(Also note that ServiceFramework has a "debug mode". Running <your_program> debug from the console instructs HandleCommandLine to run your program interactively: you get console output, and Ctrl-C terminates the program. This makes the run-fix iterations take less time but won't reveal the bugs that only manifest when running as a service. So it's helpful but is only a preliminary step, running as a service and logging to a file is the ultimate test.)}

---

Here's how I arrange my scripts that run unatteneded/as a service.

• Set up logging ASAP.
  Always use a rotating handler so that logs do not grow indefinitely.
  Make sure to log any unhandled exceptions.

  # set up logging #####################################
  import sys,logging,logging.handlers,os.path
  #in this particular case, argv[0] is likely pythonservice.exe deep in python's lib\
  # so it makes no sense to write log there
  log_file=os.path.splitext(__file__)[0]+".log"
  l = logging.getLogger()
  l.setLevel(logging.INFO)
  f = logging.Formatter('%(asctime)s %(process)d:%(thread)d %(name)s %(levelname)-8s %(message)s')
  h=logging.StreamHandler(sys.stdout)
  h.setLevel(logging.NOTSET)
  h.setFormatter(f)
  l.addHandler(h)
  h=logging.handlers.RotatingFileHandler(log_file,maxBytes=1024**2,backupCount=1)
  h.setLevel(logging.NOTSET)
  h.setFormatter(f)
  l.addHandler(h)
  del h,f
  #hook to log unhandled exceptions
  def excepthook(type,value,traceback):
      logging.error("Unhandled exception occured",exc_info=(type,value,traceback))
      #Don't need another copy of traceback on stderr
      if old_excepthook!=sys.__excepthook__:
          old_excepthook(type,value,traceback)
  old_excepthook = sys.excepthook
  sys.excepthook = excepthook
  del log_file,os
  # ####################################################
  

• Log every program start and stop.
  In the case of a service, must also log unhandled exceptions manually at SvcDoRun level since pythonservice.exe seems to swallow all exceptions. Keep the sys.excepthook replacement anyway just in case.

  def SvcDoRun(self):
      #sys.excepthook doesn't seem to work in this routine -
      # apparently, everything is handled by the ServiceFramework machinery
      try:
          l.info("Starting service")
          main()
      except Exception,e:
          excepthook(*sys.exc_info())
      else:
          l.info("Finished successfully")
  def SvcStop(self):
      l.info("Stop request received")
      <...>
  

• Log any meaningful step, in user's terms, that the program does. Report trivial or very frequent happenings at higher level of verbosity. Choose the levels in such a way that output with any l.setLevel() gives a complete picture, with the corresponding level of detail.

  file_ = findCSVFile(inputpath)
  if file_:
      l.info("Processing `%s'", file_)    # Note the quotes around the name.
                                          # They will help detect any leading/trailing
                                          #space in the path.
  else:
      l.debug("No more files")
  
  <...>
  
  l.info("Moving to `%s'",fulltarget)
  input.replace(fulltarget)
  
  <...>
  
  l.debug("waiting")
  rc = win32event.WaitForSingleObject(<...>)