utPLSQL · jgebal · Mar 16, 2019 · Mar 7, 2019 · Mar 8, 2019 · Mar 14, 2019
diff --git a/.gitignore b/.gitignore
@@ -27,3 +27,4 @@ coverage.xml
 tfs_test_results.xml
 junit_test_results.xml
 test_results.xml
+*debug*.xml
diff --git a/docs/userguide/reporters.md b/docs/userguide/reporters.md
@@ -120,3 +120,46 @@ Details:
 # Coverage reporters
 
 utPLSQL comes with a set of build-in coverage reporters. Have a look into the [coverage documentation](coverage.md) to learn more about them.
+
+
+# Debug reporter
+
+The `ut_debug_reporter` provides a highly verbose output containing thorough details about framework and test execution.
+
+Use this reporter only when you need to investigate framework issues or raise a bug report to utPLSQL team.
+
+Usage of this reporter might have impact on performance of test-suite execution.
+
+Amongst others, reporter provides the following information:
+- framework version
+- database version
+- database OS
+- database, instance and session NLS settings
+- timing of each event
+- time between events logged
+- time from start of the run
+- stack trace
+- information about input parameters for the run including
+    - run paths
+    - source file mappings
+    - test file mappings
+    - coverage schemas
+    - coverage exclusions and inclusions
+    - client character set
+- information about every step of the run including
+    - every suite and context
+    - every before/after procedure
+    - every test
+    - every expectation and it's result
+
+Some of the information in debug log might be redundant.
+
+**Note:**
+>Some of the information in debug log may be sensitive. In particular:
+> - expectation results and messages (logged even for successful runs)
+> - test structure
+> - db object names
+> - etc.
+
+
+
diff --git a/source/api/ut_runner.pkb b/source/api/ut_runner.pkb
@@ -97,10 +97,21 @@ create or replace package body ut_runner is
     l_paths                 ut_varchar2_list := ut_varchar2_list();                 
   begin
     ut_event_manager.initialize();
+    if a_reporters is not empty then
+      for i in 1 .. a_reporters.count loop
+        ut_event_manager.add_listener( a_reporters(i) );
+      end loop;
+    else
+      ut_event_manager.add_listener( ut_documentation_reporter() );
+    end if;
+
+    ut_event_manager.trigger_event(ut_event_manager.gc_initialize);
+    ut_event_manager.trigger_event(ut_event_manager.gc_debug, ut_run_info());
+
     if a_paths is null or a_paths is empty or a_paths.count = 1 and a_paths(1) is null then
       l_paths := ut_varchar2_list(sys_context('userenv', 'current_schema'));
     else
-      for i in 1..a_paths.COUNT loop
+      for i in 1..a_paths.count loop
         l_paths := l_paths multiset union ut_utils.string_to_table(a_string => a_paths(i),a_delimiter => ',');
       end loop;
     end if;
@@ -110,13 +121,6 @@ create or replace package body ut_runner is
       ut_utils.save_dbms_output_to_cache();
 
       ut_console_reporter_base.set_color_enabled(a_color_console);
-      if a_reporters is null or a_reporters.count = 0 then
-        ut_event_manager.add_listener(ut_documentation_reporter());
-      else
-        for i in 1 .. a_reporters.count loop
-          ut_event_manager.add_listener(a_reporters(i));
-        end loop;
-      end if;
 
       if a_coverage_schemes is not empty then
         l_coverage_schema_names := ut_utils.convert_collection(a_coverage_schemes);
@@ -143,8 +147,6 @@ create or replace package body ut_runner is
         a_client_character_set
       );
 
-      ut_event_manager.trigger_event(ut_event_manager.gc_initialize, l_run);
-
       ut_suite_manager.configure_execution_by_path(l_paths, l_run.items);
       if a_force_manual_rollback then
         l_run.set_rollback_type( a_rollback_type => ut_utils.gc_rollback_manual, a_force => true );

diff --git a/source/core/coverage/ut_coverage.pkb b/source/core/coverage/ut_coverage.pkb
@@ -131,8 +131,8 @@ create or replace package body ut_coverage is
 
     if not ut_coverage_helper.is_tmp_table_populated() or is_develop_mode() then
       ut_coverage_helper.cleanup_tmp_table();
-
-      l_cov_sources_crsr := get_cov_sources_cursor(a_coverage_options,a_sql);
+      ut_event_manager.trigger_event(ut_event_manager.gc_debug, ut_key_anyvalues().put('a_sql',a_sql) );
+      l_cov_sources_crsr := get_cov_sources_cursor(a_coverage_options, a_sql);
 
       loop
         fetch l_cov_sources_crsr bulk collect into l_cov_sources_data limit 10000;
@@ -209,48 +209,50 @@ create or replace package body ut_coverage is
     l_line_no                binary_integer;
   begin
     --prepare global temp table with sources
+    ut_event_manager.trigger_event('about to populate coverage temp table');
     populate_tmp_table(a_coverage_options, get_cov_sources_sql(a_coverage_options));
+    ut_event_manager.trigger_event('coverage temp table populated');
 
     -- Get raw data for both reporters, order is important as tmp table will skip headers and dont populate
     -- tmp table for block again.
     l_result_profiler_enrich:= ut_coverage_profiler.get_coverage_data( a_coverage_options, get_coverage_id(gc_proftab_coverage) );
-
-   -- If block coverage available we will use it.
-   $if dbms_db_version.version = 12 and dbms_db_version.release >= 2 or dbms_db_version.version > 12 $then
-    l_result_block := ut_coverage_block.get_coverage_data( a_coverage_options, get_coverage_id(gc_block_coverage) );
-
-    -- Enrich profiler results with some of the block results
-    l_object := l_result_profiler_enrich.objects.first;
-    while (l_object is not null)
-     loop
-
-      l_line_no := l_result_profiler_enrich.objects(l_object).lines.first;
-
-      -- to avoid no data found check if we got object in profiler
-      if l_result_block.objects.exists(l_object) then
-      while (l_line_no is not null)
-       loop         
-        -- To avoid no data check for object line
-        if l_result_block.objects(l_object).lines.exists(l_line_no) then
-         -- enrich line level stats
-         l_result_profiler_enrich.objects(l_object).lines(l_line_no).partcove := l_result_block.objects(l_object).lines(l_line_no).partcove;
-         l_result_profiler_enrich.objects(l_object).lines(l_line_no).covered_blocks := l_result_block.objects(l_object).lines(l_line_no).covered_blocks;
-         l_result_profiler_enrich.objects(l_object).lines(l_line_no).no_blocks := l_result_block.objects(l_object).lines(l_line_no).no_blocks;
-         -- enrich object level stats
-         l_result_profiler_enrich.objects(l_object).partcovered_lines :=  nvl(l_result_profiler_enrich.objects(l_object).partcovered_lines,0) + l_result_block.objects(l_object).lines(l_line_no).partcove;    
+    ut_event_manager.trigger_event('profiler coverage data retrieved');
+
+    -- If block coverage available we will use it.
+    $if dbms_db_version.version = 12 and dbms_db_version.release >= 2 or dbms_db_version.version > 12 $then
+      l_result_block := ut_coverage_block.get_coverage_data( a_coverage_options, get_coverage_id(gc_block_coverage) );
+      ut_event_manager.trigger_event('block coverage data retrieved');
+
+      -- Enrich profiler results with some of the block results
+      l_object := l_result_profiler_enrich.objects.first;
+      while (l_object is not null) loop
+
+        l_line_no := l_result_profiler_enrich.objects(l_object).lines.first;
+
+        -- to avoid no data found check if we got object in profiler
+        if l_result_block.objects.exists(l_object) then
+          while (l_line_no is not null) loop
+            -- To avoid no data check for object line
+            if l_result_block.objects(l_object).lines.exists(l_line_no) then
+             -- enrich line level stats
+             l_result_profiler_enrich.objects(l_object).lines(l_line_no).partcove := l_result_block.objects(l_object).lines(l_line_no).partcove;
+             l_result_profiler_enrich.objects(l_object).lines(l_line_no).covered_blocks := l_result_block.objects(l_object).lines(l_line_no).covered_blocks;
+             l_result_profiler_enrich.objects(l_object).lines(l_line_no).no_blocks := l_result_block.objects(l_object).lines(l_line_no).no_blocks;
+             -- enrich object level stats
+             l_result_profiler_enrich.objects(l_object).partcovered_lines :=  nvl(l_result_profiler_enrich.objects(l_object).partcovered_lines,0) + l_result_block.objects(l_object).lines(l_line_no).partcove;
+            end if;
+            --At the end go to next line
+            l_line_no := l_result_profiler_enrich.objects(l_object).lines.next(l_line_no);
+          end loop;
+          --total level stats enrich
+          l_result_profiler_enrich.partcovered_lines := nvl(l_result_profiler_enrich.partcovered_lines,0) + l_result_profiler_enrich.objects(l_object).partcovered_lines;
+          -- At the end go to next object
         end if;
-        --At the end go to next line
-        l_line_no := l_result_profiler_enrich.objects(l_object).lines.next(l_line_no);
-       end loop;
-       --total level stats enrich
-       l_result_profiler_enrich.partcovered_lines := nvl(l_result_profiler_enrich.partcovered_lines,0) + l_result_profiler_enrich.objects(l_object).partcovered_lines;
-      -- At the end go to next object
-     end if;
-
-     l_object := l_result_profiler_enrich.objects.next(l_object);
-
-     end loop;    
-    $end   
+
+        l_object := l_result_profiler_enrich.objects.next(l_object);
+      end loop;
+      ut_event_manager.trigger_event('coverage data combined');
+    $end
 
     return l_result_profiler_enrich;
   end get_coverage_data;  

diff --git a/source/core/events/ut_event_item.tps b/source/core/events/ut_event_item.tps
@@ -21,6 +21,5 @@ create or replace type ut_event_item authid current_user as object (
   * The true abstract type is ut_suite_item
   */
   self_type    varchar2(250 byte)
-
 ) not final not instantiable
 /
diff --git a/source/core/events/ut_event_manager.pkb b/source/core/events/ut_event_manager.pkb
@@ -57,15 +57,30 @@ create or replace package body ut_event_manager  as
     end if;
   end;
 
-  procedure trigger_event( a_event_name t_event_name, a_event_object ut_event_item ) is
-  begin
-    if a_event_name is not null and g_event_listeners_index.exists(a_event_name)
-    then
-      for listener_number in 1 .. g_event_listeners_index(a_event_name).count loop
-        g_listeners(listener_number).on_event(a_event_name, a_event_object);
+  procedure trigger_event( a_event_name t_event_name, a_event_object ut_event_item := null ) is
+
+    procedure trigger_listener_event(
+      a_listener_numbers t_listener_numbers,
+      a_event_name t_event_name,
+      a_event_object ut_event_item
+    ) is
+      l_listener_number t_listener_number := a_listener_numbers.first;
+    begin
+      while l_listener_number is not null loop
+        g_listeners(l_listener_number).on_event(a_event_name, a_event_object);
+        l_listener_number := a_listener_numbers.next(l_listener_number);
       end loop;
+    end;
+  begin
+    if a_event_name is not null then
+      if g_event_listeners_index.exists(gc_all) then
+        trigger_listener_event( g_event_listeners_index(gc_all), a_event_name, a_event_object );
+      end if;
+      if g_event_listeners_index.exists(a_event_name) then
+        trigger_listener_event( g_event_listeners_index(a_event_name), a_event_name, a_event_object );
+      end if;
       if a_event_name = ut_event_manager.gc_finalize then
-        dispose_listeners;
+        dispose_listeners();
       end if;
     end if;
   end;
@@ -78,7 +93,7 @@ create or replace package body ut_event_manager  as
   procedure add_events( a_event_names ut_varchar2_list, a_listener_pos binary_integer ) is
   begin
     for i in 1 .. a_event_names.count loop
-      add_event(a_event_names(i), a_listener_pos);
+      add_event( a_event_names(i), a_listener_pos );
     end loop;
   end;
 
@@ -98,10 +113,9 @@ create or replace package body ut_event_manager  as
     if a_listener is not null then
       l_event_names := a_listener.get_supported_events();
       if l_event_names is not empty then
-        add_events( l_event_names, add_listener(a_listener ) );
+        add_events( l_event_names, add_listener( a_listener ) );
       end if;
     end if;
-
   end;
 
 end;

diff --git a/source/core/events/ut_event_manager.pks b/source/core/events/ut_event_manager.pks
@@ -18,6 +18,11 @@ create or replace package ut_event_manager authid current_user as
   /* Constants: Event names */
   subtype t_event_name           is varchar2(250);
 
+    --capture all events
+  gc_all                         constant t_event_name := 'all';
+
+  gc_debug                       constant t_event_name := 'debug';
+
   gc_initialize                  constant t_event_name := 'initialize';
 
   gc_before_run                  constant t_event_name := 'before_run';
@@ -51,7 +56,7 @@ create or replace package ut_event_manager authid current_user as
 
   gc_finalize                    constant t_event_name := 'finalize';
 
-  procedure trigger_event( a_event_name t_event_name, a_event_object ut_event_item );
+  procedure trigger_event( a_event_name t_event_name, a_event_object ut_event_item := null );
 
   procedure initialize;
 

diff --git a/source/core/output_buffers/ut_output_table_buffer.tpb b/source/core/output_buffers/ut_output_table_buffer.tpb
@@ -83,7 +83,7 @@ create or replace type body ut_output_table_buffer is
     l_finished_flags     ut_integer_list;
     l_already_waited_for number(10,2) := 0;
     l_finished           boolean := false;
-    lc_init_wait_sec     constant naturaln := coalesce(a_initial_timeout, 15 ); -- 15 seconds
+    lc_init_wait_sec     constant naturaln := coalesce(a_initial_timeout, 60 ); -- 1 minute
     lc_max_wait_sec      constant naturaln := coalesce(a_timeout_sec, 60 * 60 * 4); -- 4 hours
     l_wait_for           integer := lc_init_wait_sec;
     lc_short_sleep_time  constant number(1,1) := 0.1; --sleep for 100 ms between checks

diff --git a/source/core/types/ut_expectation_result.tpb b/source/core/types/ut_expectation_result.tpb
@@ -21,6 +21,7 @@ create or replace type body ut_expectation_result is
     a_description varchar2, a_message clob, a_include_caller_info boolean := true
   ) return self as result is
   begin
+    self.self_type       := $$plsql_unit;
     self.status          := a_status;
     self.description     := a_description;
     self.message := a_message;

diff --git a/source/core/types/ut_expectation_result.tps b/source/core/types/ut_expectation_result.tps
@@ -1,4 +1,4 @@
-create or replace type ut_expectation_result authid current_user as object(
+create or replace type ut_expectation_result under ut_event_item(
   /*
   utPLSQL - Version 3
   Copyright 2016 - 2018 utPLSQL Project

diff --git a/source/core/types/ut_reporter_base.tpb b/source/core/types/ut_reporter_base.tpb
@@ -211,6 +211,7 @@ create or replace type body ut_reporter_base is
       then self.after_calling_after_all(treat(a_event_item as ut_executable));
       when ut_event_manager.gc_finalize
       then self.on_finalize(treat(a_event_item as ut_run));
+      else null;
     end case;
   end;
 

diff --git a/source/core/types/ut_run_info.tpb b/source/core/types/ut_run_info.tpb
@@ -0,0 +1,48 @@
+create or replace type body ut_run_info as
+  /*
+  utPLSQL - Version 3
+  Copyright 2016 - 2018 utPLSQL Project
+
+  Licensed under the Apache License, Version 2.0 (the "License"):
+  you may not use this file except in compliance with the License.
+  You may obtain a copy of the License at
+
+      http://www.apache.org/licenses/LICENSE-2.0
+
+  Unless required by applicable law or agreed to in writing, software
+  distributed under the License is distributed on an "AS IS" BASIS,
+  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+  See the License for the specific language governing permissions andTEST_GET_REPORTERS_LIST
+  limitations under the License.
+  */
+  constructor function ut_run_info(self in out nocopy ut_run_info) return self as result is
+    l_ut_owner varchar2(250) := ut_utils.ut_owner;
+  begin
+    self.self_type := $$plsql_unit;
+    execute immediate
+      'select '||l_ut_owner||'.ut.version() from dual'
+        into self.ut_version;
+
+    dbms_utility.db_version( self.db_version, self.db_compatibility );
+    db_os_type := dbms_utility.port_string();
+
+    execute immediate
+      'select '||l_ut_owner||'.ut_key_value_pair(x.product, x.version) from product_component_version x'
+        bulk collect into self.db_component_version;
+
+    execute immediate
+      'select '||l_ut_owner||'.ut_key_value_pair(x.parameter, x.value)
+      from nls_session_parameters x'
+        bulk collect into self.nls_session_params;
+
+    execute immediate
+      'select '||l_ut_owner||'.ut_key_value_pair(x.parameter, x.value) from nls_instance_parameters x'
+        bulk collect into self.nls_instance_params;
+
+    execute immediate
+      'select '||l_ut_owner||'.ut_key_value_pair(x.parameter, x.value) from nls_database_parameters x'
+        bulk collect into self.nls_db_params;
+    return;
+  end;
+end;
+/
diff --git a/source/core/types/ut_run_info.tps b/source/core/types/ut_run_info.tps
@@ -0,0 +1,28 @@
+create or replace type ut_run_info under ut_event_item (
+  /*
+  utPLSQL - Version 3
+  Copyright 2016 - 2018 utPLSQL Project
+
+  Licensed under the Apache License, Version 2.0 (the "License"):
+  you may not use this file except in compliance with the License.
+  You may obtain a copy of the License at
+
+      http://www.apache.org/licenses/LICENSE-2.0
+
+  Unless required by applicable law or agreed to in writing, software
+  distributed under the License is distributed on an "AS IS" BASIS,
+  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+  See the License for the specific language governing permissions and
+  limitations under the License.
+  */
+  ut_version           varchar2(4000),
+  db_version           varchar2(4000),
+  db_compatibility     varchar2(4000),
+  db_os_type           varchar2(4000),
+  db_component_version ut_key_value_pairs,
+  nls_session_params   ut_key_value_pairs,
+  nls_instance_params  ut_key_value_pairs,
+  nls_db_params        ut_key_value_pairs,
+  constructor function ut_run_info(self in out nocopy ut_run_info) return self as result
+);
+/