DB Backup Bug

tdrs-backend/tdpservice/scheduling/db_backup.py

@@ -26,18 +26,26 @@ def get_system_values():
     sys_values['SPACE'] = json.loads(OS_ENV['VCAP_APPLICATION'])['space_name']
 
     # Postgres client pg_dump directory
-    pgdump_search = subprocess.Popen(["find", "/", "-iname", "pg_dump"],
-                                     stderr=subprocess.DEVNULL, stdout=subprocess.PIPE)
-    pgdump_search.wait()
-    pg_dump_paths, pgdump_search_error = pgdump_search.communicate()
-    pg_dump_paths = pg_dump_paths.decode("utf-8").split('\n')
-    if pg_dump_paths[0] == '':
-        raise Exception("Postgres client is not found")
-
-    for _ in pg_dump_paths:
-        if 'pg_dump' in str(_) and 'postgresql' in str(_):
-            sys_values['POSTGRES_CLIENT'] = _[:_.find('pg_dump')]
-            print("Found PG client here: {}".format(_))
+    sys_values['POSTGRES_CLIENT_DIR'] = "/home/vcap/deps/0/apt/usr/lib/postgresql/12/bin/"
+
+    # If the client directory and binaries don't exist, we need to find them.
+    if not (os.path.exists(sys_values['POSTGRES_CLIENT_DIR']) and
+            os.path.isfile(f"{sys_values['POSTGRES_CLIENT_DIR']}pg_dump")):
+        logger.warning("Couldn't find postgres client binaries at the hardcoded path: "
+                       f"{sys_values['POSTGRES_CLIENT_DIR']}. Searching OS for client directory.")
+        pgdump_search = subprocess.Popen(["find", "/", "-iname", "pg_dump"],
+                                         stderr=subprocess.DEVNULL, stdout=subprocess.PIPE)
+        pgdump_search.wait()
+        pg_dump_paths, pgdump_search_error = pgdump_search.communicate()
+        pg_dump_paths = pg_dump_paths.decode("utf-8").split('\n')
+        if pg_dump_paths[0] == '':
+            raise Exception("Postgres client is not found")
+
+        for _ in pg_dump_paths:
+            if 'pg_dump' in str(_) and 'postgresql' in str(_):
+                sys_values['POSTGRES_CLIENT'] = _[:_.find('pg_dump')]
+
+    logger.info(f"Using postgres client at: {sys_values['POSTGRES_CLIENT_DIR']}")
 
     sys_values['S3_ENV_VARS'] = json.loads(OS_ENV['VCAP_SERVICES'])['s3']
     sys_values['S3_CREDENTIALS'] = sys_values['S3_ENV_VARS'][0]['credentials']
@@ -82,12 +90,16 @@ def backup_database(file_name,
     pg_dump -F c --no-acl --no-owner -f backup.pg postgresql://${USERNAME}:${PASSWORD}@${HOST}:${PORT}/${NAME}
     """
     try:
-        os.system(postgres_client + "pg_dump -Fc --no-acl -f " + file_name + " -d " + database_uri)
-        print("Wrote pg dumpfile to {}".format(file_name))
+        cmd = postgres_client + "pg_dump -Fc --no-acl -f " + file_name + " -d " + database_uri
+        logger.info(f"Executing backup command: {cmd}")
+        os.system(cmd)
+        logger.info("Wrote pg dumpfile to {}".format(file_name))
+        file_size = os.path.getsize(file_name)
+        logger.info(f"Pg dumpfile size in bytes: {file_size}.")
         return True
     except Exception as e:
-        print(e)
-        return False
+        logger.error(f"Caught Exception while backing up database. Exception: {e}")
+        raise e
 
 
 def restore_database(file_name, postgres_client, database_uri):
@@ -100,10 +112,12 @@ def restore_database(file_name, postgres_client, database_uri):
      DATABASE_DB_NAME] = get_database_credentials(database_uri)
     os.environ['PGPASSWORD'] = DATABASE_PASSWORD
     try:
+        logger.info("Begining database creation.")
         os.system(postgres_client + "createdb " + "-U " + DATABASE_USERNAME + " -h " + DATABASE_HOST + " -T template0 "
                   + DATABASE_DB_NAME)
+        logger.info("Completed database creation.")
     except Exception as e:
-        print(e)
+        logger.error(f"Caught exception while creating the database. Exception: {e}.")
         return False
 
     # write .pgpass
@@ -112,8 +126,10 @@ def restore_database(file_name, postgres_client, database_uri):
     os.environ['PGPASSFILE'] = '/home/vcap/.pgpass'
     os.system('chmod 0600 /home/vcap/.pgpass')
 
+    logger.info("Begining database restoration.")
     os.system(postgres_client + "pg_restore" + " -p " + DATABASE_PORT + " -h " +
               DATABASE_HOST + " -U " + DATABASE_USERNAME + " -d " + DATABASE_DB_NAME + " " + file_name)
+    logger.info("Completed database restoration.")
     return True
 
 
@@ -129,10 +145,12 @@ def upload_file(file_name, bucket, sys_values, object_name=None, region='us-gov-
     if object_name is None:
         object_name = os.path.basename(file_name)
 
+    logger.info(f"Uploading {file_name} to S3.")
     s3_client = boto3.client('s3', region_name=sys_values['S3_REGION'])
 
-    s3_client.upload_file(file_name, bucket, object_name)
-    print("Uploaded {} to S3:{}{}".format(file_name, bucket, object_name))
+    response = s3_client.upload_file(file_name, bucket, object_name)
+    logger.info(f"S3 upload response: {response}")
+    logger.info("Uploaded {} to s3://{}/{}.".format(file_name, bucket, object_name))
     return True
 
 
@@ -150,9 +168,11 @@ def download_file(bucket,
     """
     if object_name is None:
         object_name = os.path.basename(file_name)
+    logger.info("Begining download for backup file.")
     s3 = boto3.client('s3', region_name=region)
-    s3.download_file(bucket, object_name, file_name)
-    print("Downloaded s3 file {}{} to {}.".format(bucket, object_name, file_name))
+    response = s3.download_file(bucket, object_name, file_name)
+    logger.info(f"Response from s3 download: {response}.")
+    logger.info("Downloaded s3 file {}/{} to {}.".format(bucket, object_name, file_name))
 
 
 def list_s3_files(sys_values):
@@ -212,7 +232,7 @@ def main(argv, sys_values):
     if arg_to_backup:
         # back up database
         backup_database(file_name=arg_file,
-                        postgres_client=sys_values['POSTGRES_CLIENT'],
+                        postgres_client=sys_values['POSTGRES_CLIENT_DIR'],
                         database_uri=arg_database)
 
         # upload backup file
@@ -221,6 +241,7 @@ def main(argv, sys_values):
                     sys_values=sys_values,
                     region=sys_values['S3_REGION'],
                     object_name="backup"+arg_file)
+        logger.info(f"Deleting {arg_file} from local storage.")
         os.system('rm ' + arg_file)
 
     elif arg_to_restore:
@@ -232,9 +253,10 @@ def main(argv, sys_values):
 
         # restore database
         restore_database(file_name=arg_file,
-                         postgres_client=sys_values['POSTGRES_CLIENT'],
+                         postgres_client=sys_values['POSTGRES_CLIENT_DIR'],
                          database_uri=arg_database)
 
+        logger.info(f"Deleting {arg_file} from local storage.")
         os.system('rm ' + arg_file)
 
 
@@ -243,7 +265,12 @@ def run_backup(arg):
     if settings.USE_LOCALSTACK is True:
         logger.info("Won't backup locally")
     else:
-        main([arg], sys_values=get_system_values())
+        try:
+            main([arg], sys_values=get_system_values())
+        except Exception as e:
+            logger.error(f"Caught Exception in run_backup. Exception: {e}.")
+            return False
+    return True
 
 
 if __name__ == '__main__':

tdrs-backend/tdpservice/scheduling/tasks.py

@@ -20,8 +20,13 @@ def postgres_backup(*args):
     """Run nightly postgres backup."""
     arg = ''.join(args)
     logger.debug("postgres_backup::run_backup() run with arg: " + arg)
-    run_backup(arg)
-    return True
+    logger.info("Begining database backup.")
+    result = run_backup(arg)
+    if result:
+        logger.info("Finished database backup.")
+    else:
+        logger.error("Failed to complete database backup.")
+    return result
 
 @shared_task
 def check_for_accounts_needing_deactivation_warning():

tdrs-backend/tdpservice/settings/common.py

@@ -452,15 +452,15 @@ class Common(Configuration):
     CELERY_TIMEZONE = 'UTC'
 
     CELERY_BEAT_SCHEDULE = {
-        'name': {
+        'Database Backup': {
             'task': 'tdpservice.scheduling.tasks.postgres_backup',
             'schedule': crontab(minute='0', hour='4'), # Runs at midnight EST
             'args': "-b",
             'options': {
                 'expires': 15.0,
             },
         },
-        'name': {
+        'Account Deactivation Warning': {
             'task': 'tdpservice.scheduling.tasks.check_for_accounts_needing_deactivation_warning',
             'schedule': crontab(day_of_week='*', hour='13', minute='0'), # Every day at 1pm UTC (9am EST)
 

terraform/dev/main.tf

@@ -52,6 +52,7 @@ resource "cloudfoundry_service_instance" "database" {
   name             = "tdp-db-dev"
   space            = data.cloudfoundry_space.space.id
   service_plan     = data.cloudfoundry_service.rds.service_plans["micro-psql"]
+  json_params      = "{\"version\": \"12\"}"
   recursive_delete = true
 }
 

terraform/production/main.tf

@@ -51,6 +51,7 @@ resource "cloudfoundry_service_instance" "database" {
   name             = "tdp-db-prod"
   space            = data.cloudfoundry_space.space.id
   service_plan     = data.cloudfoundry_service.rds.service_plans["medium-psql"]
+  json_params      = "{\"version\": \"12\"}"
   recursive_delete = true
 }
 

terraform/staging/main.tf

@@ -51,6 +51,7 @@ resource "cloudfoundry_service_instance" "database" {
   name             = "tdp-db-staging"
   space            = data.cloudfoundry_space.space.id
   service_plan     = data.cloudfoundry_service.rds.service_plans["micro-psql"]
+  json_params      = "{\"version\": \"12\"}"
   recursive_delete = true
 }