Adding logging and recovery code around DB hack

.gitignore

@@ -5,3 +5,5 @@ myimage.yaml
 /.venv
 /ansible.cfg
 *.pyc
+*.code-workspace
+*.vscode

CHANGELOG.md

@@ -8,6 +8,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 ## [Unreleased]
 ### Changed
 - CASMTRIAGE-4091 - make gunicorn worker timeout configurable to handle larger image sizes
+- CASMCMS-8202 - log and handle DB recovery.
+- Dockerfile stage for starting service in debug mode for debugability.
 
 ## [3.6.0] - 2022-08-03
 ### Changed

Dockerfile

@@ -60,6 +60,15 @@ COPY tests /app/tests
 ARG FORCE_TESTS=null
 CMD [ "./docker_test_entry.sh" ]
 
+# Run app as debug
+# Can use any IDE remote debugger attach to use breakpoints in the IDE
+FROM base as debug
+
+RUN pip3 install debugpy
+ENV FLASK_APP=/app/src/server/app
+EXPOSE 5678 5000
+CMD python -m debugpy --listen 0.0.0.0:5678 --wait-for-client -m flask run -h 0.0.0.0 -p 5000
+
 # Run openapi validation on openapi.yaml
 FROM artifactory.algol60.net/csm-docker/stable/docker.io/openapitools/openapi-generator-cli:v5.1.0 as openapi-validator
 RUN mkdir /tmp/api

README.md

@@ -145,7 +145,7 @@ The following are required:
    ```
    $ docker pull minio/minio
 
-   $ docker run -p 9000:9000,9001:9001 -d minio/minio server /data --console-address :9001
+   $ docker run -p 9000:9000 -p 9001:9001 -d minio/minio server data --console-address :9001
    941dbec66ecd9fe062a0fc99a2ac1e998e89abc72293d001dc4a484f7a9bc67a
 
    $ docker logs 941dbec66ecd9fe062a0fc99a2ac1e998e89abc72293d001dc4a484f7a9bc67a
@@ -179,10 +179,10 @@ The image can be run with the following command:
 
 ```bash
 $ docker run --rm --name ims-service \
-  -p 9000:9000 \
+  -p 8080:9000 \
   -e "S3_ACCESS_KEY=minioadmin" \
   -e "S3_SECRET_KEY=minioadmin" \
-  -e "S3_ENDPOINT=172.17.0.2:9000" \
+  -e "S3_ENDPOINT=http://localhost:9000" \
   -e "S3_IMS_BUCKET=ims" \
   -e "S3_BOOT_IMAGES_BUCKET=boot-images" \
   -e "FLASK_ENV=staging" \
@@ -296,6 +296,45 @@ For a local build, you will also need to manually write the .version, .docker_ve
 builds a docker image), and .chart_version (if this repo builds a helm chart) files. When building
 on github, this is done by the setVersionFiles() function.
 
+### Debug Mode ###
+If you wish to run flask app locally through the container with breakpoints, build the image using the
+`Dockerfile.debug` stage.
+```
+docker build --target debug -t ims-service:debug -f Dockerfile .
+```
+
+Then run by exposing port 5678 on your local machine so the container can remote attach using debugpy. Make sure you are running the `ims-service:debug` tag from the previous command. This will put
+the flask app in standby until a remote connection is made. Once connected the flask app will boot in debug mode.
+```
+docker run -p 5678:5678 -p 5000:5000 -d ims-service:debug
+```
+
+Below is a remote debug configuration from VSCode, but any IDE should
+have similar remote configurations.
+```
+   "configurations": [
+        {
+            "name": "Python: Remote Attach",
+            "type": "python",
+            "request": "attach",
+            "connect": {
+                "host": "127.0.0.1",
+                "port": 5678
+            },
+            "pathMappings": [
+                {
+                    "localRoot": "${workspaceFolder}",
+                    "remoteRoot": "."
+                }
+            ],
+            "justMyCode": true
+        }
+    ]
+```
+
+If code changes are made, make sure you rebuild the container since currently we do not use docker-compose for hot-reloading source code in the containers.
+
+
 ## Versioning
 
 In order to make it easier to go from an artifact back to the source code that produced that artifact,

src/server/__init__.py

@@ -26,44 +26,103 @@
 real data store is enabled.
 """
 import collections
+from datetime import datetime
+
 # TODO CASMCMS-1154 Get a real data store
+import json
+import logging
 import os
 import os.path
 
+logger = logging.getLogger(__name__)
+
 
 class DataStoreHACK(collections.MutableMapping):
-    """ A dictionary that reads/writes to a file """
+    """A dictionary that reads/writes to a file"""
+
+    MAX_RECOVERY_RETRIES: int = 3
 
     def __init__(self, store_file, schema_obj, key_field, *args, **kwargs):
         self.store = dict()
         self.schema = schema_obj
         self.key_field = key_field
         self.update(*args, **kwargs)
         self.store_file = store_file
+        self.current_retries = 0
         if not os.path.exists(self.store_file):
-            with open(self.store_file, 'a'):
+            with open(self.store_file, "a"):
                 os.utime(self.store_file, None)
             self._write()
         else:
             self._read()
 
     def _read(self):
-        """ Read in the data """
-        with open(self.store_file, 'r') as data_file:
-            obj_data = self.schema.loads(data_file.read(), many=True)
-            self.store = {str(getattr(obj, self.key_field)): obj for obj in obj_data}
+        """Reads in store file"""
+        try:
+            logger.info(f"Starting read of {self.store_file}")
+            with open(self.store_file, "r") as data_file:
+                obj_data = self.schema.loads(data_file.read(), many=True)
+                self.store = {
+                    str(getattr(obj, self.key_field)): obj for obj in obj_data
+                }
+        except BaseException as error:
+            logger.error(
+                f"Unable to read {self.store_file} data, file may be empty or corrupted",
+                exc_info=error,
+            )
+            self._save_corrupted_file()
+            self._recover_file_read()
 
     def _write(self):
-        """ Write the data to the file store """
-        with open(self.store_file, 'w') as data_file:
-            data_file.write(self.schema.dumps(iter(self.store.values()), many=True))
+        """Write the data to the file store"""
+        try:
+            with open(self.store_file, "w") as data_file:
+                data_file.write(self.schema.dumps(iter(self.store.values()), many=True))
+        except BaseException as error:
+            logger.error(f"Unable to write to file {self.store_file}", exc_info=error)
+            raise error
+
+    def _save_corrupted_file(self):
+        """
+        Saves the file with a timestamp prefix for manual debugging
+        """
+        path: list[str] = self.store_file.split(os.sep)
+        path[0]: str = os.sep
+        file_name: str = path[-1]
+        timestamp: str = datetime.now().strftime("%Y%m%d-%H%M%S")
+        timestamp_prefix_name: str = timestamp + "_" + file_name
+        path[-1]: str = timestamp_prefix_name
+
+        new_path: str = os.path.join(*path)
+        os.rename(self.store_file, new_path)
+        logger.info(
+            f"Saving corrupted data file {file_name} as {timestamp_prefix_name}"
+        )
+
+    def _recover_file_read(self):
+        """
+        Creates a valid empty JSON file if _read() throws an exception due to corruption
+        or recovery has failed too many times.
+        """
+        logger.info(f"Starting recreation of {self.store_file} with empty JSON")
+        try:
+            with open(self.store_file, "w") as f:
+                f.write(json.dumps([]))
+                logger.info(f"Recreated {self.store_file} with empty JSON")
+        except BaseException as error:
+            logger.error(f"Failed recreation of corrupted file {self.store_file}")
+            raise error
+
+        if self.current_retries < self.MAX_RECOVERY_RETRIES:
+            self.current_retries += 1
+            self._read()
 
     def save(self):
-        """ Save the data to disk """
+        """Save the data to disk"""
         return self._write()
 
     def reset(self):
-        """ Reset the data store to empty and write it out to disk """
+        """Reset the data store to empty and write it out to disk"""
         self.store = dict()
         return self._write()
 

src/server/app.py

@@ -50,31 +50,31 @@
 
 
 def load_datastore(_app):
-    """ Utility function to load IMS data files. """
+    """ Utility function to load IMS data files. """ 
 
     _app.data['public_keys'] = DataStoreHACK(
-        os.path.join(_app.config['HACK_DATA_STORE'], 'v2_public_keys.json'),
+    os.path.join(_app.config['HACK_DATA_STORE'], 'v2_public_keys.json'),
         V2PublicKeyRecordSchema(), 'id')
     _app.data['deleted_public_keys'] = DataStoreHACK(
-        os.path.join(_app.config['HACK_DATA_STORE'], 'v3_deleted_public_keys.json'),
+    os.path.join(_app.config['HACK_DATA_STORE'], 'v3_deleted_public_keys.json'),
         V3DeletedPublicKeyRecordSchema(), 'id')
 
     _app.data['recipes'] = DataStoreHACK(
-        os.path.join(_app.config['HACK_DATA_STORE'], 'v2.1_recipes.json'),
+    os.path.join(_app.config['HACK_DATA_STORE'], 'v2.1_recipes.json'),
         V2RecipeRecordSchema(), 'id')
     _app.data['deleted_recipes'] = DataStoreHACK(
-        os.path.join(_app.config['HACK_DATA_STORE'], 'v3.1_deleted_recipes.json'),
+    os.path.join(_app.config['HACK_DATA_STORE'], 'v3.1_deleted_recipes.json'),
         V3DeletedRecipeRecordSchema(), 'id')
 
     _app.data['images'] = DataStoreHACK(
-        os.path.join(_app.config['HACK_DATA_STORE'], 'v2_images.json'),
+    os.path.join(_app.config['HACK_DATA_STORE'], 'v2_images.json'),
         V2ImageRecordSchema(), 'id')
     _app.data['deleted_images'] = DataStoreHACK(
-        os.path.join(_app.config['HACK_DATA_STORE'], 'v3_deleted_images.json'),
+    os.path.join(_app.config['HACK_DATA_STORE'], 'v3_deleted_images.json'),
         V3DeletedImageRecordSchema(), 'id')
 
     _app.data['jobs'] = DataStoreHACK(
-        os.path.join(_app.config['HACK_DATA_STORE'], 'v2_jobs.json'),
+    os.path.join(_app.config['HACK_DATA_STORE'], 'v2_jobs.json'),
         V2JobRecordSchema(), 'id')
 
 

tests/v2/test_v2_datastore.py

@@ -0,0 +1,82 @@
+#
+# MIT License
+#
+# (C) Copyright 2019, 2021-2022 Hewlett Packard Enterprise Development LP
+#
+# Permission is hereby granted, free of charge, to any person obtaining a
+# copy of this software and associated documentation files (the "Software"),
+# to deal in the Software without restriction, including without limitation
+# the rights to use, copy, modify, merge, publish, distribute, sublicense,
+# and/or sell copies of the Software, and to permit persons to whom the
+# Software is furnished to do so, subject to the following conditions:
+#
+# The above copyright notice and this permission notice shall be included
+# in all copies or substantial portions of the Software.
+#
+# THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+# IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+# FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL
+# THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR
+# OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE,
+# ARISING FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR
+# OTHER DEALINGS IN THE SOFTWARE.
+#
+#
+
+import datetime
+import os
+import tempfile
+
+from unittest import TestCase, mock
+from json import JSONDecodeError
+from mock import MagicMock
+
+from src.server import DataStoreHACK
+
+
+class TestV2DataStore(TestCase):
+    """
+    Tests the DataStoreHack init code.
+    """
+
+    def setUp(self) -> None:
+        # Create temp directory for file testing
+        self.temp_file = tempfile.NamedTemporaryFile()
+
+    def tearDown(self) -> None:
+        self.temp_file.close()
+
+    def test_file_not_found(self):
+        mock_schema = MagicMock()
+
+        with self.assertRaises(FileNotFoundError):
+            DataStoreHACK("/bad/path", mock_schema, "fake_key")
+
+    @mock.patch("src.server.datetime", wraps=datetime.datetime)
+    @mock.patch("os.rename")
+    def test_file_found_decode_error(self, mock_rename, mock_datetime):
+        # setup mocks
+        expected_datetime: datetime.datetime = datetime.datetime(
+            2022, 9, 27, 11, 22, 31, 123456
+        )
+        mock_schema = MagicMock()
+        mock_schema.loads.side_effect = [
+            JSONDecodeError("bad json", self.temp_file.name, 0),
+            [],
+        ]
+        mock_datetime.now.return_value = expected_datetime
+
+        with mock.patch("builtins.open", mock.mock_open()) as mock_file:
+            DataStoreHACK(self.temp_file.name, mock_schema, "id")
+            mock_file.assert_called_with(self.temp_file.name, "r")
+
+            # test if file was renamed with correct timestamps
+            expected_renamed_prefix: str = expected_datetime.strftime("%Y%m%d-%H%M%S")
+            args, _ = mock_rename.call_args
+            new_filepath: str = args[1]
+            renamed_file_prefix = new_filepath.split(os.sep)[-1].split("_")[0]
+            self.assertEqual(renamed_file_prefix, expected_renamed_prefix)
+
+            # test if the file was written to with clean data
+            write_handle: MagicMock = mock_file()
+            write_handle.write.assert_called_once_with("[]")

tests/v2/test_v2_images.py

@@ -35,10 +35,11 @@
 from testtools import TestCase
 from testtools.matchers import HasLength
 
+from tests.v2.ims_fixtures import V2FlaskTestClientFixture, V2ImagesDataFixture
+from tests.utils import check_error_responses
+
 from src.server import app
 from src.server.helper import S3Url
-from tests.utils import check_error_responses
-from tests.v2.ims_fixtures import V2FlaskTestClientFixture, V2ImagesDataFixture
 
 
 class TestV2ImageEndpoint(TestCase):
@@ -82,7 +83,6 @@ def setUp(self):
             self.data_record_link_none,
             self.data_record_no_link
         ]
-
         self.useFixture(V2ImagesDataFixture(initial_data=self.data))
         self.test_uri_with_link = '/images/{}'.format(self.test_id)
         self.test_uri_with_link_cascade_false = '/images/{}?cascade=False'.format(self.test_id)