Python Windows Service - Logging not working

Question

Using Python 3.7, Windows 10 Pro, Pywin32

I have a test script that starts a service and pushes some basic lines into a log file as the different commands are issued. Code is as follows:

import win32serviceutil
import win32service
import win32event
import servicemanager
import socket
import logging


class AppServerSvc(win32serviceutil.ServiceFramework):
    _svc_name_ = "TestService"
    _svc_display_name_ = "Test Service"
    _svc_description_ = "New Test Service"

    logging.basicConfig(filename='search_server.log', level=logging.INFO)
    logging.info('Class opened')

    def __init__(self, args):
        logging.basicConfig(filename='search_server.log', level=logging.INFO)
        logging.info('Init')
        win32serviceutil.ServiceFramework.__init__(self, args)
        self.hWaitStop = win32event.CreateEvent(None, 0, 0, None)
        socket.setdefaulttimeout(60)


    def SvcStop(self):
        logging.basicConfig(filename='search_server.log', level=logging.INFO)
        logging.info('Stop')
        self.ReportServiceStatus(win32service.SERVICE_STOP_PENDING)
        win32event.SetEvent(self.hWaitStop)


    def SvcDoRun(self):
        logging.basicConfig(filename='search_server.log', level=logging.INFO)
        logging.info('Run')
        servicemanager.LogMsg(servicemanager.EVENTLOG_INFORMATION_TYPE,
                              servicemanager.PYS_SERVICE_STARTED,
                              (self._svc_name_, ''))
        self.main()


    def main(self):
        print("running")
        logging.basicConfig(filename='search_server.log', level=logging.INFO)
        logging.info('Main')


if __name__ == '__main__':
    logging.basicConfig(filename='search_server.log', level=logging.INFO)
    logging.info('Calling Handle Command Line')
    win32serviceutil.HandleCommandLine(AppServerSvc)

I have gone through the basic trouble shooting with this, and the service is installing, starting, restarting and being removed without any errors. However I am expecting the log file to receive basic output to show the functions are being hit, and it isn't.

The calls I am making at the admin command prompt:

C:\PythonScripts\SearchServer>python servicetest.py install
Installing service TestService
Service installed

C:\PythonScripts\SearchServer>python servicetest.py start
Starting service TestService

C:\PythonScripts\SearchServer>python servicetest.py restart
Restarting service TestService

C:\PythonScripts\SearchServer>python servicetest.py remove
Removing service TestService
Service removed

C:\PythonScripts\SearchServer>

Contents of log file:

INFO:root:Class opened
INFO:root:Calling Handle Command Line
INFO:root:Class opened
INFO:root:Calling Handle Command Line
INFO:root:Class opened
INFO:root:Calling Handle Command Line
INFO:root:Class opened
INFO:root:Calling Handle Command Line

As you can see the service is being hit every time a command is issued, however I'd expect the internal functions to be called too. Being new to both services and Python I'm wondering if I've missed anything? I'm assuming the function names are predefined and don't need me to set up delegation to access them. Its not something I've seen in any of the questions I've come across.

I am of course assuming that these functions are supposed to be hit and they are being hit and are capable of creating logs?

Any help gratefully received.

Answer 1

I've had unexplainable problems with python logging, I solved them by setting up the logging right at the beginning of the program:

import logging
logging.basicConfig(filename='convert_st.log', level=logging.INFO)
logging.info('Started')

import all_other_packages
import...
...

def main:
   # main comes here
   ...

if __name__ == '__main__':
    main()

Answer 2

There are a few problems with the code:

1. logging.basicConfig() should be called only once, if called again it won't have any effect.
2. Class definition will be called first in your code, even before block if __name__ == '__main__': because of natural flow of code. Due to this, whatever you set in logging.basicConfig() in class definition will become final for whole script. It is not an ideal place for this setting, so should be moved elsewhere (at the top, outside the class preferably).
3. filename parameter passed in the logging.basicConfig should be the absolute file path, because once service starts running, its current path won't be the same as the script, so logging won't be able to find out the log file. (current working directory for the service would become something like C:\Python37\lib\site-packages\win32).
4. (Optional): Try not to use root logging config at all, it's better to have an instance of logger for your own use.

After all these changes, the script will look like this:

import win32serviceutil
import win32service
import win32event
import servicemanager
import socket
import logging.handlers

log_file_path = ""  # mention full path here
mylogger = logging.getLogger("TestLogger")
mylogger.setLevel(logging.INFO)
handler = logging.handlers.RotatingFileHandler(log_file_path)
mylogger.addHandler(handler)

class AppServerSvc(win32serviceutil.ServiceFramework):
    _svc_name_ = "TestService"
    _svc_display_name_ = "Test Service"
    _svc_description_ = "New Test Service"

    mylogger.info('Class opened')

    def __init__(self, args):
        mylogger.info('Init')
        win32serviceutil.ServiceFramework.__init__(self, args)
        self.hWaitStop = win32event.CreateEvent(None, 0, 0, None)
        socket.setdefaulttimeout(60)


    def SvcStop(self):
        mylogger.info('Stop')
        self.ReportServiceStatus(win32service.SERVICE_STOP_PENDING)
        win32event.SetEvent(self.hWaitStop)


    def SvcDoRun(self):
        mylogger.info('Run')
        servicemanager.LogMsg(servicemanager.EVENTLOG_INFORMATION_TYPE,
                              servicemanager.PYS_SERVICE_STARTED,
                              (self._svc_name_, ''))
        self.main()


    def main(self):
        print("running")
        mylogger.info('Main')

if __name__ == '__main__':
    mylogger.info('Calling Handle Command Line')
    win32serviceutil.HandleCommandLine(AppServerSvc)

Output:

Class opened
Init
Run
Main
Class opened
Calling Handle Command Line