Uncategorized

multithreading – Python Windows Service Not Refreshing Heartbeat as Expected


I’m working on a Python script to create a Windows service that performs two primary tasks:

1.Writing random numbers to a file (This will later be replaced with a other API call)
2.maintaining a heartbeat by making periodic API calls.

The service is supposed to
refresh the heartbeat every X seconds (as set in a configuration file), but it’s not doing so as expected. The random number writing functionality works fine, but the heartbeat doesn’t seem to refresh at the specified interval.

import servicemanager
import win32serviceutil
import win32service
import win32event
import configparser
import os
import random
import time
import sys
import logging
from logging.handlers import TimedRotatingFileHandler
from datetime import datetime
import threading
import requests

class MyService:
    def __init__(self, config):
        self.running = False
        self.base_directory = os.path.join(os.environ['PROGRAMDATA'], 'TEST', 'Test')
        self.logs_directory = os.path.join(self.base_directory, 'logs')
        self.file_path = os.path.join(self.base_directory, 'random_numbers.txt')
        self.config = config
        self.setup_logging()
        self.cached_token = None
        self.token_lock = threading.Lock()
        self.api_url = self.config.get('Settings', 'api_url')
        self.username = self.config.get('Credentials', 'username')
        self.password = self.config.get('Credentials', 'password')
        self.heartbeat_interval = self.config.getint('Settings', 'heartbeat_interval', fallback=60)

        self.authenticate_and_start_heartbeat()


    def setup_logging(self):
        if not os.path.exists(self.logs_directory):
            os.makedirs(self.logs_directory)

        # Format the log file name with the current date
        current_date = datetime.now().strftime("%d_%m_%Y")
        log_file_name = f'LOGING_{current_date}.log'

        log_file_path = os.path.join(self.logs_directory, log_file_name)
        self.logger = logging.getLogger('MyServiceLogger')
        self.logger.setLevel(logging.INFO)

        handler = TimedRotatingFileHandler(log_file_path, when="midnight", interval=1, backupCount=7)
        formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')
        handler.setFormatter(formatter)
        self.logger.addHandler(handler)


    def log_message(self, message):
        self.logger.info(message)
    
    def get_bearer_token(self, username, password, api_url):
        auth_url = api_url + "/api/token"
        auth_data = {"grant_type": "password", "username": username, "password": password}
        headers = {"Content-Type": "application/x-www-form-urlencoded"}
        response = requests.post(auth_url, data=auth_data, headers=headers)

        if response.status_code == 200:
            self.log_message("Authenticated successfully")
            return response.json().get('access_token')
        else:
            self.logger.error(f"Failed to authenticate: {response.status_code} || Response: {response.text}")
            return None

    def authenticate(self):
        self.log_message("Attempting to authenticate.")
        new_token = self.get_bearer_token(self.username, self.password, self.api_url)
        if new_token:
            self.log_message("New token obtained successfully.")
            with self.token_lock:
                self.cached_token = new_token
        else:
            self.logger.error("Failed to obtain new token.")

    def refresh_heartbeat(self):
        self.log_message("Attempting to refresh heartbeat.")
        heartbeat_url = self.api_url + "/api/heartbeat"
        headers = {"Authorization": f"Bearer {self.cached_token}"}
        response = requests.post(heartbeat_url, headers=headers)

        if response.status_code == 200:
            self.log_message("Heartbeat refreshed successfully.")
            return True
        else:
            self.log_message(f"Failed to refresh heartbeat: {response.status_code} || Response: {response.text}")
            return False

    def maintain_heartbeat(self):
        self.log_message(f"Starting heartbeat maintenance with interval {self.heartbeat_interval} seconds.")
        while self.running:
            try:
                with self.token_lock:
                    self.log_message("Checking for valid token for heartbeat.")
                    if self.cached_token:
                        self.log_message("Valid token found. Proceeding to refresh heartbeat.")
                        if not self.refresh_heartbeat():
                            self.log_message("Refreshing token due to heartbeat failure.")
                            self.authenticate()  # Refresh token if heartbeat failed
                    else:
                        self.log_message("No valid token found. Skipping heartbeat refresh.")
                self.log_message("Sleeping for heartbeat interval.")
                time.sleep(self.heartbeat_interval)
            except Exception as e:
                self.log_message(f"Error in maintain_heartbeat: {e}")

    def authenticate_and_start_heartbeat(self):
        self.authenticate()
        heartbeat_thread = threading.Thread(target=self.maintain_heartbeat)
        heartbeat_thread.daemon = True
        heartbeat_thread.start()
    
    def stop(self):
        self.running = False

    def run(self):
        if not os.path.exists(self.base_directory):
            os.makedirs(self.base_directory)

        self.running = True
        while self.running:
            number = random.randint(1, 100)
            with open(self.file_path, 'a') as f:
                f.write(f'{number}\n')
            self.log_message(f'Written number: {number}')
            time.sleep(5)

class MyServiceFramework(win32serviceutil.ServiceFramework):
    _svc_name_ = "TestService"
    _svc_display_name_ = "Test Service"

    def __init__(self, args):
        win32serviceutil.ServiceFramework.__init__(self, args)
        self.hWaitStop = win32event.CreateEvent(None, 0, 0, None)

        config_file = os.path.join(os.environ['PROGRAMDATA'], 'Folder', 'TEST', 'config', 'service_config.ini')
        config = configparser.ConfigParser()
        config.read(config_file)

        self.service_impl = MyService(config)

    def SvcStop(self):
        self.ReportServiceStatus(win32service.SERVICE_STOP_PENDING)
        self.service_impl.stop()
        win32event.SetEvent(self.hWaitStop)
        self.ReportServiceStatus(win32service.SERVICE_STOPPED)

    def SvcDoRun(self):
        self.ReportServiceStatus(win32service.SERVICE_RUNNING)
        self.service_impl.run()

def init():
    if len(sys.argv) == 1:
        servicemanager.Initialize()
        servicemanager.PrepareToHostSingle(MyServiceFramework)
        servicemanager.StartServiceCtrlDispatcher()
    else:
        win32serviceutil.HandleCommandLine(MyServiceFramework)

if __name__ == '__main__':
    init()

But my logs look like this:

2024-01-17 16:49:20,603 - INFO - Attempting to authenticate.
2024-01-17 16:49:21,060 - INFO - Authenticated successfully
2024-01-17 16:49:21,060 - INFO - New token obtained successfully.
2024-01-17 16:49:21,060 - INFO - Starting heartbeat maintenance with interval 30 seconds.
2024-01-17 16:49:21,075 - INFO - Written number: 10
2024-01-17 16:49:26,077 - INFO - Written number: 72
2024-01-17 16:49:31,079 - INFO - Written number: 96
2024-01-17 16:49:36,081 - INFO - Written number: 61
2024-01-17 16:49:41,082 - INFO - Written number: 85
2024-01-17 16:49:46,083 - INFO - Written number: 76
2024-01-17 16:49:51,085 - INFO - Written number: 3
2024-01-17 16:49:56,087 - INFO - Written number: 34
2024-01-17 16:50:01,088 - INFO - Written number: 97
2024-01-17 16:50:06,089 - INFO - Written number: 72
2024-01-17 16:50:11,091 - INFO - Written number: 50
2024-01-17 16:50:16,093 - INFO - Written number: 89
2024-01-17 16:50:21,094 - INFO - Written number: 99
2024-01-17 16:50:26,096 - INFO - Written number: 24
2024-01-17 16:50:31,097 - INFO - Written number: 76
2024-01-17 16:50:36,098 - INFO - Written number: 53
2024-01-17 16:50:41,099 - INFO - Written number: 19
2024-01-17 16:50:46,101 - INFO - Written number: 12
2024-01-17 16:50:51,103 - INFO - Written number: 37
2024-01-17 16:50:56,104 - INFO - Written number: 80
2024-01-17 16:51:01,106 - INFO - Written number: 24
2024-01-17 16:51:06,107 - INFO - Written number: 23
2024-01-17 16:51:11,108 - INFO - Written number: 43
2024-01-17 16:51:16,109 - INFO - Written number: 4
2024-01-17 16:51:21,110 - INFO - Written number: 25
2024-01-17 16:51:26,111 - INFO - Written number: 58
2024-01-17 16:51:31,113 - INFO - Written number: 85
2024-01-17 16:51:36,115 - INFO - Written number: 44
2024-01-17 16:51:41,116 - INFO - Written number: 49
2024-01-17 16:51:46,117 - INFO - Written number: 6
2024-01-17 16:51:51,120 - INFO - Written number: 80
2024-01-17 16:51:56,121 - INFO - Written number: 18
2024-01-17 16:52:01,123 - INFO - Written number: 44

As you can see it does not refresh the Heartbeat ever, which is very confusing as I have told it to do so every 30 seconds (60s if not specified)



Source link

Leave a Reply

Your email address will not be published. Required fields are marked *