[python-win32] unexpected behavior for threaded Windows Service

[Jim Vickroy]

Attached is a "short" script that demonstrates an unexpected behavior of a
threaded, producer/consumer, Windows Service.

My expectation was that the producer would be queuing events every 2
(producer_pause) seconds while the consumer would be processing queued
events every 10 (consumer_pause) seconds.  However, the log, generated by
this Service, indicates the producer is queuing events at the same frequency
as the consumer is processing them.

Could someone help me to understand why the producer is not operating
independently of the consumer?


Thanks,

-- jv


P.S.

My system:
	Python 2.3.3
	pywin build 202
	Windows XP
-------------- next part --------------
'''
A MSW  Service with a producer and a consumer thread connected by a queue.

AUTHOR
   jim.vickroy at noaa.gov
'''


import win32serviceutil, win32service, win32event
import Queue
from   thread  import start_new_thread
from   logging import getLogger, shutdown, Logger, FileHandler, Formatter, CRITICAL, ERROR, WARNING, INFO, DEBUG, NOTSET
from   time    import ctime, sleep, time




class Tester(win32serviceutil.ServiceFramework):

   _svc_name_         = 'Threaded.Services.Tester'
   _svc_display_name_ = _svc_name_.replace('.', ' ')
   _svc_deps_         = ['EventLog'] # optional -- names of services to be started before this one

   consumer_pause = 10 # seconds
   producer_pause =  2 # seconds


   def __init__(self, args):

      win32serviceutil.ServiceFramework.__init__(self, args)

      # create/configure a logger to record service activities ...
      self.log        = getLogger(self._svc_display_name_)
      filename  = '%s.log' % self._svc_display_name_
      recorder  = FileHandler(filename)
      formatter = Formatter('%(asctime)s, %(levelname)-8s, %(message)s')
      recorder.setLevel(DEBUG)
      recorder.setFormatter(formatter)
      self.log.addHandler(recorder)
      self.log.setLevel(DEBUG)

      # remaining infrastructure attributes ...
      self.stop_request = win32event.CreateEvent(None, 0, 0, None) # "stop" request
      self.events       = Queue.Queue() # events to be processed


   def SvcStop(self):

      self.ReportServiceStatus(win32service.SERVICE_STOP_PENDING) # send an acknowledgement to the SCM
      win32event.SetEvent(self.stop_request)


   def SvcDoRun(self):

      start_new_thread(self.producer, ()) # no parameters to pass to the procedure

      import servicemanager # available only at runtime
      servicemanager.LogInfoMsg('%s started' % self._svc_display_name_) # record event in Microsoft Windows Application Events Log

      while not self.shutdown_requested():
         while not self.events.empty():
            event = self.events.get()
            self.log.info('consumed "%s"' % event)

      self.shut_down()


   def shut_down(self):

      import servicemanager # available only at runtime
      servicemanager.LogInfoMsg('%s stopped' % self._svc_display_name_) # record event in Microsoft Windows Application Events Log
      self.log.info('SHUTDOWN request received')
      shutdown()


   def shutdown_requested(self):

      return win32event.WaitForSingleObject(self.stop_request, self.consumer_pause * 1000) == win32event.WAIT_OBJECT_0


   def producer(self):

      while not self.shutdown_requested():
         event = ctime(time())
         try:
            self.events.put(event)
         except Exception, details:
            self.log.exception('events queuing failure')
         else:
            self.log.info('queued   "%s"' % event)
         sleep(self.producer_pause)




if __name__=='__main__':
   from win32serviceutil import HandleCommandLine
   HandleCommandLine(Tester)