From 122196fc6450b7834a3908a586b1fbd76b87b217 Mon Sep 17 00:00:00 2001
From: Jorrit Schaap <schaap@astron.nl>
Date: Tue, 23 Jul 2019 12:07:23 +0200
Subject: [PATCH] SW-776: logging, and less wait time.

---
 .../lib/webservice.py                         | 22 +++++++++----------
 1 file changed, 10 insertions(+), 12 deletions(-)

diff --git a/SAS/ResourceAssignment/ResourceAssignmentEditor/lib/webservice.py b/SAS/ResourceAssignment/ResourceAssignmentEditor/lib/webservice.py
index 099fb24843b..2beceb3390b 100755
--- a/SAS/ResourceAssignment/ResourceAssignmentEditor/lib/webservice.py
+++ b/SAS/ResourceAssignment/ResourceAssignmentEditor/lib/webservice.py
@@ -28,7 +28,7 @@ import time
 from optparse import OptionParser
 from threading import Condition, Lock, current_thread, Thread
 import _strptime
-from datetime import datetime
+from datetime import datetime, timedelta
 from json import loads as json_loads
 import time
 import logging
@@ -485,12 +485,7 @@ def putTask(task_id):
                     otdbrpc.taskSetStatus(task['otdb_id'], updatedTask['status'])
 
                     #we expect the status in otdb/radb to eventually become what we asked for...
-                    expected_statuses = set([updatedTask['status']])
-
-                    #except for the prescheduled status, because then the resource assigner tries
-                    #to schedule the task, and it will end up in either 'scheduled', 'conflict', 'error' state.
-                    if updatedTask['status'] == 'prescheduled':
-                        expected_statuses = set(['scheduled', 'conflict', 'error'])
+                    expected_status = updatedTask['status']
 
                     #block until radb and mom task status are equal to the expected_statuses (with timeout)
                     start_wait = datetime.utcnow()
@@ -500,21 +495,24 @@ def putTask(task_id):
                         otdb_status = otdbrpc.taskGetStatus(task['otdb_id'])
 
                         logger.info('waiting for otdb/radb task status to be in [%s].... otdb:%s radb:%s',
-                                    ', '.join(expected_statuses), otdb_status, task['status'])
+                                    expected_status, otdb_status, task['status'])
 
-                        if (task['status'] in expected_statuses and
-                            otdb_status in expected_statuses):
+                        if (task['status'] == expected_status and otdb_status == expected_status):
+                            logger.info('otdb/radb task status now has the expected status %s otdb:%s radb:%s',
+                                        expected_status, otdb_status, task['status'])
                             break
 
                         if datetime.utcnow() - start_wait > timedelta(seconds=10):
+                            logger.warning('timeout while waiting for otdb/radb task status to get the expected status %s otdb:%s radb:%s',
+                                        expected_status, otdb_status, task['status'])
                             break
 
-                        time.sleep(0.2)
+                        time.sleep(0.1)
                 except RPCException as e:
                     if 'does not exist' in str(e):
                         # task does not exist (anymore) in otdb
                         #so remove it from radb as well (with cascading deletes on specification)
-                        logger.warn('task with otdb_id %s does not exist anymore in OTDB. removing task radb_id %s from radb', task['otdb_id'], task['id'])
+                        logger.warning('task with otdb_id %s does not exist anymore in OTDB. removing task radb_id %s from radb', task['otdb_id'], task['id'])
                         radb().deleteSpecification(task['specification_id'])
 
             if 'data_pinned' in updatedTask:
-- 
GitLab