From 652b1ff9aea395b2bc24004e0e0741631190ba26 Mon Sep 17 00:00:00 2001
From: Xavier Morel <xmo@odoo.com>
Date: Wed, 11 Jan 2023 14:32:39 +0100
Subject: [PATCH] [IMP] runbot_merge: more logging on synchronize

Was missing a logging message in the case where the current and sync'd
head are identical, which seems to occur from time to time but can
only be inferred (by seeing a sync event then nothing happening).

Add a logging warning (because it's a strange situation) in order to
explicitely note the issue.

Also make the sync logging messages more regular for clarity.

And add the delivery information (delivery id and user-agent) to event
log, so it's more possible to report issues to github.
---
 runbot_merge/controllers/__init__.py | 26 +++++++++++++++++++++-----
 1 file changed, 21 insertions(+), 5 deletions(-)

diff --git a/runbot_merge/controllers/__init__.py b/runbot_merge/controllers/__init__.py
index 7e134af3..8aa1342f 100644
--- a/runbot_merge/controllers/__init__.py
+++ b/runbot_merge/controllers/__init__.py
@@ -156,8 +156,16 @@ def handle_pr(env, event):
     if not branch:
         return "Not set up to care about {}:{}".format(r, b)
 
-
-    _logger.info("%s: %s#%s (%s) (by %s)", event['action'], repo.name, pr['number'], pr['title'].strip(), event['sender']['login'])
+    headers = request.httprequest.headers if request.httprequest else {}
+    _logger.info(
+        "%s: %s#%s (%s) (by %s, delivery %s by %s)",
+        event['action'],
+        repo.name, pr['number'],
+        pr['title'].strip(),
+        event['sender']['login'],
+        headers.get('X-Github-Delivery'),
+        headers.get('User-Agent'),
+     )
     if event['action'] == 'opened':
         author_name = pr['user']['login']
         author = env['res.partner'].search([('github_login', '=', author_name)], limit=1)
@@ -172,19 +180,27 @@ def handle_pr(env, event):
         return "Unknown PR {}:{}, scheduling fetch".format(repo.name, pr['number'])
     if event['action'] == 'synchronize':
         if pr_obj.head == pr['head']['sha']:
+            _logger.warning(
+                "PR %s sync %s -> %s => same head",
+                pr_obj.display_name,
+                pr_obj.head,
+                pr['head']['sha'],
+            )
             return 'No update to pr head'
 
         if pr_obj.state in ('closed', 'merged'):
-            _logger.error("Tentative sync to closed PR %s", pr_obj.display_name)
+            _logger.error("PR %s sync %s -> %s => failure (closed)", pr_obj.display_name, pr_obj.head, pr['head']['sha'])
             return "It's my understanding that closed/merged PRs don't get sync'd"
 
         if pr_obj.state == 'ready':
             pr_obj.unstage("updated by %s", event['sender']['login'])
 
         _logger.info(
-            "PR %s updated to %s by %s, resetting to 'open' and squash=%s",
+            "PR %s sync %s -> %s by %s => reset to 'open' and squash=%s",
             pr_obj.display_name,
-            pr['head']['sha'], event['sender']['login'],
+            pr_obj.head,
+            pr['head']['sha'],
+            event['sender']['login'],
             pr['commits'] == 1
         )