25023 Add more loggings for affiliation call and others

legal-api/src/legal_api/services/bootstrap.py

@@ -150,13 +150,15 @@ def create_affiliation(cls, account: int,
                            details: dict = None,
                            flags: any = None):
         """Affiliate a business to an account."""
+        current_app.logger.info(f'Creating affiliation of {business_registration} for {account}')
         auth_url = current_app.config.get('AUTH_SVC_URL')
         account_svc_entity_url = f'{auth_url}/entities'
         account_svc_affiliate_url = f'{auth_url}/orgs/{account}/affiliations'
 
         token = cls.get_bearer_token()
 
         if not token:
+            current_app.logger.info('Missing token for affiliation call')
             return HTTPStatus.UNAUTHORIZED
 
         # Create an entity record
@@ -244,6 +246,7 @@ def delete_affiliation(cls, account: int, business_registration: str) -> Dict:
 
         @TODO Update this when account affiliation is changed next sprint.
         """
+        current_app.logger.info(f'Deleting affiliation of {business_registration} for {account}')
         auth_url = current_app.config.get('AUTH_SVC_URL')
         account_svc_entity_url = f'{auth_url}/entities'
         account_svc_affiliate_url = f'{auth_url}/orgs/{account}/affiliations'

queue_services/entity-filer/filer_service.py

@@ -21,26 +21,37 @@
 from entity_filer.resources import register_endpoints
 from entity_filer.worker import APP_CONFIG, FLASK_APP, cb_subscription_handler, flags, qsm
 from entity_queue_common.service_utils import logger
+from structured_logging import StructuredLogging
+
+
+def setup_logger(app, flag_on):
+    if flag_on:
+        app.logger = StructuredLogging.get_logger()
+    else:
+        app.logger = logger
 
 
 if __name__ == '__main__':
     # This flag is added specifically for the sandbox environment.
     with FLASK_APP.app_context():
         flag_on = flags.is_on("enable-sandbox")
-    logger.debug(f"enable-sandbox flag on: {flag_on}")
 
-    if flag_on:
-        # GCP Queue
-        register_endpoints(FLASK_APP)
-        server_port = os.environ.get("PORT", "8080")
-        FLASK_APP.run(debug=False, port=server_port, host="0.0.0.0")
-    else:
-        # NATS Queue
-        event_loop = asyncio.get_event_loop()
-        event_loop.run_until_complete(qsm.run(loop=event_loop,
-                                            config=APP_CONFIG,
-                                            callback=cb_subscription_handler))
-        try:
-            event_loop.run_forever()
-        finally:
-            event_loop.close()
+        setup_logger(FLASK_APP, flag_on)
+        FLASK_APP.logger.debug(f"enable-sandbox flag on: {flag_on}")
+
+        if flag_on:
+            # GCP Queue
+            register_endpoints(FLASK_APP)
+            server_port = os.environ.get("PORT", "8080")
+            FLASK_APP.run(debug=False, port=server_port, host="0.0.0.0")
+        else:
+            # NATS Queue
+            logger.debug('asdfasdf')
+            event_loop = asyncio.get_event_loop()
+            event_loop.run_until_complete(qsm.run(loop=event_loop,
+                                                config=APP_CONFIG,
+                                                callback=cb_subscription_handler))
+            try:
+                event_loop.run_forever()
+            finally:
+                event_loop.close()

queue_services/entity-filer/src/entity_filer/filing_processors/admin_freeze.py

@@ -16,7 +16,8 @@
 from typing import Dict
 
 import dpath
-from entity_queue_common.service_utils import QueueException, logger
+from entity_queue_common.service_utils import QueueException
+from flask import current_app
 from legal_api.models import Business, Filing
 
 from entity_filer.filing_meta import FilingMeta
@@ -25,10 +26,10 @@
 def process(business: Business,  filing: Dict, filing_rec: Filing, filing_meta: FilingMeta):
     """Render the admin freeze filing unto the model objects."""
     if not (admin_freeze_filing := filing.get('adminFreeze')):
-        logger.error('Could not find adminFreeze in: %s', filing)
+        current_app.logger.error('Could not find adminFreeze in: %s', filing)
         raise QueueException(f'legal_filing:adminFreeze missing from {filing}')
 
-    logger.debug('processing adminFreeze: %s', filing)
+    current_app.logger.debug('processing adminFreeze: %s', filing)
 
     freeze = bool(dpath.util.get(admin_freeze_filing, '/freeze'))
     business.admin_freeze = freeze

queue_services/entity-filer/src/entity_filer/filing_processors/annual_report.py

@@ -16,7 +16,7 @@
 from contextlib import suppress
 from typing import Dict
 
-from entity_queue_common.service_utils import logger
+from flask import current_app
 from legal_api.models import BatchProcessing, Business
 from legal_api.services.filings import validations
 from legal_api.services.involuntary_dissolution import InvoluntaryDissolutionService
@@ -34,7 +34,7 @@ def process(business: Business, filing: Dict, filing_meta: FilingMeta, flag_on):
         ar_date = datetime.date.fromisoformat(ar_date)
     else:
         # should never get here (schema validation should prevent this from making it to the filer)
-        logger.error('No annualReportDate given for in annual report. Filing id: %s', filing.id)
+        current_app.logger.error('No annualReportDate given for in annual report. Filing id: %s', filing.id)
 
     business.last_ar_date = ar_date
     if agm_date and validations.annual_report.requires_agm(business):

queue_services/entity-filer/src/entity_filer/filing_processors/change_of_directors.py

@@ -15,7 +15,8 @@
 from datetime import datetime
 from typing import Dict
 
-from entity_queue_common.service_utils import QueueException, logger
+from entity_queue_common.service_utils import QueueException
+from flask import current_app
 from legal_api.models import Business, PartyRole
 
 from entity_filer.filing_meta import FilingMeta
@@ -79,7 +80,7 @@ def process(business: Business, filing: Dict, filing_meta: FilingMeta):  # pylin
                 else new_director['officer'].get('prevFirstName') + \
                 new_director['officer'].get('prevMiddleInitial') + new_director['officer'].get('prevLastName')
             if not new_director_name:
-                logger.error('Could not resolve director name from json %s.', new_director)
+                current_app.logger.error('Could not resolve director name from json %s.', new_director)
                 raise QueueException
 
             for director in PartyRole.get_parties_by_role(business.id, PartyRole.RoleTypes.DIRECTOR.value):

queue_services/entity-filer/src/entity_filer/filing_processors/change_of_name.py

@@ -14,15 +14,15 @@
 """File processing rules and actions for the Change of Name filing."""
 from typing import Dict
 
-from entity_queue_common.service_utils import logger
+from flask import current_app
 from legal_api.models import Business
 
 from entity_filer.filing_meta import FilingMeta
 
 
 def process(business: Business, filing: Dict, filing_meta: FilingMeta):
     """Render the change of name into the business model objects."""
-    logger.debug('processing Change of Name: %s', filing)
+    current_app.logger.debug('processing Change of Name: %s', filing)
 
     if name_request_json := filing['changeOfName'].get('nameRequest'):
         new_name = name_request_json.get('legalName')

queue_services/entity-filer/src/entity_filer/filing_processors/dissolution.py

@@ -17,7 +17,8 @@
 
 import dpath
 import sentry_sdk
-from entity_queue_common.service_utils import QueueException, logger
+from entity_queue_common.service_utils import QueueException
+from flask import current_app
 from legal_api.models import BatchProcessing, Business, Document, Filing, db
 from legal_api.models.document import DocumentType
 from legal_api.services.filings.validations.dissolution import DissolutionTypes
@@ -36,10 +37,10 @@
 def process(business: Business, filing: Dict, filing_rec: Filing, filing_meta: FilingMeta, flag_on: bool = False):
     """Render the dissolution filing unto the model objects."""
     if not (dissolution_filing := filing.get('dissolution')):
-        logger.error('Could not find Dissolution in: %s', filing)
+        current_app.logger.error('Could not find Dissolution in: %s', filing)
         raise QueueException(f'legal_filing:Dissolution missing from {filing}')
 
-    logger.debug('processing dissolution: %s', filing)
+    current_app.logger.debug('processing dissolution: %s', filing)
 
     filing_meta.dissolution = {}
     dissolution_type = dpath.util.get(filing, '/dissolution/dissolutionType')
@@ -75,7 +76,7 @@ def process(business: Business, filing: Dict, filing_rec: Filing, filing_meta: F
         if office := create_office(business, 'custodialOffice', custodial_office):
             business.offices.append(office)
         else:
-            logger.error('Could not create custodial office for Dissolution in: %s', filing)
+            current_app.logger.error('Could not create custodial office for Dissolution in: %s', filing)
             sentry_sdk.capture_message(
                 f'Queue Error: Could not create custodial office for Dissolution filing:{filing.id}',
                 level='error')

queue_services/entity-filer/src/entity_filer/filing_processors/filing_components/business_profile.py

@@ -31,6 +31,7 @@
 def update_business_profile(business: Business, filing: Filing, filing_type: str = None, flags: Flags = None):
     """Update business profile."""
     if flags.is_on('enable-sandbox'):
+        current_app.logger.info('Skip updating business profile')
         return
 
     filing_type = filing_type if filing_type else filing.filing_type
@@ -99,6 +100,7 @@ def _update_business_profile(business: Business, profile_info: Dict) -> Dict:
 def update_affiliation(business: Business, filing: Filing, flags: Flags = None):
     """Create an affiliation for the business and remove the bootstrap."""
     try:
+        current_app.logger.info('Updating affiliation for business')
         bootstrap = RegistrationBootstrap.find_by_identifier(filing.temp_reg)
 
         pass_code = ''
@@ -127,6 +129,7 @@ def update_affiliation(business: Business, filing: Filing, flags: Flags = None):
 
         if rv not in (HTTPStatus.OK, HTTPStatus.CREATED):
             deaffiliation = AccountService.delete_affiliation(bootstrap.account, business.identifier)
+            current_app.logger.error(f'Unable to affiliate business:{business.identifier} for filing:{filing.id}')
             sentry_sdk.capture_message(
                 f'Queue Error: Unable to affiliate business:{business.identifier} for filing:{filing.id}',
                 level='error'
@@ -145,6 +148,7 @@ def update_affiliation(business: Business, filing: Filing, flags: Flags = None):
                 or ('bootstrap_update' in locals() and bootstrap_update != HTTPStatus.OK)):
             raise QueueException
     except Exception as err:  # pylint: disable=broad-except; note out any exception, but don't fail the call
+        current_app.logger.error(f'Affiliation error for filing:{filing.id}, with err:{err}')
         sentry_sdk.capture_message(
             f'Queue Error: Affiliation error for filing:{filing.id}, with err:{err}',
             level='error'

queue_services/entity-filer/src/entity_filer/filing_processors/filing_components/name_request.py

@@ -17,7 +17,7 @@
 
 import requests
 import sentry_sdk
-from entity_queue_common.service_utils import QueueException, logger
+from entity_queue_common.service_utils import QueueException
 from flask import current_app
 from legal_api.models import Business, Filing, RegistrationBootstrap
 from legal_api.services import AccountService, Flags
@@ -28,6 +28,7 @@ def consume_nr(business: Business, filing: Filing, filing_type: str = None, flag
     """Update the nr to a consumed state."""
     try:
         if flags.is_on('enable-sandbox'):
+            current_app.logger.info('Skip consuming NR')
             return
 
         filing_type = filing_type if filing_type else filing.filing_type
@@ -37,7 +38,7 @@ def consume_nr(business: Business, filing: Filing, filing_type: str = None, flag
             namex_svc_url = current_app.config.get('NAMEX_API')
             token = AccountService.get_bearer_token()
             if flags and (flag_on := flags.is_on('namex-nro-decommissioned')):
-                logger.debug('namex-nro-decommissioned flag: %s', flag_on)
+                current_app.logger.debug('namex-nro-decommissioned flag: %s', flag_on)
                 data = json.dumps({'state': 'CONSUMED', 'corpNum': business.identifier})
             else:
                 data = json.dumps({'consume': {'corpNum': business.identifier}})

queue_services/entity-filer/src/entity_filer/filing_processors/put_back_on.py

@@ -17,7 +17,8 @@
 from typing import Dict
 
 import dpath
-from entity_queue_common.service_utils import QueueException, logger
+from entity_queue_common.service_utils import QueueException
+from flask import current_app
 from legal_api.models import Business, Filing, Office, OfficeType, db
 
 from entity_filer.filing_meta import FilingMeta
@@ -28,10 +29,10 @@
 def process(business: Business, filing: Dict, filing_rec: Filing, filing_meta: FilingMeta):
     """Render the put back on filing unto the model objects."""
     if not (put_back_on_filing := filing.get('putBackOn')):
-        logger.error('Could not find putBackOn in: %s', filing)
+        current_app.logger.error('Could not find putBackOn in: %s', filing)
         raise QueueException(f'legal_filing:putBackOn missing from {filing}')
 
-    logger.debug('processing putBackOn: %s', filing)
+    current_app.logger.debug('processing putBackOn: %s', filing)
 
     # update court order, if any is present
     with suppress(IndexError, KeyError, TypeError):

queue_services/entity-filer/src/entity_filer/filing_processors/special_resolution.py

@@ -13,13 +13,13 @@
 from typing import Dict
 
 from dateutil.parser import parse
-from entity_queue_common.service_utils import logger
+from flask import current_app
 from legal_api.models import Business, Filing, Party, Resolution
 
 
 def process(business: Business, filing: Dict, filing_rec: Filing):
     """Render the special resolution filing unto the model objects."""
-    logger.debug('Processing Special Resolution : %s', filing)
+    current_app.logger.debug('Processing Special Resolution : %s', filing)
     if (resolution_filing := filing.get('specialResolution')):
         resolution = Resolution(
             resolution=resolution_filing.get('resolution'),

queue_services/entity-filer/src/entity_filer/resources/worker.py

@@ -41,14 +41,12 @@
 
 from flask import Blueprint, current_app, request
 from gcp_queue import SimpleCloudEvent
-from structured_logging import StructuredLogging
 
 from entity_filer.services import gcp_queue, verify_gcp_jwt
 from entity_filer.worker import process_filing
 
 
 bp = Blueprint('worker', __name__)
-logger = StructuredLogging.get_logger()
 loop = asyncio.get_event_loop()
 
 
@@ -68,14 +66,14 @@ def worker():
     - Filings that cannot be processed are knocked off the Q
     """
     if not request.data:
-        logger.debug('No incoming raw msg.')
+        current_app.logger.debug('No incoming raw msg.')
         return {}, HTTPStatus.OK
 
     if msg := verify_gcp_jwt(request):
-        logger.info(msg)
+        current_app.logger.info(msg)
         return {}, HTTPStatus.FORBIDDEN
 
-    logger.info(f'Incoming raw msg: {str(request.data)}')
+    current_app.logger.info(f'Incoming raw msg: {str(request.data)}')
 
     # 1. Get cloud event
     # ##
@@ -85,28 +83,28 @@ def worker():
         #
         # Decision here is to return a 200,
         # so the event is removed from the Queue
-        logger.debug(f'ignoring message, raw payload: {str(ce)}')
+        current_app.logger.debug(f'ignoring message, raw payload: {str(ce)}')
         return {}, HTTPStatus.OK
-    logger.info(f'received ce: {str(ce)}')
+    current_app.logger.info(f'received ce: {str(ce)}')
 
     # 2. Get filing_message information
     # ##
     if not (filing_message := get_filing_message(ce)):
         # no filing_message info, take off Q
-        logger.debug(f'no filing_message info in: {ce}')
+        current_app.logger.debug(f'no filing_message info in: {ce}')
         return {'message': 'no filing info in cloud event'}, HTTPStatus.OK
-    logger.info(f'Incoming filing_message: {filing_message}')
+    current_app.logger.info(f'Incoming filing_message: {filing_message}')
 
     # 3. Process Filing
     # ##
     try:
         loop.run_until_complete(process_filing(filing_message, current_app))
     except Exception as err:  # pylint: disable=broad-exception-caught
-        logger.error(f'Error processing filing {filing_message}: {err}')
-        logger.debug(traceback.format_exc())
+        current_app.logger.error(f'Error processing filing {filing_message}: {err}')
+        current_app.logger.debug(traceback.format_exc())
         return {'error': f'Unable to process filing: {filing_message}'}, HTTPStatus.INTERNAL_SERVER_ERROR
 
-    logger.info(f'completed ce: {str(ce)}')
+    current_app.logger.info(f'completed ce: {str(ce)}')
     return {}, HTTPStatus.OK
 
 

queue_services/entity-filer/src/entity_filer/services/gcp_auth.py

@@ -35,29 +35,25 @@
 from flask import current_app
 from google.auth.transport import requests
 from google.oauth2 import id_token
-from structured_logging import StructuredLogging
-
-
-logger = StructuredLogging.get_logger()
 
 
 def verify_gcp_jwt(flask_request):
     """Verify the bearer token as sign by gcp oauth."""
     msg = ''
     try:
         bearer_token = flask_request.headers.get('Authorization')
-        logger.debug('bearer_token %s', bearer_token)
+        current_app.logger.debug('bearer_token %s', bearer_token)
         token = bearer_token.split(' ')[1]
         audience = current_app.config.get('SUB_AUDIENCE')
-        logger.debug('audience %s', audience)
+        current_app.logger.debug('audience %s', audience)
         claim = id_token.verify_oauth2_token(
             token, requests.Request(), audience=audience
         )
         sa_email = current_app.config.get('SUB_SERVICE_ACCOUNT')
-        logger.debug('sa_email %s', sa_email)
+        current_app.logger.debug('sa_email %s', sa_email)
         if not claim['email_verified'] or claim['email'] != sa_email:
             msg = f"Invalid service account or email not verified for email: {claim['email']}\n"
-        logger.debug('claim %s', claim)
+        current_app.logger.debug('claim %s', claim)
 
     except Exception as err:  # pylint: disable=broad-exception-caught
         msg = f'Invalid token: {err}\n'