Fix Postgresql configuration test and guest-log

  - Move 'log_min_duration_statement' into non-dynamic values.
    Although the property itself is dynamic, it still requires restart
    because we don't provide default value for it in our template.
  - Add the 'ms' suffix to the 'log_min_duration_statement' time.
    Postgres by default returns the default suffix.
    Specifing the suffix explicitly fixes the comparison.
  - Change the validation rules for PostgreSQL
    long_min_duration_statement to string from int.
  - Enhance the ConfigurationManager to be able to apply
    system overrides *before* user overrides, as well
    as after.  This allows the logging to be overridden
    by the user config values.
  - Added to the guest-log scenario test to make sure that the
    user log doesn't change after being disabled, and that it
    can be enabled again.

Co-Authored-By: Petr Malik <pmalik@tesora.com>
Co-Authored-By: Peter Stachowski <peter@tesora.com>
Closes-Bug: #1624492
Change-Id: I059357d52fa24c609e45c2dc108d2b4ba77b3458

8 files changed, 174 insertions, 32 deletions

diff --git a/trove/guestagent/common/configuration.py b/trove/guestagent/common/configuration.py
index 1fd226d2..8b986866 100644
--- a/trove/guestagent/common/configuration.py
+++ b/trove/guestagent/common/configuration.py
@@ -34,9 +34,13 @@ class ConfigurationManager(object):
     """
 
     # Configuration group names. The names determine the order in which the
-    # groups get applied. System group should get applied over the user group.
+    # groups get applied. System groups are divided into two camps; pre-user
+    # and post-user.  In general system overrides will get applied over the
+    # user group, unless specified otherwise (i.e. SYSTEM_POST_USER_GROUP
+    # will be used).
+    SYSTEM_PRE_USER_GROUP = '10-system'
     USER_GROUP = '20-user'
-    SYSTEM_GROUP = '50-system'
+    SYSTEM_POST_USER_GROUP = '50-system'
 
     DEFAULT_STRATEGY_OVERRIDES_SUB_DIR = 'overrides'
     DEFAULT_CHANGE_ID = 'common'
@@ -128,7 +132,8 @@ class ConfigurationManager(object):
             self.save_configuration(self._codec.serialize(options))
         else:
             self._override_strategy.remove(self.USER_GROUP)
-            self._override_strategy.remove(self.SYSTEM_GROUP)
+            self._override_strategy.remove(self.SYSTEM_PRE_USER_GROUP)
+            self._override_strategy.remove(self.SYSTEM_POST_USER_GROUP)
 
             operating_system.write_file(
                 self._base_config_path, options, as_root=self._requires_root)
@@ -144,9 +149,13 @@ class ConfigurationManager(object):
     def has_system_override(self, change_id):
         """Return whether a given 'system' change exists.
         """
-        return self._override_strategy.exists(self.SYSTEM_GROUP, change_id)
+        return (self._override_strategy.exists(self.SYSTEM_POST_USER_GROUP,
+                                               change_id) or
+                self._override_strategy.exists(self.SYSTEM_PRE_USER_GROUP,
+                                               change_id))
 
-    def apply_system_override(self, options, change_id=DEFAULT_CHANGE_ID):
+    def apply_system_override(self, options, change_id=DEFAULT_CHANGE_ID,
+                              pre_user=False):
         """Apply a 'system' change to the configuration.
 
         System overrides are always applied after all user changes so that
@@ -155,7 +164,10 @@ class ConfigurationManager(object):
         :param options        Configuration changes.
         :type options         string or dict
         """
-        self._apply_override(self.SYSTEM_GROUP, change_id, options)
+        group_name = (
+            self.SYSTEM_PRE_USER_GROUP if pre_user else
+            self.SYSTEM_POST_USER_GROUP)
+        self._apply_override(group_name, change_id, options)
 
     def apply_user_override(self, options, change_id=DEFAULT_CHANGE_ID):
         """Apply a 'user' change to the configuration.
@@ -183,7 +195,8 @@ class ConfigurationManager(object):
     def remove_system_override(self, change_id=DEFAULT_CHANGE_ID):
         """Revert a 'system' configuration change.
         """
-        self._remove_override(self.SYSTEM_GROUP, change_id)
+        self._remove_override(self.SYSTEM_POST_USER_GROUP, change_id)
+        self._remove_override(self.SYSTEM_PRE_USER_GROUP, change_id)
 
     def remove_user_override(self, change_id=DEFAULT_CHANGE_ID):
         """Revert a 'user' configuration change.
diff --git a/trove/guestagent/datastore/manager.py b/trove/guestagent/datastore/manager.py
index 109e8de3..5d3e94dd 100644
--- a/trove/guestagent/datastore/manager.py
+++ b/trove/guestagent/datastore/manager.py
@@ -571,12 +571,8 @@ class Manager(periodic_task.PeriodicTasks):
             config_man_values = cfg_values
             if section_label:
                 config_man_values = {section_label: cfg_values}
-            # Applying the changes with a group id lower than the one used
-            # by user overrides. Any user defined value will override these
-            # settings (irrespective of order in which they are applied).
-            # See Bug 1542485
-            self.configuration_manager._apply_override(
-                '10-system-low-priority', apply_label, config_man_values)
+            self.configuration_manager.apply_system_override(
+                config_man_values, change_id=apply_label, pre_user=True)
         if restart_required:
             self.status.set_status(instance.ServiceStatuses.RESTART_REQUIRED)
         else:
diff --git a/trove/templates/postgresql/validation-rules.json b/trove/templates/postgresql/validation-rules.json
index 9a285eb7..39f64c75 100644
--- a/trove/templates/postgresql/validation-rules.json
+++ b/trove/templates/postgresql/validation-rules.json
@@ -481,12 +481,6 @@
             "type": "string"
         },
         {
-            "name": "log_min_duration_statement",
-            "restart_required": false,
-            "min": -1,
-            "type": "integer"
-        },
-        {
             "name": "debug_print_parse",
             "restart_required": false,
             "type": "boolean"
@@ -902,8 +896,7 @@
         {
             "name": "log_min_duration_statement",
             "restart_required": false,
-            "min": -1,
-            "type": "integer"
+            "type": "string"
         }
     ]
 }
diff --git a/trove/tests/scenario/groups/guest_log_group.py b/trove/tests/scenario/groups/guest_log_group.py
index beb0418c..1ba5e287 100644
--- a/trove/tests/scenario/groups/guest_log_group.py
+++ b/trove/tests/scenario/groups/guest_log_group.py
@@ -50,11 +50,6 @@ class GuestLogGroup(TestGroup):
         self.test_runner.run_test_admin_log_list()
 
     @test
-    def test_log_show(self):
-        """Test that log-show works on USER log."""
-        self.test_runner.run_test_log_show()
-
-    @test
     def test_log_enable_sys(self):
         """Ensure log-enable on SYS log fails."""
         self.test_runner.run_test_log_enable_sys()
@@ -109,6 +104,12 @@ class GuestLogGroup(TestGroup):
         """Ensure log-discard on unexposed log fails for auth client."""
         self.test_runner.run_test_log_discard_unexposed_user()
 
+    # USER log tests
+    @test(runs_after=[test_log_list, test_admin_log_list])
+    def test_log_show(self):
+        """Test that log-show works on USER log."""
+        self.test_runner.run_test_log_show()
+
     @test(runs_after=[test_log_show])
     def test_log_enable_user(self):
         """Test log-enable on USER log."""
@@ -211,6 +212,72 @@ class GuestLogGroup(TestGroup):
         """Wait for restart to complete again."""
         self.test_runner.run_test_wait_for_restart()
 
+    @test(runs_after=[test_wait_for_restart_again])
+    def test_log_show_after_stop_details(self):
+        """Get log-show details before adding data."""
+        self.test_runner.run_test_log_show_after_stop_details()
+
+    @test(runs_after=[test_log_show_after_stop_details])
+    def test_add_data_again_after_stop(self):
+        """Add more data to ensure logging has stopped on USER log."""
+        self.test_runner.run_test_add_data_again_after_stop()
+
+    @test(runs_after=[test_add_data_again_after_stop])
+    def test_verify_data_again_after_stop(self):
+        """Verify data for stopped logging on USER log."""
+        self.test_runner.run_test_verify_data_again_after_stop()
+
+    @test(runs_after=[test_verify_data_again_after_stop])
+    def test_log_show_after_stop(self):
+        """Test that log-show has same values on USER log."""
+        self.test_runner.run_test_log_show_after_stop()
+
+    @test(runs_after=[test_log_show_after_stop])
+    def test_log_enable_user_after_stop(self):
+        """Test log-enable still works on USER log."""
+        self.test_runner.run_test_log_enable_user_after_stop()
+
+    @test(runs_after=[test_log_enable_user_after_stop])
+    def test_restart_datastore_after_stop_start(self):
+        """Test restart datastore after stop/start if required."""
+        self.test_runner.run_test_restart_datastore()
+
+    @test(runs_after=[test_restart_datastore_after_stop_start])
+    def test_wait_for_restart_after_stop_start(self):
+        """Wait for restart to complete again after stop/start."""
+        self.test_runner.run_test_wait_for_restart()
+
+    @test(runs_after=[test_wait_for_restart_after_stop_start])
+    def test_add_data_again_after_stop_start(self):
+        """Add more data to ensure logging works again on USER log."""
+        self.test_runner.run_test_add_data_again_after_stop_start()
+
+    @test(runs_after=[test_add_data_again_after_stop_start])
+    def test_verify_data_again_after_stop_start(self):
+        """Verify data for re-enabled logging on USER log."""
+        self.test_runner.run_test_verify_data_again_after_stop_start()
+
+    @test(runs_after=[test_verify_data_again_after_stop_start])
+    def test_log_publish_after_stop_start(self):
+        """Test log-publish after stop/start on USER log."""
+        self.test_runner.run_test_log_publish_after_stop_start()
+
+    @test(runs_after=[test_log_publish_after_stop_start])
+    def test_log_disable_user_after_stop_start(self):
+        """Test log-disable on USER log after stop/start."""
+        self.test_runner.run_test_log_disable_user_after_stop_start()
+
+    @test(runs_after=[test_log_disable_user_after_stop_start])
+    def test_restart_datastore_after_final_stop(self):
+        """Test restart datastore again if required after final stop."""
+        self.test_runner.run_test_restart_datastore()
+
+    @test(runs_after=[test_restart_datastore_after_final_stop])
+    def test_wait_for_restart_after_final_stop(self):
+        """Wait for restart to complete again after final stop."""
+        self.test_runner.run_test_wait_for_restart()
+
+    # SYS log tests
     @test
     def test_log_show_sys(self):
         """Test that log-show works for SYS log."""
diff --git a/trove/tests/scenario/helpers/postgresql_helper.py b/trove/tests/scenario/helpers/postgresql_helper.py
index 5b0c37b2..9fec07d1 100644
--- a/trove/tests/scenario/helpers/postgresql_helper.py
+++ b/trove/tests/scenario/helpers/postgresql_helper.py
@@ -45,11 +45,11 @@ class PostgresqlHelper(SqlHelper):
                  'databases': [{'name': 'db1'}, {'name': 'db2'}]}]
 
     def get_dynamic_group(self):
-        return {'effective_cache_size': '528MB',
-                'log_min_duration_statement': 257}
+        return {'effective_cache_size': '528MB'}
 
     def get_non_dynamic_group(self):
-        return {'max_connections': 113}
+        return {'max_connections': 113,
+                'log_min_duration_statement': '257ms'}
 
     def get_invalid_groups(self):
         return [{'timezone': 997},
diff --git a/trove/tests/scenario/helpers/test_helper.py b/trove/tests/scenario/helpers/test_helper.py
index 01b1d1a4..0deeb9ca 100644
--- a/trove/tests/scenario/helpers/test_helper.py
+++ b/trove/tests/scenario/helpers/test_helper.py
@@ -33,6 +33,10 @@ class DataType(Enum):
     micro = 1
     # another micro dataset (also for datastore logging)
     micro2 = 2
+    # another micro dataset (also for datastore logging)
+    micro3 = 3
+    # another micro dataset (also for datastore logging)
+    micro4 = 4
     # very tiny amount of data, useful for testing replication
     # propagation, etc.
     tiny = 3
@@ -111,6 +115,12 @@ class TestHelper(object):
             DataType.micro2.name: {
                 self.DATA_START: 200,
                 self.DATA_SIZE: 10},
+            DataType.micro3.name: {
+                self.DATA_START: 300,
+                self.DATA_SIZE: 10},
+            DataType.micro4.name: {
+                self.DATA_START: 400,
+                self.DATA_SIZE: 10},
             DataType.tiny.name: {
                 self.DATA_START: 1000,
                 self.DATA_SIZE: 100},
diff --git a/trove/tests/scenario/runners/guest_log_runners.py b/trove/tests/scenario/runners/guest_log_runners.py
index 3c7d299e..fb47dae0 100644
--- a/trove/tests/scenario/runners/guest_log_runners.py
+++ b/trove/tests/scenario/runners/guest_log_runners.py
@@ -35,6 +35,7 @@ class GuestLogRunner(TestRunner):
 
         self.container = CONF.guest_log_container_name
         self.prefix_pattern = '%(instance_id)s/%(datastore)s-%(log)s/'
+        self.stopped_log_details = None
         self._last_log_published = {}
         self._last_log_contents = {}
 
@@ -611,6 +612,62 @@ class GuestLogRunner(TestRunner):
                 expected_status=expected_status,
                 expected_published=0, expected_pending=1)
 
+    def run_test_log_show_after_stop_details(self):
+        self.stopped_log_details = self.auth_client.instances.log_show(
+            self.instance_info.id, self._get_exposed_user_log_name())
+        self.assert_is_not_none(self.stopped_log_details)
+
+    def run_test_add_data_again_after_stop(self):
+        # Add some more data to make sure logging has stopped
+        self.test_helper.add_data(DataType.micro3, self.get_instance_host())
+
+    def run_test_verify_data_again_after_stop(self):
+        self.test_helper.verify_data(DataType.micro3, self.get_instance_host())
+
+    def run_test_log_show_after_stop(self):
+        self.assert_log_show(
+            self.auth_client, self._get_exposed_user_log_name(),
+            expected_published=self.stopped_log_details.published,
+            expected_pending=self.stopped_log_details.pending)
+
+    def run_test_log_enable_user_after_stop(self):
+        expected_status = guest_log.LogStatus.Ready.name
+        expected_pending = 1
+        if self.test_helper.log_enable_requires_restart():
+            expected_status = guest_log.LogStatus.Restart_Required.name
+
+        self.assert_log_enable(
+            self.auth_client,
+            self._get_exposed_user_log_name(),
+            expected_status=expected_status,
+            expected_published=0, expected_pending=expected_pending)
+
+    def run_test_add_data_again_after_stop_start(self):
+        # Add some more data to make sure logging has started again
+        self.test_helper.add_data(DataType.micro4, self.get_instance_host())
+
+    def run_test_verify_data_again_after_stop_start(self):
+        self.test_helper.verify_data(DataType.micro4, self.get_instance_host())
+
+    def run_test_log_publish_after_stop_start(self):
+        log_name = self._get_exposed_user_log_name()
+        self.assert_log_publish(
+            self.auth_client,
+            log_name,
+            expected_status=guest_log.LogStatus.Published.name,
+            expected_published=self._get_last_log_published(log_name) + 1,
+            expected_pending=0)
+
+    def run_test_log_disable_user_after_stop_start(self):
+        expected_status = guest_log.LogStatus.Disabled.name
+        if self.test_helper.log_enable_requires_restart():
+            expected_status = guest_log.LogStatus.Restart_Required.name
+        self.assert_log_disable(
+            self.auth_client,
+            self._get_exposed_user_log_name(), discard=True,
+            expected_status=expected_status,
+            expected_published=0, expected_pending=1)
+
     def run_test_log_show_sys(self):
         self.assert_log_show(
             self.admin_client,
diff --git a/trove/tests/unittests/guestagent/test_configuration.py b/trove/tests/unittests/guestagent/test_configuration.py
index 0f514f4b..c2098923 100644
--- a/trove/tests/unittests/guestagent/test_configuration.py
+++ b/trove/tests/unittests/guestagent/test_configuration.py
@@ -75,11 +75,17 @@ class TestConfigurationManager(trove_testtools.TestCase):
         manager.apply_user_override(sample_data)
         manager.apply_system_override(sample_data, change_id='sys1')
         manager.apply_user_override(sample_data, change_id='usr1')
+        manager.apply_system_override(sample_data, change_id='sys2',
+                                      pre_user=True)
         sample_strategy.apply.has_calls([
-            call(manager.SYSTEM_GROUP, manager.DEFAULT_CHANGE_ID, sample_data),
+            call(manager.SYSTEM_POST_USER_GROUP,
+                 manager.DEFAULT_CHANGE_ID, sample_data),
             call(manager.USER_GROUP, manager.DEFAULT_CHANGE_ID, sample_data),
-            call(manager.SYSTEM_GROUP, 'sys1', sample_data),
-            call(manager.USER_GROUP, 'usr1', sample_data)
+            call(manager.SYSTEM_POST_USER_GROUP,
+                 'sys1', sample_data),
+            call(manager.USER_GROUP, 'usr1', sample_data),
+            call(manager.SYSTEM_PRE_USER_GROUP,
+                 'sys2', sample_data),
         ])