SP-149 - when logging execution and execution-model, ensure that all available details are logged.

Author: ChintanRaval

rdl/data_load_tracking/DataLoadTrackerRepository.py

@@ -53,7 +53,7 @@ def complete_execution(self, execution_id, total_number_of_models,
         current_execution.rows_processed = total_rows_processed
         current_execution.batches_processed = total_batches_processed
         session.commit()
-        self.logger.info(current_execution)
+        self.logger.info(f'Completed {current_execution}')
         session.close()
         return total_rows_processed
 

rdl/entities/execution_entity.py

@@ -23,16 +23,35 @@ class ExecutionEntity(Base):
     models_processed = Column(Integer, nullable=True)
 
     def __str__(self):
-        if self.status == Constants.ExecutionStatus.STARTED:
-            return f"Started Execution ID: {self.execution_id} at {self.started_on}"
-
-        total_execution_seconds = self.execution_time_s
-        execution_hours = total_execution_seconds // 3600
-        execution_minutes = (total_execution_seconds // 60) % 60
-        execution_seconds = total_execution_seconds % 60
-
-        return f"Completed Execution ID: {self.execution_id}" \
-            f"; Models Processed: {self.models_processed:,}" \
-            f"; Rows Processed: {self.rows_processed:,}" \
-            f"; Execution Time: {execution_hours}h {execution_minutes}m {execution_seconds}s" \
-            f"; Average rows processed per second: {(self.rows_processed//max(total_execution_seconds, 1)):,}."
+        execution_time_str = None
+        rows_per_second = None
+
+        if self.execution_time_s:
+            total_execution_seconds = self.execution_time_s
+
+            execution_hours = total_execution_seconds // 3600
+            execution_minutes = (total_execution_seconds // 60) % 60
+            execution_seconds = total_execution_seconds % 60
+            execution_time_str = f'{execution_hours}h {execution_minutes}m {execution_seconds}s'
+
+            if self.rows_processed:
+                rows_per_second = (self.rows_processed//max(total_execution_seconds, 1))
+
+        return 'Execution ID: {exec_id}; ' \
+               'Status: {status}; ' \
+               'Started on: {started}; ' \
+               'Completed on: {completed}; ' \
+               'Execution time: {exec_time}; ' \
+               'Models processed: {models}; ' \
+               'Batches processed: {batches};' \
+               'Rows processed: {rows}; ' \
+               'Average rows processed per second: {rows_per_second};'.format(
+                exec_id=self.execution_id,
+                status=self.status,
+                started=self.started_on.isoformat(),
+                completed=self.completed_on.isoformat() if self.completed_on else '',
+                exec_time=execution_time_str if self.execution_time_str else '',
+                models=f'{self.models_processed:,}' if self.models_processed else '',
+                batches=f'{self.batches_processed:,}' if self.batches_processed else '',
+                rows=f'{self.rows_processed:,}' if self.rows_processed else '',
+                rows_per_second=f'{rows_per_second:,}' if rows_per_second else '')

rdl/entities/execution_model_entity.py

@@ -36,12 +36,32 @@ class ExecutionModelEntity(Base):
     failure_reason = Column(String(1000), nullable=True)
 
     def __str__(self):
-        load_type = 'FULL' if self.is_full_refresh else f"INCREMENTAL from " \
-                                                        f"version '{self.last_sync_version}' " \
-                                                        f"to '{self.sync_version}'"
-
-        execution_tims_s = max(self.execution_time_ms // 1000, 1)
-        rows_per_second = self.rows_processed / execution_tims_s
-        return f"Rows: {self.rows_processed}, " \
-               f"Load type: {load_type}, " \
-               f"Total Execution Time: {execution_tims_s}s @ {rows_per_second:.2f} rows per second "
+        load_type = f'FULL ({self.full_refresh_reason})' if self.is_full_refresh else \
+            f"INCREMENTAL from version '{self.last_sync_version}' to '{self.sync_version}'"
+        execution_time_s = None
+        rows_per_second = None
+
+        if self.execution_time_ms:
+            execution_time_s = max(self.execution_time_ms // 1000, 1)
+
+            if self.rows_processed:
+                rows_per_second = self.rows_processed / execution_time_s
+
+        return 'Model: {model}; ' \
+               'Load type: {load_type}; ' \
+               'Status: {status}; ' \
+               'Started on: {started}; ' \
+               'Completed on: {completed}; ' \
+               'Execution time: {exec_time}; ' \
+               'Batches processed: {batches}; ' \
+               'Rows processed: {rows}; ' \
+               'Average rows processed per second: {rows_per_second};'.format(
+                model=self.model_name,
+                load_type=load_type,
+                status=self.status,
+                started=self.started_on.isoformat(),
+                completed=self.completed_on.isoformat() if self.completed_on else '',
+                exec_time=f'{execution_time_s}s' if execution_time_s else '',
+                batches=f'{self.batches_processed:,}' if self.batches_processed else '',
+                rows=f'{self.rows_processed:,}' if self.rows_processed else '',
+                rows_per_second=f'{rows_per_second:,}' if rows_per_second else '')