Merge pull request #4 from Leits/master

Planned auction for tender

openprocurement/chronograph/__init__.py

@@ -9,18 +9,14 @@
 from datetime import datetime, timedelta
 #from openprocurement.chronograph.jobstores import CouchDBJobStore
 from openprocurement.chronograph.scheduler import push
+from openprocurement.chronograph.utils import add_logging_context
 from pyramid.config import Configurator
 from pytz import timezone
 from pyramid.events import ApplicationCreated, ContextFound, BeforeRender
 from pbkdf2 import PBKDF2
 
-try:
-    from systemd.journal import JournalHandler
-except ImportError:
-    JournalHandler = False
+LOG = getLogger(__name__)
 
-INIT_LOGGER = getLogger("{}.init".format(__name__))
-LOGGER = getLogger(__name__)
 TZ = timezone(os.environ['TZ'] if 'TZ' in os.environ else 'Europe/Kiev')
 SECURITY = {u'admins': {u'names': [], u'roles': ['_admin']}, u'members': {u'names': [], u'roles': ['_admin']}}
 VALIDATE_DOC_ID = '_design/_auth'
@@ -39,35 +35,6 @@
 }"""
 
 
-def set_journal_handler(event):
-    request = event.request
-    params = {
-        'TENDERS_API_URL': request.registry.api_url,
-        'TAGS': 'python,chronograph',
-        'CURRENT_URL': request.url,
-        'CURRENT_PATH': request.path_info,
-        'REMOTE_ADDR': request.remote_addr or '',
-        'USER_AGENT': request.user_agent or '',
-        'TENDER_ID': '',
-        'TIMESTAMP': datetime.now(TZ).isoformat(),
-        'REQUEST_ID': request.environ.get('REQUEST_ID', ''),
-        'CLIENT_REQUEST_ID': request.headers.get('X-Client-Request-ID', ''),
-    }
-    if request.params:
-        params['PARAMS'] = str(dict(request.params))
-    if request.matchdict:
-        for i, j in request.matchdict.items():
-            params[i.upper()] = j
-    for i in LOGGER.handlers:
-        LOGGER.removeHandler(i)
-    LOGGER.addHandler(JournalHandler(**params))
-
-
-def clear_journal_handler(event):
-    for i in LOGGER.handlers:
-        LOGGER.removeHandler(i)
-
-
 def start_scheduler(event):
     app = event.app
     app.registry.scheduler.start()
@@ -77,9 +44,7 @@ def main(global_config, **settings):
     """ This function returns a Pyramid WSGI application.
     """
     config = Configurator(settings=settings)
-    if JournalHandler:
-        config.add_subscriber(set_journal_handler, ContextFound)
-        config.add_subscriber(clear_journal_handler, BeforeRender)
+    config.add_subscriber(add_logging_context, ContextFound)
     config.include('pyramid_exclog')
     config.add_route('home', '/')
     config.add_route('resync_all', '/resync_all')
@@ -103,7 +68,7 @@ def main(global_config, **settings):
         aserver = Server(settings.get('couchdb.admin_url'), session=Session(retry_delays=range(10)))
         users_db = aserver['_users']
         if SECURITY != users_db.security:
-            INIT_LOGGER.info("Updating users db security", extra={'MESSAGE_ID': 'update_users_security'})
+            LOG.info("Updating users db security", extra={'MESSAGE_ID': 'update_users_security'})
             users_db.security = SECURITY
         username, password = server.resource.credentials
         user_doc = users_db.get('org.couchdb.user:{}'.format(username), {'_id': 'org.couchdb.user:{}'.format(username)})
@@ -114,20 +79,20 @@ def main(global_config, **settings):
                 "type": "user",
                 "password": password
             })
-            INIT_LOGGER.info("Updating chronograph db main user", extra={'MESSAGE_ID': 'update_chronograph_main_user'})
+            LOG.info("Updating chronograph db main user", extra={'MESSAGE_ID': 'update_chronograph_main_user'})
             users_db.save(user_doc)
         security_users = [username, ]
         if db_name not in aserver:
             aserver.create(db_name)
         db = aserver[db_name]
         SECURITY[u'members'][u'names'] = security_users
         if SECURITY != db.security:
-            INIT_LOGGER.info("Updating chronograph db security", extra={'MESSAGE_ID': 'update_chronograph_security'})
+            LOG.info("Updating chronograph db security", extra={'MESSAGE_ID': 'update_chronograph_security'})
             db.security = SECURITY
         auth_doc = db.get(VALIDATE_DOC_ID, {'_id': VALIDATE_DOC_ID})
         if auth_doc.get('validate_doc_update') != VALIDATE_DOC_UPDATE % username:
             auth_doc['validate_doc_update'] = VALIDATE_DOC_UPDATE % username
-            INIT_LOGGER.info("Updating chronograph db validate doc", extra={'MESSAGE_ID': 'update_chronograph_validate_doc'})
+            LOG.info("Updating chronograph db validate doc", extra={'MESSAGE_ID': 'update_chronograph_validate_doc'})
             db.save(auth_doc)
     else:
         if db_name not in server:

openprocurement/chronograph/scheduler.py

@@ -9,6 +9,7 @@
 from time import sleep
 from random import randint
 from logging import getLogger
+from openprocurement.chronograph.utils import context_unpack
 
 
 LOG = getLogger(__name__)
@@ -95,6 +96,7 @@ def planning_auction(tender, start, db, quick=False, lot_id=None):
     mode = tender.get('mode', '')
     calendar = get_calendar(db)
     streams = get_streams(db)
+    skipped_days = 0
     if quick:
         quick_start = calc_auction_end_time(0, start)
         return quick_start
@@ -110,6 +112,7 @@ def planning_auction(tender, start, db, quick=False, lot_id=None):
         dayStart, stream, plan = get_date(db, mode, nextDate)
         if dayStart >= WORKING_DAY_END and stream >= streams:
             nextDate += timedelta(days=1)
+            skipped_days += 1
             continue
         if dayStart >= WORKING_DAY_END and stream < streams:
             stream += 1
@@ -122,15 +125,23 @@ def planning_auction(tender, start, db, quick=False, lot_id=None):
         elif end <= TZ.localize(datetime.combine(nextDate, WORKING_DAY_END)):
             break
         nextDate += timedelta(days=1)
+        skipped_days += 1
     #for n in range((end.date() - start.date()).days):
         #date = start.date() + timedelta(n)
         #_, dayStream = get_date(db, mode, date.date())
         #set_date(db, mode, date.date(), WORKING_DAY_END, dayStream+1)
     set_date(db, plan, end.time(), stream, "_".join([tid, lot_id]) if lot_id else tid, dayStart)
-    return start
+    return (start, stream, skipped_days)
 
 
-def check_tender(tender, db):
+def skipped_days(days):
+    days_str = ''
+    if days:
+        days_str = ' Skipped {} full days.'.format(days)
+    return days_str
+
+
+def check_tender(request, tender, db):
     enquiryPeriodEnd = tender.get('enquiryPeriod', {}).get('endDate')
     enquiryPeriodEnd = enquiryPeriodEnd and parse_date(enquiryPeriodEnd, TZ).astimezone(TZ)
     tenderPeriodStart = tender.get('tenderPeriod', {}).get('startDate')
@@ -149,12 +160,14 @@ def check_tender(tender, db):
         quick = os.environ.get('SANDBOX_MODE', False) and u'quick' in tender.get('submissionMethodDetails', '')
         while not planned:
             try:
-                auctionPeriod = planning_auction(tender, tenderPeriodEnd, db, quick)
+                auctionPeriod, stream, skip_days = planning_auction(tender, tenderPeriodEnd, db, quick)
                 planned = True
             except ResourceConflict:
                 planned = False
         auctionPeriod = randomize(auctionPeriod).isoformat()
-        LOG.info('Planned auction for tender {} to {}'.format(tender['id'], auctionPeriod))
+        LOG.info('Planned auction for tender {} to {}. Stream {}.{}'.format(tender['id'], auctionPeriod, stream, skipped_days(skip_days)),
+                extra=context_unpack(request, {'MESSAGE_ID': 'planned_auction_tender'}, {'PLANNED_DATE': auctionPeriod, 'PLANNED_STREAM': stream,
+                'PLANNED_DAYS_SKIPPED': skip_days}))
         return {'auctionPeriod': {'startDate': auctionPeriod}}, now
     elif tender.get('lots') and tender['status'] == 'active.tendering' and any([not lot.get('auctionPeriod') for lot in tender['lots'] if lot['status'] == 'active']) and tenderPeriodEnd and tenderPeriodEnd > now:
         quick = os.environ.get('SANDBOX_MODE', False) and u'quick' in tender.get('submissionMethodDetails', '')
@@ -167,13 +180,15 @@ def check_tender(tender, db):
             planned = False
             while not planned:
                 try:
-                    auctionPeriod = planning_auction(tender, tenderPeriodEnd, db, quick, lot_id)
+                    auctionPeriod, stream, skip_days = planning_auction(tender, tenderPeriodEnd, db, quick, lot_id)
                     planned = True
                 except ResourceConflict:
                     planned = False
             auctionPeriod = randomize(auctionPeriod).isoformat()
             lots.append({'auctionPeriod': {'startDate': auctionPeriod}})
-            LOG.info('Planned auction for lot {} of tender {} to {}'.format(lot_id, tender['id'], auctionPeriod))
+            LOG.info('Planned auction for lot {} of tender {} to {}. Stream {}.{}'.format(lot_id, tender['id'], auctionPeriod, stream, skipped_days(skip_days)),
+                    extra=context_unpack(request, {'MESSAGE_ID': 'planned_auction_lot'}, {'PLANNED_DATE': auctionPeriod, 'PLANNED_STREAM': stream,
+                    'PLANNED_DAYS_SKIPPED':skip_days, 'LOT_ID':lot_id}))
         return {'lots': lots}, now
     elif not tender.get('lots') and tender['status'] == 'active.tendering' and tenderPeriodEnd and tenderPeriodEnd <= now:
         LOG.info('Switched tender {} to {}'.format(tender['id'], 'active.auction'))
@@ -195,12 +210,14 @@ def check_tender(tender, db):
         quick = os.environ.get('SANDBOX_MODE', False) and u'quick' in tender.get('submissionMethodDetails', '')
         while not planned:
             try:
-                auctionPeriod = planning_auction(tender, tenderPeriodEnd, db, quick)
+                auctionPeriod, stream, skip_days = planning_auction(tender, tenderPeriodEnd, db, quick)
                 planned = True
             except ResourceConflict:
                 planned = False
         auctionPeriod = randomize(auctionPeriod).isoformat()
-        LOG.info('Planned auction for tender {} to {}'.format(tender['id'], auctionPeriod))
+        LOG.info('Planned auction for tender {} to {}. Stream {}.{}'.format(tender['id'], auctionPeriod, stream, skipped_days(skip_days)),
+                extra=context_unpack(request, {'MESSAGE_ID': 'planned_auction_tender'}, {'PLANNED_DATE': auctionPeriod, 'PLANNED_STREAM': stream,
+                'PLANNED_DAYS_SKIPPED':skip_days}))
         return {'auctionPeriod': {'startDate': auctionPeriod}}, now
     elif not tender.get('lots') and tender['status'] == 'active.auction' and tender.get('auctionPeriod'):
         tenderAuctionStart = parse_date(tender.get('auctionPeriod', {}).get('startDate'), TZ).astimezone(TZ)
@@ -210,12 +227,14 @@ def check_tender(tender, db):
             quick = os.environ.get('SANDBOX_MODE', False) and u'quick' in tender.get('submissionMethodDetails', '')
             while not planned:
                 try:
-                    auctionPeriod = planning_auction(tender, now, db, quick)
+                    auctionPeriod, stream, skip_days = planning_auction(tender, now, db, quick)
                     planned = True
                 except ResourceConflict:
                     planned = False
             auctionPeriod = randomize(auctionPeriod).isoformat()
-            LOG.info('Replanned auction for tender {} to {}'.format(tender['id'], auctionPeriod))
+            LOG.info('Replanned auction for tender {} to {}. Stream {}.{}'.format(tender['id'], auctionPeriod, stream, skipped_days(skip_days)),
+                    extra=context_unpack(request, {'MESSAGE_ID': 'replanned_auction_tender'}, {'PLANNED_DATE': auctionPeriod, 'PLANNED_STREAM': stream,
+                    'PLANNED_DAYS_SKIPPED':skip_days}))
             return {'auctionPeriod': {'startDate': auctionPeriod}}, now
         else:
             return None, tenderAuctionEnd + MIN_PAUSE
@@ -230,13 +249,16 @@ def check_tender(tender, db):
             planned = False
             while not planned:
                 try:
-                    auctionPeriod = planning_auction(tender, tenderPeriodEnd, db, quick, lot_id)
+                    auctionPeriod, stream, skip_days = planning_auction(tender, tenderPeriodEnd, db, quick, lot_id)
                     planned = True
                 except ResourceConflict:
                     planned = False
             auctionPeriod = randomize(auctionPeriod).isoformat()
             lots.append({'auctionPeriod': {'startDate': auctionPeriod}})
-            LOG.info('Planned auction for lot {} of tender {} to {}'.format(lot_id, tender['id'], auctionPeriod))
+            LOG.info('Planned auction for lot {} of tender {} to {}. Stream {}.{}'.format(lot_id, tender['id'], auctionPeriod, stream, skipped_days(skip_days)),
+                    extra=context_unpack(request, {'MESSAGE_ID': 'planned_auction_lot'}, {'PLANNED_DATE': auctionPeriod, 'PLANNED_STREAM': stream,
+                    'PLANNED_DAYS_SKIPPED':skip_days, 'LOT_ID':lot_id}))
+
         return {'lots': lots}, now
     elif tender.get('lots') and tender['status'] == 'active.auction':
         quick = os.environ.get('SANDBOX_MODE', False) and u'quick' in tender.get('submissionMethodDetails', '')
@@ -253,13 +275,15 @@ def check_tender(tender, db):
                 planned = False
                 while not planned:
                     try:
-                        auctionPeriod = planning_auction(tender, now, db, quick, lot_id)
+                        auctionPeriod, stream, skip_days = planning_auction(tender, now, db, quick, lot_id)
                         planned = True
                     except ResourceConflict:
                         planned = False
                 auctionPeriod = randomize(auctionPeriod).isoformat()
                 lots.append({'auctionPeriod': {'startDate': auctionPeriod}})
-                LOG.info('Replanned auction for lot {} of tender {} to {}'.format(lot_id, tender['id'], auctionPeriod))
+                LOG.info('Replanned auction for lot {} of tender {} to {}. Stream {}.{}'.format(lot_id, tender['id'], auctionPeriod, stream, skipped_days(skip_days)),
+                        extra=context_unpack(request, {'MESSAGE_ID': 'replanned_auction_lot'}, {'PLANNED_DATE': auctionPeriod, 'PLANNED_STREAM': stream,
+                        'PLANNED_DAYS_SKIPPED':skip_days, 'LOT_ID':lot_id}))
             else:
                 lots_ends.append(lotAuctionEnd + MIN_PAUSE)
         if any(lots):
@@ -370,7 +394,14 @@ def push(url, params):
         tx, ty = ty, tx + ty
 
 
-def resync_tender(scheduler, url, api_token, callback_url, db, tender_id, request_id):
+def resync_tender(request):
+    tender_id = request.matchdict['tender_id']
+    scheduler = request.registry.scheduler
+    url = request.registry.api_url + 'tenders/' + tender_id
+    api_token = request.registry.api_token
+    callback_url = request.registry.callback_url + 'resync/' + tender_id
+    db = request.registry.db
+    request_id = request.environ.get('REQUEST_ID', '')
     r = get_request(url, auth=(api_token, ''), headers={'X-Client-Request-ID': request_id})
     if r.status_code != requests.codes.ok:
         LOG.error("Error {} on getting tender '{}': {}".format(r.status_code, url, r.text))
@@ -381,7 +412,7 @@ def resync_tender(scheduler, url, api_token, callback_url, db, tender_id, reques
     else:
         json = r.json()
         tender = json['data']
-        changes, next_check = check_tender(tender, db)
+        changes, next_check = check_tender(request, tender, db)
         if changes:
             data = dumps({'data': changes})
             r = requests.patch(url,

openprocurement/chronograph/tests/test.py

@@ -501,26 +501,26 @@ def test_auction_quick_planning(self):
 
     def test_auction_planning_overlow(self):
         now = datetime.now(TZ)
-        res = planning_auction(test_tender_data_test_quick, now, self.db)
+        res = planning_auction(test_tender_data_test_quick, now, self.db)[0]
         startDate = res.date()
         count = 0
         while startDate == res.date():
             count += 1
-            res = planning_auction(test_tender_data_test_quick, now, self.db)
+            res = planning_auction(test_tender_data_test_quick, now, self.db)[0]
         self.assertEqual(count, 100)
 
     def test_auction_planning_buffer(self):
         some_date = datetime(2015, 9, 21, 6, 30)
         date = some_date.date()
         ndate = (some_date + timedelta(days=1)).date()
-        res = planning_auction(test_tender_data_test_quick, some_date, self.db)
+        res = planning_auction(test_tender_data_test_quick, some_date, self.db)[0]
         self.assertEqual(res.date(), date)
         some_date = some_date.replace(hour=10)
-        res = planning_auction(test_tender_data_test_quick, some_date, self.db)
+        res = planning_auction(test_tender_data_test_quick, some_date, self.db)[0]
         self.assertNotEqual(res.date(), date)
         self.assertEqual(res.date(), ndate)
         some_date = some_date.replace(hour=16)
-        res = planning_auction(test_tender_data_test_quick, some_date, self.db)
+        res= planning_auction(test_tender_data_test_quick, some_date, self.db)[0]
         self.assertNotEqual(res.date(), date)
         self.assertEqual(res.date(), ndate)
 

openprocurement/chronograph/utils.py

@@ -0,0 +1,46 @@
+import os
+from datetime import datetime
+from pytz import timezone
+
+TZ = timezone(os.environ['TZ'] if 'TZ' in os.environ else 'Europe/Kiev')
+
+
+def add_logging_context(event):
+    request = event.request
+    params = {
+        'TENDERS_API_URL': request.registry.api_url,
+        'TAGS': 'python,chronograph',
+        'CURRENT_URL': request.url,
+        'CURRENT_PATH': request.path_info,
+        'REMOTE_ADDR': request.remote_addr or '',
+        'USER_AGENT': request.user_agent or '',
+        'TENDER_ID': '',
+        'TIMESTAMP': datetime.now(TZ).isoformat(),
+        'REQUEST_ID': request.environ.get('REQUEST_ID', ''),
+        'CLIENT_REQUEST_ID': request.headers.get('X-Client-Request-ID', ''),
+    }
+    if request.params:
+        params['PARAMS'] = str(dict(request.params))
+    if request.matchdict:
+        for i, j in request.matchdict.items():
+            params[i.upper()] = j
+
+    request.logging_context = params
+
+
+def update_logging_context(request, params):
+    if not request.__dict__.get('logging_context'):
+        request.logging_context = {}
+
+    for x, j in params.items():
+        request.logging_context[x.upper()] = j
+
+
+def context_unpack(request, msg, params=None):
+    if params:
+        update_logging_context(request, params)
+    logging_context = request.logging_context
+    journal_context = msg
+    for key, value in logging_context.items():
+        journal_context["JOURNAL_" + key] = value
+    return journal_context

openprocurement/chronograph/views.py

@@ -34,16 +34,7 @@ def resync_all(request):
 
 @view_config(route_name='resync', renderer='json')
 def resync(request):
-    tid = request.matchdict['tender_id']
-    return resync_tender(
-        request.registry.scheduler,
-        request.registry.api_url + 'tenders/' + tid,
-        request.registry.api_token,
-        request.registry.callback_url + 'resync/' + tid,
-        request.registry.db,
-        tid,
-        request.environ.get('REQUEST_ID', '')
-    )
+    return resync_tender(request)
 
 
 @view_config(route_name='calendar', renderer='json')