log improvements, some rework, update readme

Author: freenoth

README.md

@@ -3,7 +3,7 @@ This package allow to easy manage apps migrations based on GIT repository (it us
 So you can return to any previous state that is saved in DB by one command.
 
 ## Version
-Current version is `0.3.1`
+Current version is `0.4.0`
 
 It works with:
 - django >= 1.11.3
@@ -14,7 +14,7 @@ It works with:
 
 First you need to install package with pip:
 ```bash
-pip install git+https://github.com/freenoth/django-rollback.git@0.3.1
+pip install git+https://github.com/freenoth/django-rollback.git@0.4.0
 ```
 
 Then install it to your `INSTALLED_APPS`
@@ -39,7 +39,7 @@ Both commands have common arguments:
                         Log level for logging. INFO, DEBUG, etc.
 
 ```
-`PATH` argument used to specify path to git repository directory (local). Default path is current dir : `'.'`.
+`PATH` argument used to specify path to git repository directory (local). Default path is current dir : `'.'`. For django applications it is a project root where `manage.py` is located.
 
 `LOGGER` and `LOG_LEVEL` arguments can be used to setup internal logging. For example, you can use one of django_logging loggers (to push it to slack, write console, file, etc.). There is no default value, so by default additional logging disabled.
 
@@ -51,9 +51,10 @@ Help message below:
 ```bash
 usage: manage.py save_migrations_state [-p PATH] [-l LOGGER]
                                        [--log-level LOG_LEVEL]
+                                       [--log-full-data] [--log-diff]
 
 Save migrations state for current commit. It also check if commit already
-exists and print warning if it`s not the latest state that may be a symptom of
+exists and print warning if it's not the latest state that may be a symptom of
 inconsistent state for migrations.
 
 optional arguments:
@@ -62,24 +63,29 @@ optional arguments:
                         Logger name for logging.
   --log-level LOG_LEVEL
                         Log level for logging. INFO, DEBUG, etc.
+  --log-full-data       Log full data for migrations state when created.
+  --log-diff            Log current diff for current and previous state.
 
 ```
 This command used to save apps migrations state of current commit to DB. It try to create new state, but if already exists it checks is this state the latest.
 If state for current commit is not the latest - it may be a symptom of problems and rollback from current commit will not work for it.
 
 Successful output example below:
 ```bash
-Data = [(4, 'admin', '0002_logentry_remove_auto_add'), (12, 'auth', '0008_alter_user_username_max_length'), (5, 'contenttypes', '0002_remove_content_type_name'), (16, 'django_auto_rollback', '0001_initial'), (17, 'django_rollback', '0001_initial'), (14, 'sessions', '0001_initial')].
-Successfully created for commit "84e47461a95fa325d9e933bbe8cca8c52bbea203".
+$ ./manage.py save_migrations_state --log-full-data --log-diff
+State successfully created for commit "03ec91e5319ed65a94f8ea07f6093018a61f9e1b" ['0.3.2'].
+Data = [(4, 'admin', '0002_logentry_remove_auto_add'), (12, 'auth', '0008_alter_user_username_max_length'), (5, 'contenttypes', '0002_remove_content_type_name'), (15, 'django_rollback', '0001_initial'), (14, 'sessions', '0001_initial')]
+Diff not found. There is no migrations to rollback.
 ```
+Every commit that is logged will be marked by list of tags for this commit.
 
 ### Return to previous state (rollback)
 ```bash
 ./manage.py rollback_migrations
 ```
 Help message below:
 ```bash
-usage: manage.py rollback_migrations [-p PATH] [-l LOGGER] [--log-level LOG_LEVEL]
+usage: manage.py rollback_migrations [-p PATH] [-l LOGGER] [--log-level LOG_LEVEL] 
                                      [--list] [-t TAG] [-c COMMIT] [--fake]
 
 Rollback migrations state of all django apps to chosen tag or commit if
@@ -100,6 +106,7 @@ optional arguments:
                         Git commit hash to which to rollback migrations.
   --fake                It allow to only print info about processed actions
                         without execution (no changes for DB).
+
 ```
 
 You can use git commit hash (hex) directly. And you don`t need to specify full commit hash, you just can use first letters.
@@ -117,14 +124,19 @@ Or you can use git tag (it will be translated to related commit).
 
 Successful output example below:
 ```bash
-./manage.py rollback_migrations -c c257a23
->>> Executing command: migrate django_rollback zero
+$ ./manage.py rollback_migrations -c 0df07b
+Found migrations diff. In case of rollback need migrate to:
+[MigrationRecord(id=24, app='temp', name='zero')]
+Running rollback from commit "03ec91e5319ed65a94f8ea07f6093018a61f9e1b" ['0.2.1'] to commit "0df07b2f0ce8dbb9755cfd8a1b213f9c0735e833" ['0.2.0'].
+Executing command: `migrate temp zero`
 Operations to perform:
-  Unapply all migrations: django_rollback
+  Unapply all migrations: temp
 Running migrations:
   Rendering model states... DONE
-  Unapplying django_rollback.0001_initial... OK
+  Unapplying temp.0001_initial... OK
+state for commit "0df07b2f0ce8dbb9755cfd8a1b213f9c0735e833" ['0.2.0'] now is the last state in DB
 Rollback successfully finished.
+
 ```
 
 As you can see above, apps can be rollbacked to `zero` state too, if in previous state this app not used.
@@ -137,3 +149,47 @@ So rollback will be successfully finished if two conditions are satisfied:
 - state for current commit was saved (if not - use `./manage.py save_migrations_state` command)
 - state for specified commit, commit which relates to specified tag was saved in the past
 - if commit not specified, just the previous state should exists 
+
+## Usage example
+For example, we have a django-application packed with Docker. We have a release cycle and deploy docker images based on some version of our source code. Building images includes copying all source code data (including `.git` directory), so `django_rollback` will have direct access to local git repository to identify or search commits, tags, etc.
+
+Docker allows you to use some `entrypoint` that can be `.sh` file. So we have something like that:
+```dockerfile
+FROM python:3.6
+ENTRYPOINT ["dumb-init", "--"]
+CMD ["start.sh"]
+WORKDIR /src
+EXPOSE 8000
+
+COPY . /src
+COPY docker/bin /usr/local/bin
+
+### and other configuration
+```
+And our `start.sh` entrypoint can be something like this:
+```bash
+#!/bin/bash
+
+./_manage.py migrate
+./_manage.py save_migrations_state -l "django.slack_logging" --log-level INFO --log-diff
+
+gunicorn --bind 0.0.0.0:8000 -k eventlet -w $WORKER_COUNT --max-requests $MAX_REQUESTS --reload app.wsgi:application
+
+```
+So every time when your application is starting in docker - current migrations state will be saved or checked. And you will see all actions with specified logger (slack channel, for example). So, now you have an ability to monitoring current migrations state of your django-application in real time.
+
+### When something goes wrong...
+
+With our release cycle sometimes something goes wrong during deployment of new version of our application and we want to bring back previous state of application.
+
+So we need to unapply all new migrations and deploy docker image based on previous version.
+
+You just can use some `.sh` script to run rollback migrations or manually run manage.py command using `docker run` or `docker exec` commands.
+
+Script `rollback.sh` can be like this:
+```bash
+#!/usr/bin/env bash
+./_manage.py rollback_migrations "$@" -l "django.slack_logging" --log-level INFO
+
+```
+So in case of rollback you also able to monitoring what`s going on: which migrations are unapplying and which version of source code new DB state corresponds.

django_rollback/management/base.py

@@ -1,11 +1,14 @@
+import io
 import json
 import logging
+import traceback
 from collections import namedtuple
 
 import git
 from django.core.management import call_command
 from django.core.management.base import BaseCommand, CommandError
 from django.db import connection
+from django.utils.encoding import force_str
 
 from django_rollback.consts import DEFAULT_REPO_PATH, COMMIT_MAX_LENGTH, MIGRATE_COMMAND
 from django_rollback.models import AppsState
@@ -18,13 +21,21 @@ class BaseRollbackCommand(BaseCommand):
 
     def __init__(self, *args, **kwargs):
         super().__init__(*args, **kwargs)
+        self._repo_path = DEFAULT_REPO_PATH
+        self._repo_tags = None
+        self._commits_info = {}
+        self._out = io.StringIO()
         self._logger = None
+        self._result_log_level = logging.DEBUG
 
     def add_arguments(self, parser):
         parser.add_argument('-p', '--path', type=str, default=DEFAULT_REPO_PATH, help='Git repository path.')
         parser.add_argument('-l', '--logger', type=str, help='Logger name for logging.')
         parser.add_argument('--log-level', type=str, help='Log level for logging. INFO, DEBUG, etc.')
 
+    def configure_repo_path(self, options):
+        self._repo_path = options.get('path', DEFAULT_REPO_PATH)
+
     def configure_logger(self, options):
         if options['logger']:
             logger = logging.getLogger(options['logger'])
@@ -35,20 +46,97 @@ def configure_logger(self, options):
 
             self._logger = logger
 
+    def add_log(self, message, style_func=None, ending='\n', log_level=logging.INFO, exc_info=False):
+        if isinstance(message, str) and not message.endswith(ending):
+            message += ending
+
+        if style_func is None:
+            style_func = lambda x: x
+
+        if log_level > self._result_log_level:
+            self._result_log_level = log_level
+
+        if exc_info:
+            message += traceback.format_exc()
+            if not message.endswith(ending):
+                message += ending
+
+        self._out.write(force_str(style_func(message)))
+
+    def write_log(self):
+        message = self._out.getvalue()
+
+        self.stdout.write(message)
+
+        if self._logger:
+            self._logger.log(self._result_log_level, message)
+
+    def close_log(self):
+        self._out.close()
+
     def handle(self, *args, **options):
-        raise NotImplemented
+        try:
+            self.configure_repo_path(options)
+            self.configure_logger(options)
+            self._handle(*args, **options)
 
-    def get_current_commit(self, path):
+        finally:
+            self.write_log()
+            self.close_log()
+
+    def _handle(self, *args, **options):
+        raise NotImplementedError('subclasses of BaseRollbackCommand must provide a _handle() method')
+
+    def get_current_commit(self):
         try:
-            repo = git.Repo(path)
+            repo = git.Repo(self._repo_path)
             return repo.head.commit.hexsha
         except ValueError as err:
-            message = f'An error occurred while working with git repo!'
-            self.stdout.write(self.style.ERROR(message))
-            if self._logger:
-                self._logger.error(message + f'\n{__name__}')
+            self.add_log(f'An error occurred while working with git repo!', style_func=self.style.ERROR,
+                         log_level=logging.ERROR, exc_info=True)
             raise CommandError(err)
 
+    def get_previous_commit(self, raise_exception=True):
+        """
+        current commit should be already validated
+        so we are sure that the last state linked to current commit
+        need to select previous commit
+        """
+
+        if AppsState.objects.count() < 2:
+            message = f'There is only one state in DB. Can`t identify previous state. Rollback procedure impossible.'
+            self.add_log(message, style_func=self.style.ERROR, log_level=logging.WARNING)
+            if raise_exception:
+                raise CommandError()
+
+            return None
+
+        return AppsState.objects.all().order_by('-timestamp')[1].commit
+
+    @property
+    def repo_tags(self):
+        if not self._repo_tags:
+            try:
+                repo = git.Repo(self._repo_path)
+                result = {}
+                for tag in repo.tags:
+                    result.setdefault(tag.commit.hexsha, [])
+                    result[tag.commit.hexsha].append(tag.name)
+
+                self._repo_tags = result
+
+            except Exception:
+                message = f'An error occurred while working with git repo during getting Tags map.'
+                self.add_log(message, style_func=self.style.WARNING)
+                self._repo_tags = {}
+
+        return self._repo_tags
+
+    def get_commit_info(self, commit):
+        if commit not in self._commits_info:
+            self._commits_info[commit] = f'"{commit}" {self.repo_tags.get(commit, [])}'
+        return self._commits_info[commit]
+
     @staticmethod
     def get_last_apps_state():
         return AppsState.objects.all().order_by('timestamp').last()
@@ -69,21 +157,23 @@ def get_apps_state_by_commit(self, commit):
         count = queryset.count()
 
         if count == 0:
-            message = f'Can not find stored data of migrations state for commit `{commit}`.'
-            if self._logger:
-                self._logger.warning(message)
-            raise CommandError(message)
+            message = f'Cant find stored data of migrations state for commit {self.get_commit_info(commit)}.'
+            self.add_log(message, style_func=self.style.ERROR, log_level=logging.WARNING)
+            raise CommandError()
 
         if count > 1:
             is_short_commit = len(commit) < COMMIT_MAX_LENGTH
-            message = (f'Found more than 1 ({count}) records for selected commit {commit}.'
+            message = (f'Found more than 1 ({count}) records for selected commit {self.get_commit_info(commit)}.'
                        f'{" Please clarify commit hash for more identity." if is_short_commit else ""}')
-            if self._logger:
-                self._logger.warning(message)
-            raise CommandError(message)
+            self.add_log(message, style_func=self.style.ERROR, log_level=logging.WARNING)
+            raise CommandError()
 
         return queryset.first()
 
+    def search_commit(self, commit):
+        apps_state = self.get_apps_state_by_commit(commit)
+        return apps_state.commit
+
     def get_migrations_data_by_commit(self, commit):
         apps_state = self.get_apps_state_by_commit(commit)
         return json.loads(apps_state.migrations)
@@ -117,9 +207,11 @@ def get_migrations_diff(self, current, other):
                 'zero' if is_new_app else list(filter(lambda x: x.app == migration.app, other))[0].name,
             ))
 
-        if self._logger:
-            self._logger.info(f'Migrations diff:\n{result}')
-
+        if result:
+            self.add_log(f'Found migrations diff. In case of rollback need migrate to:\n{result}',
+                         log_level=logging.WARNING)
+        else:
+            self.add_log(f'Diff not found. There is no migrations to rollback.')
         return result
 
     def run_rollback(self, migrations_diff_records, fake=False):
@@ -129,27 +221,16 @@ def run_rollback(self, migrations_diff_records, fake=False):
         """
 
         if not migrations_diff_records:
-            message = 'There is no migrations to rollback.'
-            self.stdout.write(f'>>> {message}')
-            if self._logger:
-                self._logger.info(message)
+            self.add_log('There is no migrations to rollback.')
             return
 
         for migration in sorted(migrations_diff_records, key=lambda r: int(r.id), reverse=True):
             execute_args = (MIGRATE_COMMAND, migration.app, migration.name)
-            message = f'Executing command: {" ".join(execute_args)}'
-            self.stdout.write(f'>>> {message}')
-            if self._logger:
-                self._logger.info(message)
-
+            self.add_log(f'Executing command: `{" ".join(execute_args)}`' + (' (executing faked)' if fake else ''))
             if not fake:
-                call_command(*execute_args)
+                call_command(*execute_args, stdout=self._out)
 
     def make_the_last_state_for_commit(self, commit):
         apps_state = self.get_apps_state_by_commit(commit)
         AppsState.objects.filter(id__gt=apps_state.id).delete()
-
-        message = f'state for commit "{commit}" now is the last state in DB'
-        self.stdout.write(f'>>> {message}')
-        if self._logger:
-            self._logger.info(message)
+        self.add_log(f'state for commit {self.get_commit_info(commit)} now is the last state in DB')