[python-win32] Event log doesn't log events on SvcShutdown() event in service

[Rob McGillivray]

Hello All,

This email is a follow-on from my last post to which Mark kindly gave me some pointers. I have a service and all is working as advertised, besides the fact that the eventlog service does not log any events during the implementation of the shutdown event in SvcDoRun(). Tested both Win7 and Win Server 2003.

Mark's comment was the the eventlog service had most likely shut down by time I made my request, so try making the service dependent upon the eventlog service, which I did, but to no avail. I then logged all actions to file as he suggested, which shows pretty clearly that all the events from the SCM are firing correctly and are being handled by my service:

2012-11-05 10:32:19.590000: Doing my work...
2012-11-05 10:32:32.944000: SvcPause event on controlhandler thread
2012-11-05 10:32:32.944000: PAUSE event in SvcDoRun()
2012-11-05 10:32:39.402000: SvcContinue event on controlhandler thread
2012-11-05 10:32:39.402000: CONTINUE event in SvcDoRun()
2012-11-05 10:32:39.402000: Doing my work...
2012-11-05 10:32:49.099000: SvcShutdown event on controlhandler thread
2012-11-05 10:32:49.099000: SHUTDOWN event in SvcDoRun()

**However, the event log does not show the last call to the eventlog service "Shutting down the service…" per the code below. The last log entry for my service in the event log is "Doing my work…"**

I can't make sense of this. Surely if my service is dependent upon eventlog service, then this service must remain alive at least until my service terminates? I checked several other services for their dependencies, and they happily log shutdown notifications, BUT show NO dependency upon the eventlog as a service, so how exactly do they ensure that their events are dutifully logged during the shutdown process?

Moreover, if I notify the SCM upon shutdown within SvcDoRun() that my service is stopping, but needs a little more time, eg. ~10sec before entering the stopped state by calling ReportServiceStatus(win32service.SERVICE_STOP_PENDING, waitHint=10000), the waitHint is not respected, and the service still shuts down immediately.

Your thoughts would be much appreciated. (If there is a better way of listing code, please advise).

Thanks in advance,

Rob

------

#!/usr/bin/env python3

# Import helper modules
from os.path import splitext, abspath
from sys import modules

# Import pywin32 modules
import win32serviceutil
import servicemanager
import win32service
import win32event
import win32api

import datetime

class MyService(win32serviceutil.ServiceFramework):
    _svc_name_ = 'MyService'
    _svc_display_name_ = 'MyService Name'
    _svc_deps_ = 'eventlog',

    def __init__(self, *args):
        win32serviceutil.ServiceFramework.__init__(self, *args)
        # All manual reset events
        self.evStop = win32event.CreateEvent(None, True, 0, None)
        self.evPause = win32event.CreateEvent(None, True, 0, None)
        self.evContinue = win32event.CreateEvent(None, True, 0, None)
        self.evShutdown = win32event.CreateEvent(None, True, 0, None)
        self.evhandles = self.evStop, self.evPause, self.evContinue, self.evShutdown
        self.validSignals = range(win32event.WAIT_OBJECT_0, 
                                  win32event.MAXIMUM_WAIT_OBJECTS)

        # Signal ID returned from WFMO() else None
        self.sigStatus = 0

    def logEvent(self, msg):
        servicemanager.LogInfoMsg(str(msg))

    def sleep(self, sec):
        while sec > 0:
            # SCM event has taken place?
            if win32event.WaitForMultipleObjects(self.evhandles, 0, 1000) in self.validSignals:
                break
            sec -= 1

    def logToFile(self, msg):
        with open('c:\myservice.txt', 'a') as f:
            f.write('{0}: {1}\r\n'.format(datetime.datetime.today(), msg))

    def SvcDoRun(self):
        self.logEvent('Service started.')
        running = True

        while True:			
            if running:
                self.logEvent('Doing my work...')
                self.logToFile('Doing my work...')
            self.sleep(30)

            # SCM notification?
            self.sigStatus = win32event.WaitForMultipleObjects(self.evhandles, 0, 1000)
            if self.sigStatus == self.evhandles.index(self.evStop):
                # STOP event
                self.logToFile('STOP event in SvcDoRun()')
                self.logEvent('Stopping service...')
                break
            elif self.sigStatus == self.evhandles.index(self.evPause):
                # PAUSE event
                self.logToFile('PAUSE event in SvcDoRun()')
                self.logEvent('Pausing service...')
                self.ReportServiceStatus(win32service.SERVICE_PAUSE_PENDING)
                running = False
                win32event.ResetEvent(self.evPause)
                # Other cleanup code here...
                self.logEvent('Service paused.')
                self.ReportServiceStatus(win32service.SERVICE_PAUSED)
            elif self.sigStatus == self.evhandles.index(self.evContinue):
                # CONTINUE event
                self.logToFile('CONTINUE event in SvcDoRun()')
                self.logEvent('Resuming service...')
                self.ReportServiceStatus(win32service.SERVICE_CONTINUE_PENDING)
                running = True
                # Reset pause & continue to non-signaled state
                win32event.ResetEvent(self.evContinue)
                # Other cleanup code here...
                self.logEvent('Service started.')
                self.ReportServiceStatus(win32service.SERVICE_RUNNING)			
            elif self.sigStatus == self.evhandles.index(self.evShutdown):
                # SHUTDOWN event
                self.logToFile('SHUTDOWN event in SvcDoRun()')
                self.logEvent('Shutting down Service...')
                self.ReportServiceStatus(win32service.SERVICE_STOP_PENDING, waitHint=10000)
                win32api.Sleep(8000)
                break

    def SvcStop(self):
        # Signal STOP event
        self.logToFile('SvcStop event on controlhandler thread')
        win32event.SetEvent(self.evStop)

    def SvcPause(self):
        # Signal PAUSE event
        self.logToFile('SvcPause event on controlhandler thread')
        win32event.SetEvent(self.evPause)

    def SvcContinue(self):
        # Signal CONTINUE event
        self.logToFile('SvcContinue event on controlhandler thread')
        win32event.SetEvent(self.evContinue)

    def SvcShutdown(self):
        # Signal SHUTDOWN event
        self.logToFile('SvcShutdown event on controlhandler thread')
        win32event.SetEvent(self.evShutdown)

if __name__ == '__main__':
    win32serviceutil.HandleCommandLine(MyService)
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.python.org/pipermail/python-win32/attachments/20121105/9f2dc1c2/attachment-0001.html>