Problems with System.Timers.Timer. Firing more than once occasionally

Question

I'm using System.Timers.Timer to backup my SQL Server Express Database once a day. It seems to work fine, most of the time. Occasionally, the ElapsedEventHandler gets called multiple times at 1 or 4 minute intervals. It should just be hit once a day. I have AutoReset as false and I call Start at the end of the ElapsedEventHandler. Also, possibly relevant is that I do recalculate the interval so that the timer always goes off as close to 1 am. as possible. The backing up of the database can take a few minutes, and if I didn't change the interval, the time might drift unacceptably. I mention this because these links suggest there might be a problem with resetting the interval:

See in particular the answers by Hans Passant

However, I don't see how I can avoid resetting the interval. Also, I looked into the code for System.Timers.Timer. It didn't seem like just resetting the interval would Start the timer again. I'm not opposed to using a different timer (System.Threading.Timer?) but I'd like to know what is going on first.

I've pasted all the code below. I would think the truly relevant part is the method: DatabaseBackupTimerOnElapsed

Finally, I'll mention that the program is sometimes stopped and restarted (if there are uncaught exceptions in other parts of the code). I would assume though that all timers are killed at the point of exiting the program even if Dispose is not called? That is Timers don't live on in the operating system?

EDIT I was requested to put down a small, complete, verifiable example. I do so here. I've kept the full example as someone might claim (quite correctly!) that I took out an important detail. I've run this code and have NOT seen the problem but then, it only happens very occasionally with the original code.

public class DatabaseCleanupManager 
{
    private const int MaxRetries = 5;
    private const int DatabaseBackupHourOneAm = 1;


    private Timer _databaseBackupTimer;

    public DatabaseCleanupManager()
    { }

    public void Initialize()
    {
        Console.WriteLine("Initialize");
        TimeSpan spanTimer = GetDBBackupTimeSpan(1);

        _databaseBackupTimer = new Timer(spanTimer.TotalMilliseconds)
        {
            AutoReset = false,
        };

        _databaseBackupTimer.Elapsed += DatabaseBackupTimerOnElapsed;
        _databaseBackupTimer.Start();
    }

    private TimeSpan GetDBBackupTimeSpan(int databaseBackupFrequencyInDays)
    {
        Console.WriteLine("GetDBBackupTimeSpan");
        DateTime dt1 = DateTime.Now;
        DateTime dt2 = new DateTime(dt1.Year, dt1.Month,
            dt1.Day, 1, 0, 0);
        // I'm really interested in a timer once a day.  I'm just trying to get it to happen quicker!
        //dt2 = dt2.AddDays(databaseBackupFrequencyInDays);
        dt2 = dt1.AddMinutes(4);

        TimeSpan spanTimer = dt2 - dt1;

        if (spanTimer.TotalMilliseconds < 0) // This could conceivably happen if the have 0 or a negative number (erroneously) for DatabaseBackupFrequencyInDays 
        {
            dt2 = new DateTime(dt1.Year, dt1.Month,
                dt1.Day, 1, 0, 0);
            //dt2 = dt2.AddDays(databaseBackupFrequencyInDays);
            dt2 = dt1.AddMinutes(4);
            spanTimer = dt2 - dt1;
        }
        return spanTimer;
    }
    public void PerformDatabaseMaintenance()
    {
        if (BackupCurrentDatabase())
        {
            var success = CleanupExpiredData();

            if (success)
            {
                Console.WriteLine("Database Maintenance Finished");
            }
        }

    }

    public void Dispose()
    {
        _databaseBackupTimer.Elapsed -= DatabaseBackupTimerOnElapsed;
        _databaseBackupTimer.Stop();
        _databaseBackupTimer.Dispose();
    }

    private void DatabaseBackupTimerOnElapsed(object sender, ElapsedEventArgs elapsedEventArgs)
    {
        try
        {
            Console.WriteLine("DatabaseBackupTimerOnElapsed at: " + DateTime.Now);
            PerformDatabaseMaintenance();

            TimeSpan spanTimer = GetDBBackupTimeSpan(1);

            // NOTICE I'm calculating Interval again.  Some posts suggested that this restarts timer
            _databaseBackupTimer.Interval = Math.Max(spanTimer.TotalMilliseconds, TimeSpan.FromMinutes(1).TotalMilliseconds);
            _databaseBackupTimer.Start();

        }
        catch (Exception )
        {
            // something went wrong - log problem and start timer again.
            _databaseBackupTimer.Start();
        }

    }

    private bool BackupCurrentDatabase()
    {
        // actually backup database but here I'll just sleep for 1 minute...
        Thread.Sleep(1000);
        Console.WriteLine("Backed up DB at: " + DateTime.Now);
        return true;
    }

    private bool CleanupExpiredData()
    {
        // Actually remove old SQL Server Express DB .bak files but here just sleep
        Thread.Sleep(1000);
        Console.WriteLine("Cleaned up old .Bak files at: " + DateTime.Now);
        return true;
    }


}

 class Program
{
    static void Main(string[] args)
    {
        DatabaseCleanupManager mgr = new DatabaseCleanupManager();
        mgr.Initialize();

        // here we'd normally be running other threads etc., but for here...
        Thread.Sleep(24*60*60*1000);  // sleep for 1 day
    }
}

END EDIT

public class DatabaseCleanupManager : IDatabaseCleanupManager
{
    private const int MaxRetries = 5;
    private const int DatabaseBackupHourOneAm = 1;

    private readonly ISystemConfiguration _systemConfiguration;
    private readonly IPopsicleRepository _repository;
    private readonly ISystemErrorFactory _systemErrorFactory;
    private readonly IAuthorizationManager _authorizationManager;
    private readonly IReportRobotState _robotStateReporter;
    private Timer _databaseBackupTimer;

    public DatabaseCleanupManager(
        IPopsicleRepository repository,
        ISystemConfiguration configuration,
        ISystemErrorFactory systemErrorFactory,
        IAuthorizationManager authorizationManager,
        IReportRobotState robotStateReporter)
    {
        if (repository == null)
            throw new ArgumentNullException("repository");

        if (configuration == null)
            throw new ArgumentNullException("configuration");

        if (systemErrorFactory == null)
            throw new ArgumentNullException("systemErrorFactory");

        if (authorizationManager == null)
            throw new ArgumentNullException("authorizationManager");

        if (robotStateReporter == null)
            throw new ArgumentNullException("robotStateReporter");

        _repository = repository;
        _systemConfiguration = configuration;
        _systemErrorFactory = systemErrorFactory;
        _authorizationManager = authorizationManager;
        _robotStateReporter = robotStateReporter;
    }

    public event EventHandler<SystemErrorEventArgs> SystemError;

    public event EventHandler<SystemErrorClearedEventArgs> SystemErrorCleared;


    public void Initialize()
    {

        TimeSpan spanTimer = GetDBBackupTimeSpan(_systemConfiguration.DatabaseBackupFrequencyInDays);

        _databaseBackupTimer = new Timer(spanTimer.TotalMilliseconds)
        {
            AutoReset = false,
        };

        _databaseBackupTimer.Elapsed += DatabaseBackupTimerOnElapsed;
        _databaseBackupTimer.Start();
    }

    private TimeSpan GetDBBackupTimeSpan(int databaseBackupFrequencyInDays)
    {
        DateTime dt1 = DateTime.Now;
        DateTime dt2 = new DateTime(dt1.Year, dt1.Month,
            dt1.Day, 1, 0, 0);
        dt2 = dt2.AddDays(_systemConfiguration.DatabaseBackupFrequencyInDays);

        TimeSpan spanTimer = dt2 - dt1;

        if (spanTimer.TotalMilliseconds < 0) // This could conceivably happen if the have 0 or a negative number (erroneously) for DatabaseBackupFrequencyInDays in configuration.json
        {
            dt2 = new DateTime(dt1.Year, dt1.Month,
                dt1.Day, 1, 0, 0);
            dt2 = dt2.AddDays(1);
            spanTimer = dt2 - dt1;
        }
        return spanTimer;
    }
    public void PerformDatabaseMaintenance()
    {
        if (BackupCurrentDatabase())
        {
            var success = CleanupExpiredData();

            if (success)
            {
                Logger.Log(LogLevel.Info, string.Format("Database Maintenance succeeded"));
                NotifySystemError(ErrorLevel.Log, ErrorCode.DatabaseBackupComplete, "Database backup completed");
            }
        }

    }

    public void Dispose()
    {
        _databaseBackupTimer.Elapsed -= DatabaseBackupTimerOnElapsed;
        _databaseBackupTimer.Stop();
        _databaseBackupTimer.Dispose();
    }

    private void DatabaseBackupTimerOnElapsed(object sender, ElapsedEventArgs elapsedEventArgs)
    {

        try
        {

            PerformDatabaseMaintenance();

            TimeSpan spanTimer = GetDBBackupTimeSpan(_systemConfiguration.DatabaseBackupFrequencyInDays);

            _databaseBackupTimer.Interval = Math.Max(spanTimer.TotalMilliseconds, TimeSpan.FromMinutes(10).TotalMilliseconds);
            _databaseBackupTimer.Start();

        }
        catch (Exception e)
        {
            Logger.Log(LogLevel.Warning,
                string.Format("Database Backup Failed: {0}, ",
                    e.Message));
            NotifySystemError(ErrorLevel.Log, ErrorCode.DatabaseBackupFailed,
                "Database backup failed ");

            _databaseBackupTimer.Start();
        }


    }



    private bool BackupCurrentDatabase()
    {
        try
        {
            _repository.Alerts.Count();
        }
        catch (Exception ex)
        {
            NotifySystemError(ErrorLevel.Log, ErrorCode.DatabaseBackupFailed, "Database backup failed - the database server does not respond or the database does not exist");
            throw new InvalidOperationException(string.Format("The DB does not exist : {0} Error {1}", _systemConfiguration.LocalDbPath, ex.Message));
        }

        if (!Directory.Exists(_systemConfiguration.LocalBackupFolderPath))
            Directory.CreateDirectory(_systemConfiguration.LocalBackupFolderPath);

        var tries = 0;
        var success = false;

        while (!success && tries < MaxRetries)
        {
            try
            {
                _repository.BackupDatabase(_systemConfiguration.LocalBackupFolderPath);
                success = true;
            }
            catch (Exception e)
            {
                Logger.Log(LogLevel.Warning, string.Format("Database Backup Failed: {0}, retrying backup", e.Message));
                Thread.Sleep(TimeSpan.FromSeconds(1));
                tries++;

                if (tries == MaxRetries)
                {
                    NotifySystemError(ErrorLevel.Log, ErrorCode.DatabaseBackupFailed, string.Format("Database backup failed - {0}", e.Message));
                }
            }
        }

        var backupDirectory = new DirectoryInfo(_systemConfiguration.LocalBackupFolderPath);
        var files = backupDirectory.GetFiles().OrderBy(f => f.CreationTime).ToArray();

        if (files.Length > _systemConfiguration.MaxDatabaseBackups)
        {
            for (var i = 0; i < (files.Length - _systemConfiguration.MaxDatabaseBackups); i++)
            {
                try
                {
                    files[i].Delete();
                }
                catch (Exception e)
                {
                    Logger.Log(LogLevel.Warning, string.Format("Failed to delete old backup: {0}", e.Message));
                }
            }
        }

        Logger.Log(LogLevel.Info, success ?
            "Database Backup succeeded" :
            string.Format("Database Backup failed after {0} retries", MaxRetries));

        return success;
    }

    private bool CleanupExpiredData()
    {
        var success = false;
        try
        {
            var expirationTime = DateTime.Now - TimeSpan.FromDays(_systemConfiguration.DatabaseDataExpirationInDays);
            _repository.DeleteTemperatureReadingsBeforeDate(expirationTime);
            _repository.DeleteTransactionsBeforeDate(expirationTime);
            success = true;
        }
        catch (Exception e)
        {
            Logger.Log(LogLevel.Warning, string.Format("Failed to cleanup expired data: {0}", e.Message));
            NotifySystemError(ErrorLevel.Log, ErrorCode.DatabaseBackupFailed, string.Format("Database cleanup of expired data failed - {0}", e.Message));
        }

        Logger.Log(LogLevel.Info, success ?
            string.Format("Database clean up expired data succeeded") :
            string.Format("Database clean up expired data failed"));

        return success;
    }

    private void NotifySystemError(ErrorLevel errorLevel, ErrorCode errorCode, string description)
    {
        var handler = SystemError;
        if (handler != null)
        {
            var systemError = _systemErrorFactory.CreateSystemError(errorLevel, errorCode, description);
            handler(this, new SystemErrorEventArgs(systemError));
        }
    }
}

Please edit your question into a [mcve]. There are lots of irrelevant code there — Camilo Terevinto, Jul 18 '17 at 18:15
Seconded. Edit your question down. There's way too much irrelevant code here. — , Jul 18 '17 at 18:19
I will edit it down. I left it all in as something that I think is irrelevant might not be so. Thanks for the quick feedback. — Dave, Jul 18 '17 at 18:30
Just a side note: You read a value from `_systemConfiguration` that you then pass to `GetDBBackupTimeSpan`, but in that you ignore the argument and read from `_systemConfiguration` again. — 500 - Internal Server Error, Jul 18 '17 at 18:33
Internal Server Error..... Yes I saw that thanks. I fixed it in my condensed version that was requested. — Dave, Jul 18 '17 at 20:20

score 2 · Accepted Answer · answered Jul 18 '17 at 19:37

2

what I suspect is that Initialize is called multiple time, what you could do is check that the _databaseBackupTimer is null before creating a new instance

if it's not null, just skip the whole code in that method

answered Jul 18 '17 at 19:37

Fredou

19,848
10
58
113

Thanks for the quick response. I'll check that (with some log statements) but I don't think that's what going on as DatabaseCleanupManager is just instantiated once at program startup. – Dave Jul 18 '17 at 20:30
Eureka! That was it. Initialize is being called whenever the screen saver kicks in, whenever a user logs out, and probably other times. Why this is being done is another question, but I'm very grateful you spotted it! – Dave Jul 18 '17 at 21:10

score -2 · Answer 2 · answered Jul 18 '17 at 19:03

I think the solution is overly complicated.

The timer interval will fire the Elapsed event independent of when the fact that a previous run had finished or not, unless you explicitly stop the timer during the event. This should not be necessary. You could simply keep track of whether you are running or not when you enter the method.

Set the interval to 59999. This is a millisecond short of a minute. Then at entry in the event handler check if the current hour and minute correspond to the time when you want to backup.

private bool running = false;
private Timer timer = new Timer();
//other code.
private void Initialize()
{
    timer.Interval = 59999;
    myTimer.Elapsed += TimerElapsed;
    timer.Start();
}

public void TimerElapsed(object sender, ElapsedEventArgs e)
{
   if (running) return;
   DateTime dt = DateTime.Now();

   if (!(dt.Hour.Equals(1) && dt.Minute.Equals(0))) return;

   running = true;
   //other code
   running = false;
}

In addition, I would keep the time of running the backup in a configuration file or registry so that if I want to change it, I could do that without re-compiling my service.

Problems with System.Timers.Timer. Firing more than once occasionally

2 Answers2