Log the time difference of create time and post time (#240)

* Log the time difference of create time and post time

* Moved the time difference update to client.py and added tearDown method to print

* Removed the time_difference variable

tests/client.py

@@ -1,6 +1,7 @@
 import datetime
 import random
 import uuid
+import sys
 
 import backoff
 import requests
@@ -15,6 +16,7 @@ class TestClient():
     START_DATE_FORMAT = "%Y-%m-%dT00:00:00Z"
     V3_DEALS_PROPERTY_PREFIXES = {'hs_date_entered', 'hs_date_exited', 'hs_time_in'}
     BOOKMARK_DATE_FORMAT = '%Y-%m-%dT%H:%M:%S.%fZ'
+    record_create_times = {}
 
     ##########################################################################
     ### CORE METHODS
@@ -758,7 +760,10 @@ def create(self, stream, company_ids=[], subscriptions=[], times=1):
         elif stream == 'workflows':
             return self.create_workflows()
         elif stream == 'contacts':
-            return self.create_contacts()
+            if stream not in self.record_create_times.keys():
+                self.record_create_times[stream]=[]
+            records =  self.create_contacts()
+            return records
         elif stream == 'deal_pipelines':
             return self.create_deal_pipelines()
         elif stream == 'email_events':
@@ -822,6 +827,10 @@ def create_contacts(self):
             ]
         }
 
+        # Get the current time in seconds
+        date = datetime.datetime.utcnow()
+        seconds = datetime.datetime.timestamp(date)
+
         # generate a contacts record
         response = self.post(url, data)
         records = [response]
@@ -830,9 +839,11 @@ def create_contacts(self):
         params = {'includeVersion': True}
         get_resp = self.get(get_url, params=params)
 
+        #Get the created time and the difference to monitor the time difference - tdl-20939
         created_time = get_resp.get('properties').get('createdate').get('value')
         ts=int(created_time)/1000
         LOGGER.info("Created Time  %s", datetime.datetime.utcfromtimestamp(ts))
+        self.record_create_times["contacts"].append(ts-seconds)
 
         converted_versionTimestamp = self.BaseTest.datetime_from_timestamp(
             get_resp['versionTimestamp'] / 1000, self.BOOKMARK_DATE_FORMAT
@@ -1708,3 +1719,9 @@ def __init__(self, start_date=''):
                 delete_count = int(max_record_count / 2)
                 self.cleanup(stream, records, delete_count)
                 LOGGER.info(f"TEST CLIENT | {delete_count} records deleted from {stream}")
+
+    def print_histogram_data(self):
+        for stream, recorded_times in self.record_create_times.items():
+            LOGGER.info("Time taken for stream {} is total: {}, avg: {}, minimum: {}, maximum: {}".
+                    format(stream, sum(recorded_times), sum(recorded_times)/len(recorded_times), min(recorded_times), max(recorded_times) ))
+

tests/test_hubspot_bookmarks.py

@@ -8,12 +8,12 @@
 
 from base import HubspotBaseTest
 from client import TestClient
+from tap_tester import LOGGER
 
 
 STREAMS_WITHOUT_UPDATES = {'email_events', 'contacts_by_company', 'workflows'}
 STREAMS_WITHOUT_CREATES = {'campaigns', 'owners'}
 
-
 class TestHubspotBookmarks(HubspotBaseTest):
     """Ensure tap replicates new and upated records based on the replication method of a given stream.
 
@@ -30,7 +30,6 @@ def name():
 
     def streams_to_test(self):
         """expected streams minus the streams not under test"""
-
         expected_streams = self.expected_streams().difference(STREAMS_WITHOUT_CREATES)
 
         return expected_streams.difference({
@@ -48,24 +47,32 @@ def setUp(self):
         self.test_client = TestClient(self.get_properties()['start_date'])
 
     def create_test_data(self, expected_streams):
+        """
+        Creating more records(5) instead of 3 to get the update time to build the histogram - tdl-20939
+        Excluding workflows as it results in assertion failures with expected_pk and sync_pk at line#261
+        """
 
         self.expected_records = {stream: []
                                  for stream in expected_streams}
-
         for stream in expected_streams - {'contacts_by_company'}:
-            if stream == 'email_events':
-                email_records = self.test_client.create(stream, times=3)
+            if stream == 'contacts': 
+                self.times=10
+            else:
+                self.times =3
+
+            if stream in 'email_events':
+                email_records = self.test_client.create(stream, self.times)
                 self.expected_records['email_events'] += email_records
             else:
                 # create records, one will be updated between syncs
-                for _ in range(3):
+                for _ in range(self.times):
                     record = self.test_client.create(stream)
                     self.expected_records[stream] += record
 
         if 'contacts_by_company' in expected_streams:  # do last
             company_ids = [record['companyId'] for record in self.expected_records['companies']]
             contact_records = self.expected_records['contacts']
-            for i in range(3):
+            for i in range(self.times):
                 record = self.test_client.create_contacts_by_company(
                     company_ids=company_ids, contact_records=contact_records
                 )
@@ -246,3 +253,7 @@ def test_run(self):
                               'email_events'}: # BUG | https://jira.talendforge.org/browse/TDL-15706
                     continue  # skipping failures
                 self.assertTrue(any([expected_pk in sync_2_pks for expected_pk in expected_sync_1_pks]))
+
+    def tearDown(self):
+        """Print histogram of Create time difference - tdl-20939"""
+        self.test_client.print_histogram_data()