Modified Migration2 to simplify log initialisation.

Improved check to see if logs need to be downloaded if the database is recreated.
Split log synchronisation into separate log download and upload threads.
Switch from lastBatchId to minBatchId for /api/batches/ call.

BulkPrinting/BulkPrinting/BatchForm.cs

@@ -318,7 +318,7 @@ namespace BulkPrinting
                                 Log.Debug("Querying batches");
 
                                 Page<Batch> BatchPage = new Page<Batch>();
-                                if (Utility.RESTRequest(ref BatchPage, String.Format("/api/batches/?lastBatchId={0}", lastSyncedBatchId)))
+                                if (Utility.RESTRequest(ref BatchPage, String.Format("/api/batches/?minBatchId={0}", lastSyncedBatchId + 1)))
                                 {
                                     if (BatchPage.Items.Count == 0)
                                     {

BulkPrinting/BulkPrinting/Globals.cs

@@ -26,8 +26,12 @@ namespace BulkPrinting
         public static Printer MaxPrinter;
         public static List<int> OpenBatches;
         public static UserLimits UserCurrentUsage;
-        public static EventWaitHandle LogSyncThreadEvent;
-        public static Thread LogSyncThread;
-        public static bool LogSyncThreadAborted;
+        public static Thread LogUploadThread;
+        public static object LogUploadThreadLock = new object();
+        public static bool LogUploadThreadCancelled;
+        public static bool UploadNewLogs;
+        public static Thread LogDownloadThread;
+        public static object LogDownloadThreadLock = new object();
+        public static bool LogDownloadThreadCancelled;
     }
 }

BulkPrinting/BulkPrinting/Migrations.cs

@@ -147,6 +147,8 @@ namespace BulkPrinting
                 "UPDATE Parameters SET Value='2' WHERE Key='Migration'",
                 "UPDATE Batch SET Downloaded=(ReadyForDownload=1 AND DeliveredQuantity<=COALESCE((SELECT COUNT(*) FROM Voucher WHERE Voucher.BatchId=Batch.Id), 0))",
                 "INSERT INTO Parameters (Key, Value) VALUES ('LastSyncedBatchId', '0')",
+                "INSERT INTO Parameters (Key, Value) VALUES ('SyncBackwardsFromLogId', '0')",
+                "INSERT INTO Parameters (Key, Value) VALUES ('LoggingInitialised', '" + false.ToString() + "')",
                 "CREATE TABLE Logs_New (" +
                     "Id INTEGER PRIMARY KEY AUTOINCREMENT," +
                     "UserId INT NOT NULL," +

BulkPrinting/BulkPrinting/UserLoginForm.cs

@@ -121,8 +121,9 @@ namespace BulkPrinting
                             Globals.DBConnection = Utility.OpenDBConnection();
                         }
                         Migrations.CheckMigrations(Globals.DBConnection);
-                        Utility.CheckLastSyncedLogID(Globals.DBConnection);
-                        Utility.TriggerLogSync(); //Perform log sync before any logging happens to ensure synchronicity with server
+                        Utility.CheckLogSynchronisation(Globals.DBConnection);
+                        Utility.TriggerLogDownload();
+                        Utility.TriggerLogUpload();
                     }
                 }
             }

BulkPrinting/BulkPrinting/Utility.cs

@@ -391,7 +391,12 @@ namespace BulkPrinting
 
         public static int GetSavedParameterAsInt(SQLiteConnection conn, string key)
         {
-            return int.Parse(GetSavedParameter(conn, key));
+            return Convert.ToInt32(GetSavedParameter(conn, key));
+        }
+
+        public static bool GetSavedParameterAsBoolean(SQLiteConnection conn, string key)
+        {
+            return Convert.ToBoolean(GetSavedParameter(conn, key));
         }
 
         public static bool UpdateSavedParameter(SQLiteConnection conn, string key, object value)
@@ -399,7 +404,7 @@ namespace BulkPrinting
             return DBExecuteNonQuery(conn,
                 "UPDATE Parameters SET Value=@Value WHERE Key=@Key",
                 new SQLiteParameter("@Key", key),
-                new SQLiteParameter("@Value", value)) > 0;
+                new SQLiteParameter("@Value", Convert.ToString(value))) > 0;
         }
 
         public static void PrintVouchers(SQLiteConnection conn, int BatchId, int StartSeqNo, int EndSeqNo)
@@ -560,17 +565,23 @@ namespace BulkPrinting
                     new SQLiteParameter("@key", "SessionDataJson"),
                     new SQLiteParameter("@value", SessionDataJson));
                 LogEvent(Globals.DBConnection, VendorEvent.VendorEventType.Logout);
-                if (Globals.LogSyncThread != null)
+
+                CancelLogUploadWorker();
+                CancelLogDownloadWorker();
+
+                if (Globals.LogUploadThread != null)
                 {
-                    Globals.LogSyncThreadAborted = true;
-                    Globals.LogSyncThreadEvent.Set();
-                    if (Globals.LogSyncThread.IsAlive)
-                    {
-                        Globals.LogSyncThread.Join();
-                    }
-                    Globals.LogSyncThread = null;
+                    Globals.LogUploadThread.Join();
+                    Globals.LogUploadThread = null;
+                }
+                if (Globals.LogDownloadThread != null)
+                {
+                    Globals.LogDownloadThread.Join();
+                    Globals.LogDownloadThread = null;
                 }
 
+                Globals.UploadNewLogs = false;
+
                 Globals.DBConnection.Close();
                 Globals.SessionData = null;
                 Globals.SessionDatabasePassword = null;
@@ -592,146 +603,262 @@ namespace BulkPrinting
             return (int)MetaData.LastVendorEventRemoteId;
         }
 
-        public static void CheckLastSyncedLogID(SQLiteConnection conn)
+        public static void CheckLogSynchronisation(SQLiteConnection conn)
         {
-            int lastSyncedLogId = GetLastSyncedLogID();
-            if (lastSyncedLogId == 0)
+            if (!GetSavedParameterAsBoolean(conn, "LoggingInitialised"))
             {
-                return;
+                var lastSyncedLogId = GetLastSyncedLogID();
+
+                // If we already have logs then there is no need to synchronise.
+                // NOTE: logs are synchronised in reverse from SyncBackwardsFromLogId downwards
+                if ((long)DBExecuteScalar(conn, "SELECT COUNT(*) FROM Logs") == 0)
+                {
+                    UpdateSavedParameter(conn, "SyncBackwardsFromLogId", lastSyncedLogId);
+                }
+
+                // If there are logs on the server then ensure that the log autoincrement value is set to the last
+                // log ID received by the server so new local logs don't clash with existing log entries on the server.
+                if (lastSyncedLogId != 0)
+                {
+                    lock (Globals.DBWriteLock)
+                    {
+                        using (var trans = conn.BeginTransaction())
+                        {
+                            using (var command = new SQLiteCommand(conn))
+                            {
+                                command.Transaction = trans;
+                                command.Parameters.AddWithValue("@Id", lastSyncedLogId);
+
+                                command.CommandText = "UPDATE sqlite_sequence SET seq=CASE WHEN IFNULL(seq, 0)<@Id THEN @Id ELSE seq END WHERE name='Logs'";
+                                if (command.ExecuteNonQuery() == 0)
+                                {
+                                    command.CommandText = "INSERT INTO sqlite_sequence (name, seq) VALUES ('Logs', @id)";
+                                    command.ExecuteNonQuery();
+                                }
+                            }
+                            trans.Commit();
+                        }
+                    }
+                }
+
+                UpdateSavedParameter(conn, "LoggingInitialised", true);
             }
-            lock (Globals.DBWriteLock)
+        }
+
+        public static void CancelLogDownloadWorker()
+        {
+            lock (Globals.LogDownloadThreadLock)
             {
-                using (var trans = conn.BeginTransaction())
+                Globals.LogDownloadThreadCancelled = true;
+                Monitor.Pulse(Globals.LogDownloadThreadLock);
+            }
+        }
+
+        public static void LogDownloadWorker()
+        {
+            const int vendorEventPageSize = 1000;
+            const int retryInterval = 30000;
+
+            var conn = Globals.DBConnection;
+            //using (var conn = OpenDBConnection())
+            {
+                bool cancelled = false;
+                int maxRemoteId = GetSavedParameterAsInt(conn, "SyncBackwardsFromLogId");
+                while (!cancelled && (maxRemoteId > 0))
                 {
-                    using (var command = new SQLiteCommand(conn))
+                    var EventPage = new Page<VendorEvent>();
+                    if (RESTRequest(ref EventPage, String.Format("/api/vendorevents/?maxRemoteId={0}&pageSize={1}", maxRemoteId, vendorEventPageSize)))
                     {
-                        command.Transaction = trans;
-                        command.Parameters.AddWithValue("@Id", lastSyncedLogId);
+                        lock (Globals.DBWriteLock)
+                        {
+                            using (var trans = conn.BeginTransaction())
+                            {
+                                using (var insertCommand = new SQLiteCommand(
+                                    "INSERT INTO Logs (Id,  UserId,  VoucherId,  EventDate,  EventType,  Retry) " +
+                                              "VALUES (@id, @userid, @voucherid, @eventdate, @eventtype, @retry)",
+                                    conn, trans))
+                                using (var updateCommand = new SQLiteCommand(
+                                    "UPDATE Parameters SET Value=@Value WHERE Key='SyncBackwardsFromLogId'",
+                                    conn, trans))
+                                {
+                                    foreach (VendorEvent Event in EventPage.Items)
+                                    {
+                                        if (!Event.RemoteId.HasValue)
+                                        {
+                                            throw new Exception("Downloaded event with no remote ID");
+                                        }
+                                        else if (Event.RemoteId.Value > maxRemoteId)
+                                        {
+                                            throw new Exception("Downloaded event remote ID was not in descending order");
+                                        }
 
-                        command.CommandText = "UPDATE sqlite_sequence SET seq=CASE WHEN IFNULL(seq, 0)<@Id THEN @Id ELSE seq END WHERE name='Logs'";
-                        if (command.ExecuteNonQuery() == 0)
+                                        insertCommand.Parameters.Clear();
+                                        insertCommand.Parameters.AddWithValue("@id", Event.RemoteId);
+                                        insertCommand.Parameters.AddWithValue("@userid", Event.UserId);
+                                        insertCommand.Parameters.AddWithValue("@voucherid", Event.VoucherId);
+                                        insertCommand.Parameters.AddWithValue("@eventdate", Event.EventDate.UtcDateTime);
+                                        insertCommand.Parameters.AddWithValue("@eventtype", Event.EventType);
+                                        insertCommand.Parameters.AddWithValue("@retry", Event.Retry);
+                                        insertCommand.ExecuteNonQuery();
+
+                                        maxRemoteId = Event.RemoteId.Value - 1;
+                                    }
+
+                                    updateCommand.Parameters.Clear();
+                                    updateCommand.Parameters.AddWithValue("@Value", maxRemoteId.ToString());
+                                    updateCommand.ExecuteNonQuery();
+                                }
+
+                                trans.Commit();
+                            }
+                        }
+
+                        lock (Globals.LogDownloadThreadLock)
                         {
-                            command.CommandText = "INSERT INTO sqlite_sequence (name, seq) VALUES ('Logs', @id)";
-                            command.ExecuteNonQuery();
+                            cancelled = Globals.LogDownloadThreadCancelled;
+                        }
+                    }
+                    else
+                    {
+                        lock (Globals.LogDownloadThreadLock)
+                        {
+                            if (!Globals.LogDownloadThreadCancelled)
+                            {
+                                Monitor.Wait(Globals.LogDownloadThreadLock, retryInterval);
+                            }
+                            cancelled = Globals.LogDownloadThreadCancelled;
                         }
                     }
-                    trans.Commit();
                 }
             }
         }
 
-        public static bool SyncLogsWorker()
+        public static void TriggerLogDownload()
         {
+            if (Globals.LogDownloadThread == null)
+            {
+                Globals.LogDownloadThread = new Thread(() => LogDownloadWorker());
+                Globals.LogDownloadThread.Start();
+            }
+        }
+
+        public static void CancelLogUploadWorker()
+        {
+            lock (Globals.LogUploadThreadLock)
+            {
+                Globals.LogUploadThreadCancelled = true;
+                Monitor.Pulse(Globals.LogUploadThreadLock);
+            }
+        }
+
+        public static void LogUploadWorker()
+        {
+            const int uploadPageSize = 1000;
+            var retryInterval = 30000;
+
             var conn = Globals.DBConnection;
             //using (var conn = OpenDBConnection())
             {
-                while (Globals.LogSyncThreadEvent.WaitOne() && !Globals.LogSyncThreadAborted)
+                var cancelled = false;
+                while (! cancelled)
                 {
-                    int LastSyncedLogID = GetLastSyncedLogID();
+                    var uploadFailed = false;
+                    int lastSyncedLogId = GetLastSyncedLogID();
 
                     var result = DBExecuteScalar(conn, "SELECT MAX(Id) FROM Logs")?.ToString() ?? "0";
-                    if (string.IsNullOrWhiteSpace(result)) result = "0";
-
-                    int LastRecordedLogId = int.Parse(result.ToString());
-                    if (LastRecordedLogId > LastSyncedLogID)
-                    { //If local logs are newer than server logs
-                        List<RemoteVendorEvent> EventList = new List<RemoteVendorEvent>();
-                        RemoteVendorEvent NextEvent;
-                        RemoteVendorEventResponse LastVendorEventIdSynced;
-                        int Counter = 0;
+                    if (string.IsNullOrWhiteSpace(result))
+                    {
+                        result = "0";
+                    }
+                    int lastRecordedLogId = int.Parse(result.ToString());
+
+                    if (lastRecordedLogId > lastSyncedLogId)
+                    {
+                        List<RemoteVendorEvent> eventList = new List<RemoteVendorEvent>();
+                        int counter = 0;
                         using (var Command = new SQLiteCommand("Select Id,UserId,VoucherId,EventDate,EventType From Logs WHERE Id > @id", conn))
                         {
-                            Command.Parameters.AddWithValue("@id", LastSyncedLogID);
+                            Command.Parameters.AddWithValue("@id", lastSyncedLogId);
                             using (SQLiteDataReader read = Command.ExecuteReader())
                             {
                                 while (read.Read())
                                 {
-                                    Counter += 1;
-                                    NextEvent = new RemoteVendorEvent();
-                                    NextEvent.Id = read.GetInt32(0);
-                                    NextEvent.UserId = read.GetInt32(1);
+                                    counter += 1;
+                                    var nextEvent = new RemoteVendorEvent();
+                                    nextEvent.Id = read.GetInt32(0);
+                                    nextEvent.UserId = read.GetInt32(1);
                                     if (read.IsDBNull(2) == true)
                                     {
-                                        NextEvent.VoucherId = null;
+                                        nextEvent.VoucherId = null;
                                     }
                                     else
                                     {
-                                        NextEvent.VoucherId = read.GetInt32(2);
+                                        nextEvent.VoucherId = read.GetInt32(2);
                                     }
-                                    NextEvent.EventDate = (DateTime)read.GetDateTime(3);
-                                    NextEvent.EventType = (VendorEvent.VendorEventType)Enum.Parse(typeof(VendorEvent.VendorEventType), read.GetValue(4).ToString());
-                                    NextEvent.VendorId = Globals.SessionData.Credentials.Payload.Vendor.id;
-                                    EventList.Add(NextEvent);
-                                    if (Counter == 1000)
-                                    { //Send logs in pages of 1000
-                                        LastVendorEventIdSynced = new RemoteVendorEventResponse();
-                                        bool EventPostResult = RESTRequest<List<RemoteVendorEvent>, RemoteVendorEventResponse>(EventList, ref LastVendorEventIdSynced, "/api/vendorevents/");
-                                        Counter = 0;
-                                        EventList = new List<RemoteVendorEvent>();
+                                    nextEvent.EventDate = read.GetDateTime(3);
+                                    nextEvent.EventType = (VendorEvent.VendorEventType)Enum.Parse(typeof(VendorEvent.VendorEventType), read.GetValue(4).ToString());
+                                    nextEvent.VendorId = Globals.SessionData.Credentials.Payload.Vendor.id;
+                                    eventList.Add(nextEvent);
+
+                                    if (counter == uploadPageSize)
+                                    {
+                                        var response = new RemoteVendorEventResponse();
+                                        if (RESTRequest(eventList, ref response, "/api/vendorevents/"))
+                                        {
+                                            counter = 0;
+                                            eventList.Clear();
+                                        }
+                                        else
+                                        {
+                                            uploadFailed = true;
+                                            break;
+                                        }
                                     }
                                 }
-                                if (Counter > 0)
-                                { //Left over logs not synced in a 100 item page
-                                    LastVendorEventIdSynced = new RemoteVendorEventResponse();
-                                    bool EventPostResult = RESTRequest<List<RemoteVendorEvent>, RemoteVendorEventResponse>(EventList, ref LastVendorEventIdSynced, "/api/vendorevents/");
+                                if (counter > 0)
+                                {
+                                    var response = new RemoteVendorEventResponse();
+                                    if (! RESTRequest(eventList, ref response, "/api/vendorevents/"))
+                                    {
+                                        uploadFailed = true;
+                                    }
                                 }
                             }
                         }
                     }
-                    else if (LastSyncedLogID > LastRecordedLogId)
-                    { //Server logs are newer than local logs, indicating loss of local database - resync entire table
-                        DBExecuteNonQuery(conn, "DELETE FROM Logs");
-                        Page<VendorEvent> EventPage;
-                        int TotalPages = 1;
-                        for (int PageNumber = 1; PageNumber <= TotalPages; PageNumber++)
+
+                    lock (Globals.LogUploadThreadLock)
+                    {
+                        while (! Globals.LogUploadThreadCancelled && ! Globals.UploadNewLogs)
                         {
-                            EventPage = new Page<VendorEvent>();
-                            bool EventGetResult = RESTRequest<Page<VendorEvent>>(ref EventPage, String.Format("/api/vendorevents/?page={0}&pagesize=1000", PageNumber));
-                            if (TotalPages == 1)
-                            { //Number of pages is sent with first page, so update on the fly
-                                TotalPages = EventPage.NumPages;
-                            }
-                            lock (Globals.DBWriteLock)
+                            Monitor.Wait(Globals.LogUploadThreadLock, uploadFailed ? retryInterval : Timeout.Infinite);
+                            if (uploadFailed)
                             {
-                                using (var trans = conn.BeginTransaction())
-                                {
-                                    var Sql = "INSERT INTO Logs (Id, UserId, VoucherId, EventDate, EventType, Retry) VALUES (@id, @userid, @voucherid, @eventdate, @eventtype, @retry)";
-                                    using (var cmd = new SQLiteCommand(Sql, conn, trans))
-                                    {
-                                        foreach (VendorEvent Event in EventPage.Items)
-                                        {
-                                            if (Event.RemoteId != null) //Only interested in downloading locally generated logs
-                                            {
-                                                cmd.Parameters.Clear();
-                                                cmd.Parameters.AddWithValue("@id", Event.RemoteId);
-                                                cmd.Parameters.AddWithValue("@userid", Event.UserId);
-                                                cmd.Parameters.AddWithValue("@voucherid", Event.VoucherId);
-                                                cmd.Parameters.AddWithValue("@eventdate", Event.EventDate.UtcDateTime);
-                                                cmd.Parameters.AddWithValue("@eventtype", Event.EventType);
-                                                cmd.Parameters.AddWithValue("@retry", Event.Retry);
-                                                cmd.ExecuteNonQuery();
-                                            }
-                                        }
-                                    }
-                                    trans.Commit();
-                                }
+                                break;
                             }
                         }
+                        Globals.UploadNewLogs = false;
+                        cancelled = Globals.LogUploadThreadCancelled;
                     }
                 }
             }
-            return true;
         }
 
-        public static void TriggerLogSync()
+        public static void TriggerLogUpload()
         {
-            if (Globals.LogSyncThread == null)
+            if (Globals.LogUploadThread == null)
+            {
+                Globals.LogUploadThread = new Thread(() => LogUploadWorker());
+                Globals.LogUploadThread.Start();
+            }
+            else
             {
-                Globals.LogSyncThreadEvent = new EventWaitHandle(false, EventResetMode.AutoReset);
-                Globals.LogSyncThread = new Thread(() => SyncLogsWorker());
-                Globals.LogSyncThread.Start();
+                lock (Globals.LogUploadThreadLock)
+                {
+                    Globals.UploadNewLogs = true;
+                    Monitor.Pulse(Globals.LogUploadThreadLock);
+                }
             }
-            Globals.LogSyncThreadEvent.Set();
         }
 
         public static void LogBulkEvents(SQLiteConnection conn, List<EventLog> EventLogs)
@@ -761,7 +888,7 @@ namespace BulkPrinting
 
             if (Globals.SessionMode == SessionModes.Online)
             {
-                TriggerLogSync();
+                TriggerLogUpload();
             }
         }
 
@@ -777,7 +904,7 @@ namespace BulkPrinting
                 new SQLiteParameter("@retry", Retry));
             if (Globals.SessionMode == SessionModes.Online)
             {
-                TriggerLogSync();
+                TriggerLogUpload();
             }
         }