2

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.

Sagar Gupta
  • 1,352
  • 1
  • 12
  • 26
Matthew Baker
  • 2,637
  • 4
  • 24
  • 49
  • How did you confirm that your service is running? I'm geting :Error starting service: The service did not respond to the start or control request in a timely fashion. Solution of which will be here : https://stackoverflow.com/questions/32404/how-do-you-run-a-python-script-as-a-service-in-windows/24996607#24996607. But how did you check? – Sagar Gupta Aug 19 '19 at 18:29
  • 1
    I had the same issue - apparently its a known problem. The solution is to copy a file that commonly gets installed in the wrong place. The solution that worked for me is here: https://stackoverflow.com/questions/41200068/python-windows-service-error-starting-service-the-service-did-not-respond-to-t – Matthew Baker Aug 20 '19 at 08:49
  • The file is now pywintypes37 (not 36) but the answer is sound. You can check in services.msc that the service is installed, and if you put an inifiinite loop into the startup code it appears to remain open, but I don't understand why it cannot log anything. – Matthew Baker Aug 20 '19 at 08:52

2 Answers2

5

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
Sagar Gupta
  • 1,352
  • 1
  • 12
  • 26
  • This. Use a full path for the logger then everything will be fine. You can also confirm that a log file is indeed being created by doing a global search for `search_server.log` on your system – Taxel Aug 20 '19 at 12:33
  • 1
    Many thanks Sagar. This was just the answer I was looking for. It not only solved the issue I was having, but clearly explained where my misconceptions lay. As a new Python user I am very grateful for the support and quality of your answer. Anyone else coming across this in the future I can highly recommend the approach listed in the answer above. – Matthew Baker Aug 21 '19 at 06:12
  • Where the `servicemanager.LogMsg` will write is log message? – Aelius Sep 08 '22 at 15:03
0

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()
Francis
  • 563
  • 1
  • 7
  • 14