Merge pull request #21 from Local-Connectivity-Lab/ticket-797

Ticket 797 -  Fix locking problem when handling exception during ticket sync

Author: philion

cog_tickets.py

@@ -193,18 +193,30 @@ async def create_new_ticket(self, ctx: discord.ApplicationContext, title:str):
     async def thread(self, ctx: discord.ApplicationContext, ticket_id:int):
         ticket = self.redmine.get_ticket(ticket_id)
         if ticket:
+            ticket_link = self.bot.formatter.format_link(ticket)
+
+            # check if sync data exists for a different channel
+            synced = ticket.get_sync_record()
+            if synced and synced.channel_id != ctx.channel_id:
+                thread = self.bot.get_channel(synced.channel_id)
+                if thread:
+                    await ctx.respond(f"Ticket {ticket_link} already synced with {thread.jump_url}")
+                    return # stop processing
+                else:
+                    log.info(f"Ticket {ticket_id} synced with unknown thread ID {synced.channel_id}. Recovering.")
+                    # delete the sync record
+                    self.redmine.ticket_mgr.remove_sync_record(synced)
+                    # fall thru to create thread and sync
+
             # create the thread...
             thread = await self.create_thread(ticket, ctx)
 
             # update the discord flag on tickets, add a note with url of thread; thread.jump_url
-            # TODO message templates
             note = f"Created Discord thread: {thread.name}: {thread.jump_url}"
             user = self.redmine.user_mgr.find_discord_user(ctx.user.name)
-            log.debug(f">>> found {user} for {ctx.user.name}")
             self.redmine.enable_discord_sync(ticket.id, user, note)
 
             # ticket-614: add ticket link to thread response
-            ticket_link = self.bot.formatter.format_link(ticket)
             await ctx.respond(f"Created new thread {thread.jump_url} for ticket {ticket_link}")
         else:
             await ctx.respond(f"ERROR: Unkown ticket ID: {ticket_id}")

docs/netbot-usage.md

@@ -153,12 +153,22 @@ Will create a new ticket with the title "Upgrade the server to the v1.62 LTS", a
 ### `/ticket thread [ticket-id]` - Create a Discord thread for a ticket
 
 Create a new discord thread from an existing ticket *ticket-id*, using the ticket title as the thread title. The thread is created in the channel it is invoked in, and all notes from the existing ticket are copied into the thread.
-
 ```
 /ticket thread 787
 ```
 will create a new thread for ticket 787 in the current Discord channel.
 
+If a Discord thread has already been created for that ticket, a note with a link to that thread will be displayed.
+
+If an existing *ticket thread* has been deleted, it can be recreated in any channel with the same command.
+
+To move a *ticket thread* to a new channel:
+1. Delete the existing *ticket thread* using the Discord UI. NOTE: The relevant comments are already synced to Redmine.
+2. Create the *ticket thread* in the new channel with (you guessed it): `/thread ticket [id]`
+
+`/ticket thread` is designed to be forgiving: If no *ticket thread* exists or syncdata is old, incomplete or invalid, a new valid *ticket thread* will be created and synchroized. Otherwise, an existing *ticket thread* is associated with that ticket ID and a link to it will be displayed.
+
+
 ### `/ticket assign [ticket-id]` - Assign a ticket
 
 Assign ticket *ticket-id* to yourself (the invoking user).

model.py

@@ -368,34 +368,38 @@ def __str__(self):
         return f"#{self.id:04d}  {self.status.name:<11}  {self.priority.name:<6}  {self.assigned:<20}  {self.subject}"
 
 
-    def get_sync_record(self, expected_channel: int = 0) -> synctime.SyncRecord | None:
+    def get_sync_record(self) -> synctime.SyncRecord | None:
         # Parse custom_field into datetime
         # lookup field by name
         token = self.get_custom_field(SYNC_FIELD_NAME)
         if token:
             record = synctime.SyncRecord.from_token(self.id, token)
             log.debug(f"created sync_rec from token: {record}")
-            if record:
-                # check channel
-                if record.channel_id == 0:
-                    # no valid channel set in sync data, assume lagacy
-                    record.channel_id = expected_channel
-                    # update the record in redmine after adding the channel info
-                    # self.update_sync_record(record) REALLY needed? should be handled when token created
-                    return record
-                elif record.channel_id != expected_channel:
-                    log.debug(f"channel mismatch: rec={record.channel_id} =/= {expected_channel}, token={token}")
-                    return None
-                else:
-                    return record
+            return record
+
+
+    def validate_sync_record(self, expected_channel: int = 0) -> synctime.SyncRecord | None:
+        # Parse custom_field into datetime
+        # lookup field by name
+        record = self.get_sync_record()
+        if record:
+            # check channel
+            if record.channel_id == 0:
+                # no valid channel set in sync data, assume lagacy
+                record.channel_id = expected_channel
+                # update the record in redmine after adding the channel info
+                # self.update_sync_record(record) REALLY needed? should be handled when token created
+                return record
+            elif record.channel_id != expected_channel:
+                log.debug(f"channel mismatch: rec={record.channel_id} =/= {expected_channel}")
+                return None
+            else:
+                return record
         else:
             # no token implies not-yet-initialized
             record = synctime.SyncRecord(self.id, expected_channel, synctime.epoch_datetime())
-            # apply the new sync record back to redmine
-            # self.update_sync_record(record) same REALLY as above ^^^^
             log.debug(f"created new sync record, none found: {record}")
             return record
-        return None
 
 
     def get_notes(self, since:dt.datetime|None=None) -> list[TicketNote]:

netbot.py

@@ -171,51 +171,52 @@ async def synchronize_ticket(self, ticket, thread:discord.Thread) -> bool:
         # get the self lock before checking the lock collection
         async with self.lock:
             if ticket.id in self.ticket_locks:
-                log.debug(f"ticket #{ticket.id} locked, skipping")
+                log.info(f"ticket #{ticket.id} locked, skipping")
                 return False # locked
             else:
                 # create lock flag
                 self.ticket_locks[ticket.id] = True
-                log.debug(f"thread lock set, id: {ticket.id}, thread: {thread}")
-
-        # start of the process, will become "last update"
-        sync_start = synctime.now()
-        sync_rec = ticket.get_sync_record(expected_channel=thread.id)
-
-        if sync_rec:
-            log.debug(f"sync record: {sync_rec}")
-
-            # get the new notes from the redmine ticket
-            redmine_notes = self.gather_redmine_notes(ticket, sync_rec)
-            for note in redmine_notes:
-                # Write the note to the discord thread
-                dirty_flag = True
-                await thread.send(self.formatter.format_discord_note(note))
-            log.debug(f"synced {len(redmine_notes)} notes from #{ticket.id} --> {thread}")
-
-            # get the new notes from discord
-            discord_notes = await self.gather_discord_notes(thread, sync_rec)
-            for message in discord_notes:
-                dirty_flag = True
-                self.append_redmine_note(ticket, message)
-
-            log.debug(f"synced {len(discord_notes)} notes from {thread} -> #{ticket.id}")
-
-            # update the SYNC timestamp
-            # only update if something has changed
-            if dirty_flag:
-                sync_rec.last_sync = sync_start
-                self.redmine.update_sync_record(sync_rec)
-
+                log.debug(f"LOCK thread - id: {ticket.id}, thread: {thread}")
+
+        try:
+            # start of the process, will become "last update"
+            sync_start = synctime.now()
+            sync_rec = ticket.validate_sync_record(expected_channel=thread.id)
+
+            if sync_rec:
+                log.debug(f"sync record: {sync_rec}")
+
+                # get the new notes from the redmine ticket
+                redmine_notes = self.gather_redmine_notes(ticket, sync_rec)
+                for note in redmine_notes:
+                    # Write the note to the discord thread
+                    dirty_flag = True
+                    await thread.send(self.formatter.format_discord_note(note))
+                log.debug(f"synced {len(redmine_notes)} notes from #{ticket.id} --> {thread}")
+
+                # get the new notes from discord
+                discord_notes = await self.gather_discord_notes(thread, sync_rec)
+                for message in discord_notes:
+                    dirty_flag = True
+                    self.append_redmine_note(ticket, message)
+
+                log.debug(f"synced {len(discord_notes)} notes from {thread} -> #{ticket.id}")
+
+                # update the SYNC timestamp
+                # only update if something has changed
+                if dirty_flag:
+                    sync_rec.last_sync = sync_start
+                    self.redmine.update_sync_record(sync_rec)
+
+                log.info(f"DONE sync {ticket.id} <-> {thread.name}, took {synctime.age_str(sync_start)}")
+                return True # processed as expected
+            else:
+                log.info(f"empty sync_rec for channel={thread.id}, assuming mismatch and skipping")
+                return False # not found
+        finally:
             # unset the sync lock
             del self.ticket_locks[ticket.id]
-
-            log.info(f"DONE sync {ticket.id} <-> {thread.name}, took {synctime.age_str(sync_start)}")
-            return True # processed as expected
-        else:
-            log.debug(f"empty sync_rec for channel={thread.id}, assuming mismatch and skipping")
-            return False # not found
-
+            log.debug(f"UNLOCK thread - id: {ticket.id}, thread: {thread}")
 
     def get_channel_by_name(self, channel_name: str):
         for channel in self.get_all_channels():
@@ -245,6 +246,25 @@ async def sync_thread(self, thread:discord.Thread):
         ticket = self.redmine.get_ticket(ticket_id, include_journals=True)
         if ticket:
             completed = await self.synchronize_ticket(ticket, thread)
+            # note: synchronize_ticket returns True only when successfully completing a sync
+            # it can fail due to: lock, missing or mismatched sync record, network, remote service.
+            # all these are ignored due to the lock.... not the best option.
+            # need to think deeper about the pre-condition and desired outcome:
+            # - What are the possible states and what causes them?
+            # - Can all unexpected states be recovered?
+            # - If not, what are the edge conditions and what data is needed to recover?
+            # - (the answer is usually: this data conflict with old values. align to new values or old?)
+            # reasonable outcomes are:
+            # - temporary failure, will try again: self-resolves due to job-nature (lock, network, http)
+            # - user input error: flag error in response, expect re-entry with valid input. OPPORTUNITY: "did you mean?"
+            # - missing sync, reasonable recovery: create new.
+            # - missmatch sync implies human by-hand changes in thread names/locations or bad code.
+            #     as "bad code" is not a "reasonable" outcome, it should be fixed, so the only outcomes are:
+            # - troubleshoot if it's a bug or
+            # - note out-of-sync unexpected results: thread-name or whatever.
+            # In this situation, "locked" is not unexpected (per se) but channel-mismatch is.
+            # Implies a "user-error" exception to report back to the user specific conditions.
+            # NetbotException is general, NetbotUserException
             if completed:
                 return ticket
             else:
@@ -272,12 +292,10 @@ async def sync_all_threads(self):
                     if ticket:
                         # successful sync
                         log.debug(f"SYNC complete for ticket #{ticket.id} to {thread.name}")
-                    #else:
-                        #log.debug(f"no ticket found for {thread.name}")
                 except NetbotException as ex:
                     # ticket is locked.
                     # skip gracefully
-                    log.debug(f"Ticket locked, sync in progress: {thread}: {ex}")
+                    log.debug(str(ex))
                 except Exception:
                     log.exception(f"Error syncing {thread}")
 
@@ -290,7 +308,7 @@ async def expiration_notification(self, ticket: Ticket) -> None:
         """
 
         # first, check the syncdata.
-        sync = ticket.get_sync_record()
+        sync = ticket.validate_sync_record()
         if sync and sync.channel_id > 0:
             notification = self.bot.formatter.format_expiration_notification(ticket)
             thread: discord.Thread = self.bot.get_channel(sync.channel_id)

test_synctime.py

@@ -24,7 +24,7 @@ def test_redmine_times(self):
         ticket = self.create_test_ticket()
 
         test_channel = 4321
-        sync_rec = ticket.get_sync_record(expected_channel=test_channel)
+        sync_rec = ticket.validate_sync_record(expected_channel=test_channel)
         self.assertIsNotNone(sync_rec)
         self.assertEqual(sync_rec.ticket_id, ticket.id)
         self.assertEqual(sync_rec.channel_id, test_channel)
@@ -35,7 +35,7 @@ def test_redmine_times(self):
 
         # refetch ticket
         ticket2 = self.redmine.get_ticket(ticket.id)
-        sync_rec2 = ticket2.get_sync_record(expected_channel=1111) # NOT the test_channel
+        sync_rec2 = ticket2.validate_sync_record(expected_channel=1111) # NOT the test_channel
         log.info(f"ticket2 updated={ticket2.updated_on}, {synctime.age_str(ticket2.updated_on)} ago, channel: {sync_rec.channel_id}")
 
         self.assertIsNone(sync_rec2)

tickets.py

@@ -9,7 +9,7 @@
 
 
 
-from model import TO_CC_FIELD_NAME, User, Message, NamedId, Team, Ticket, TicketNote, TicketsResult
+from model import TO_CC_FIELD_NAME, User, Message, NamedId, Team, Ticket, TicketNote, TicketsResult, SYNC_FIELD_NAME
 from session import RedmineSession, RedmineException
 import synctime
 
@@ -468,12 +468,27 @@ def update_sync_record(self, record:synctime.SyncRecord):
         log.debug(f"Updating sync record in redmine: {record}")
         fields = {
             "custom_fields": [
-                { "id": 4, "value": record.token_str() } # cf_4, custom field syncdata, #TODO search for it
+                { "id": 4, "value": record.token_str() } # cf_4, custom field syncdata, #TODO see below
             ]
         }
         self.update(record.ticket_id, fields)
 
 
+    def remove_sync_record(self, record:synctime.SyncRecord):
+        field = self.custom_fields[SYNC_FIELD_NAME]
+        if field:
+            log.debug(f"Removing sync record in redmine: {record}")
+            fields = {
+                "custom_fields": [
+                    { "id": field.id, "value": "" }
+                ]
+            }
+            self.update(record.ticket_id, fields)
+            log.debug(f"Removed {SYNC_FIELD_NAME} from ticket {record.ticket_id}")
+        else:
+            log.error(f"Missing expected custom field: {SYNC_FIELD_NAME}")
+
+
     def get_updated_field(self, ticket) -> dt.datetime:
         return synctime.parse_str(ticket.updated_on)