Fix log rotation issue

Writing log to a single file from multiple processes is not supported
by python logging. It causes making fragmented log files at log
rotation and logs are mixed up.

This change is to use different log files for each sub-process
to help developers check log for a specific process easily.
This change does not affect to pod log (stdout log).

Signed-off-by: Satoshi Fujii <fujii-satoshi@jp.fujitsu.com>
Issue-ID: DCAEGEN2-2941
Change-Id: If8bcb2308863d1395a2c547d2e7b746301665fb0

9 files changed, 70 insertions, 46 deletions

diff --git a/Changelog.md b/Changelog.md
index db72ea9..5aeff31 100644
--- a/Changelog.md
+++ b/Changelog.md
@@ -11,6 +11,7 @@ and this project adheres to [Semantic Versioning](http://semver.org/).
 - [DCAEGEN2-2832] Pod become unready state
 - [DCAEGEN2-2872] No such file or directory error and stop working
 - [DCAEGEN2-2940] Microsec timestamp not properly handled
+- [DCAEGEN2-2941] Log file fragmented by log rotation
 - [DCAEGEN2-2944] cbs polling process startup failure
 
 
diff --git a/miss_htbt_service/cbs_polling.py b/miss_htbt_service/cbs_polling.py
index 3832b71..e7bdef1 100644
--- a/miss_htbt_service/cbs_polling.py
+++ b/miss_htbt_service/cbs_polling.py
@@ -22,7 +22,7 @@
 #    CBS Polling
 #    Set the hb_common table with state="RECONFIGURATION" periodically
 #    to get the new configuration downloaded
-
+import logging
 import sys
 import os
 import socket
@@ -30,7 +30,7 @@ import time
 import misshtbtd as db
 import get_logger
 
-_logger = get_logger.get_logger(__name__)
+_logger = logging.getLogger(__name__)
 
 
 def poll_cbs(current_pid: int) -> None:
@@ -60,6 +60,7 @@ def poll_cbs(current_pid: int) -> None:
 
 
 def cbs_polling_loop(current_pid: int):
+    get_logger.configure_logger('cbs_polling')
     while True:
         poll_cbs(current_pid)
 
diff --git a/miss_htbt_service/db_monitoring.py b/miss_htbt_service/db_monitoring.py
index 32e8edc..a405876 100644
--- a/miss_htbt_service/db_monitoring.py
+++ b/miss_htbt_service/db_monitoring.py
@@ -24,6 +24,7 @@
 #    and generates Missing Heartbeat signal for Policy Engine
 
 import json
+import logging
 import sys
 import os
 import socket
@@ -33,7 +34,7 @@ import htbtworker as pm
 import misshtbtd as db
 import get_logger
 
-_logger = get_logger.get_logger(__name__)
+_logger = logging.getLogger(__name__)
 
 
 def sendControlLoopEvent(CLType, pol_url, policy_version, policy_name, policy_scope, target_type, srcName, epoc_time,
@@ -232,6 +233,7 @@ def db_monitoring(current_pid, json_file, user_name, password, ip_address, port_
 
 
 if __name__ == "__main__":
+    get_logger.configure_logger('db_monitoring')
     _logger.info("DBM: DBM Process started")
     current_pid = sys.argv[1]
     jsfile = sys.argv[2]
diff --git a/miss_htbt_service/get_logger.py b/miss_htbt_service/get_logger.py
index c58a945..55286eb 100644
--- a/miss_htbt_service/get_logger.py
+++ b/miss_htbt_service/get_logger.py
@@ -17,20 +17,32 @@
 
 import logging.handlers
 
-'''Configures the module root logger'''
-root = logging.getLogger()
-if root.handlers:
-    del root.handlers[:]
-formatter = logging.Formatter('%(asctime)s | %(name)s | %(module)s | %(funcName)s | %(lineno)d |  %(levelname)s | %(message)s')
-handler = logging.StreamHandler()
-handler.setFormatter(formatter)
-root.addHandler(handler)
-fhandler = logging.handlers.RotatingFileHandler('./hb_logs.txt', maxBytes=(1048576 * 5), backupCount=10)
-fhandler.setFormatter(formatter)
-root.addHandler(fhandler)
-root.setLevel("DEBUG")
+LOG_LEVEL = logging.DEBUG
+LOG_FORMAT = '%(asctime)s | %(levelname)5s | %(name)s | %(module)s | %(funcName)s | %(lineno)d | %(message)s'
+LOG_MAXSIZE = 10485760 * 5
+LOG_BACKUP_COUNT = 10
 
 
-def get_logger(module=None):
-    '''Returns a module-specific logger or global logger if the module is None'''
-    return root if module is None else root.getChild(module)
+def configure_logger(proc_name: str) -> None:
+    """Configures the module root logger"""
+
+    # Clear handlers
+    root = logging.getLogger()
+    if root.handlers:
+        del root.handlers[:]
+
+    # Add stdout handler
+    formatter = logging.Formatter(LOG_FORMAT)
+    handler = logging.StreamHandler()
+    handler.setFormatter(formatter)
+    root.addHandler(handler)
+
+    # Add rotating log file handler
+    if proc_name:
+        logfile_path = './hb_%s_logs.txt' % proc_name
+    else:
+        logfile_path = './hb_logs.txt'
+    fhandler = logging.handlers.RotatingFileHandler(logfile_path, maxBytes=LOG_MAXSIZE, backupCount=LOG_BACKUP_COUNT)
+    fhandler.setFormatter(formatter)
+    root.addHandler(fhandler)
+    root.setLevel(LOG_LEVEL)
diff --git a/miss_htbt_service/htbtworker.py b/miss_htbt_service/htbtworker.py
index 6fbda2d..be1b6aa 100644
--- a/miss_htbt_service/htbtworker.py
+++ b/miss_htbt_service/htbtworker.py
@@ -22,6 +22,7 @@
 #    Simple Microservice
 #    Tracks Heartbeat messages on input topic in DMaaP
 #    and poppulate the information in postgres DB
+import logging
 
 import psycopg2
 import requests
@@ -33,7 +34,7 @@ import time
 import misshtbtd as db
 import get_logger
 
-_logger = get_logger.get_logger(__name__)
+_logger = logging.getLogger(__name__)
 
 
 def read_json_file(i, prefix="../../tests"):
@@ -160,8 +161,7 @@ def process_msg(jsfile, user_name, password, ip_address, port_num, db_name):
                 source_name_key = source_name_count + 1
                 cl_flag = 0
                 if source_name_count == 0:  # pragma: no cover
-                    msg = "HBT: Insert entry in table_2,source_name_count=0 : ", row
-                    _logger.info(msg)
+                    _logger.info("HBT: Insert entry into vnf_table_2, source_name='%s'", srcname)
                     cur.execute("INSERT INTO vnf_table_2 VALUES(%s,%s,%s,%s,%s)",
                                 (eventName, source_name_key, lastepo, srcname, cl_flag))
                     cur.execute("UPDATE vnf_table_1 SET SOURCE_NAME_COUNT = %s where EVENT_NAME = %s",
@@ -190,8 +190,7 @@ def process_msg(jsfile, user_name, password, ip_address, port_num, db_name):
                     _logger.info(msg)
                     if source_name_count == (source_name_key + 1):
                         source_name_key = source_name_count + 1
-                        msg = "HBT: Insert entry in table_2 : ", row
-                        _logger.info(msg)
+                        _logger.info("HBT: Insert entry into vnf_table_2, source_name='%s'", srcname)
                         cur.execute("INSERT INTO vnf_table_2 VALUES(%s,%s,%s,%s,%s)",
                                     (eventName, source_name_key, lastepo, srcname, cl_flag))
                         cur.execute("UPDATE vnf_table_1 SET SOURCE_NAME_COUNT = %s WHERE EVENT_NAME = %s",
@@ -256,6 +255,7 @@ def commit_and_close_db(connection_db):
 
 
 if __name__ == '__main__':
+    get_logger.configure_logger('htbtworker')
     jsfile = sys.argv[1]
     msg = "HBT:HeartBeat thread Created"
     _logger.info("HBT:HeartBeat thread Created")
diff --git a/miss_htbt_service/misshtbtd.py b/miss_htbt_service/misshtbtd.py
index 61da9d9..6be2260 100644
--- a/miss_htbt_service/misshtbtd.py
+++ b/miss_htbt_service/misshtbtd.py
@@ -28,6 +28,7 @@
 #
 #  Author  Prakash Hosangady(ph553f@att.com)
 import shutil
+import logging
 import traceback
 import os
 import sys
@@ -49,6 +50,7 @@ from mod import trapd_settings as tds
 from mod.trapd_get_cbs_config import get_cbs_config
 
 hb_properties_file = path.abspath(path.join(__file__, "../config/hbproperties.yaml"))
+_logger = logging.getLogger(__name__)
 
 ABSOLUTE_PATH1 = path.abspath(path.join(__file__, "../htbtworker.py"))
 ABSOLUTE_PATH2 = path.abspath(path.join(__file__, "../db_monitoring.py"))
@@ -319,10 +321,8 @@ def create_process(job_list, jsfile, pid_current):
     return job_list
 
 
-_logger = get_logger.get_logger(__name__)
-
-
 def main():
+    get_logger.configure_logger('misshtbtd')
     pid_current = os.getpid()
     hc_proc = multiprocessing.Process(target=check_health.start_health_check_server)
     cbs_polling_proc = multiprocessing.Process(target=cbs_polling.cbs_polling_loop, args=(pid_current,))
diff --git a/miss_htbt_service/mod/trapd_vnf_table.py b/miss_htbt_service/mod/trapd_vnf_table.py
index ff738f0..db6bd17 100644
--- a/miss_htbt_service/mod/trapd_vnf_table.py
+++ b/miss_htbt_service/mod/trapd_vnf_table.py
@@ -25,7 +25,7 @@
 """
 trapd_vnf_table verifies the successful creation of DB Tables.
 """
-
+import logging
 import os
 import yaml
 import os.path as path
@@ -39,8 +39,9 @@ import misshtbtd as db
 import cbs_polling as cbs
 
 prog_name = os.path.basename(__file__)
-hb_properties_file =  path.abspath(path.join(__file__, "../../config/hbproperties.yaml"))
-_logger = get_logger.get_logger(__name__)
+hb_properties_file = path.abspath(path.join(__file__, "../../config/hbproperties.yaml"))
+_logger = logging.getLogger(__name__)
+
 
 def hb_properties():
 	#Read the hbproperties.yaml for postgress and CBS related data
diff --git a/tests/test_get_logger.py b/tests/test_get_logger.py
index a643e0f..cbef9c6 100644
--- a/tests/test_get_logger.py
+++ b/tests/test_get_logger.py
@@ -1,5 +1,6 @@
 # ============LICENSE_START=======================================================
 # Copyright (c) 2020 AT&T Intellectual Property. All rights reserved.
+# Copyright 2021 Fujitsu Ltd.
 # ================================================================================
 # Licensed under the Apache License, Version 2.0 (the "License");
 # you may not use this file except in compliance with the License.
@@ -13,23 +14,30 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 # ============LICENSE_END=========================================================
+import logging
+import os
+from pathlib import Path
 
 from miss_htbt_service import get_logger
 
-import os
+log = logging.getLogger(__name__)
+
 
-def test_get_logger():
-    try:
-        os.remove("hb_logs.txt")
-    except:
-        pass
-    log = get_logger.get_logger()
+def test_configure_logger():
+    expected_log_path = Path('./hb_logs.txt')
+    if expected_log_path.exists():
+        os.remove(expected_log_path)
+    get_logger.configure_logger('')
     log.info("hi there")
+    assert expected_log_path.exists()
+    os.remove(expected_log_path)
 
-def test_get_logger_node():
-    try:
-        os.remove("hb_logs.txt")
-    except:
-        pass
-    log = get_logger.get_logger("node")
-    log.info("hi there node")
+
+def test_configure_logger_with_name():
+    expected_log_path = Path('./hb_htbtworker_logs.txt')
+    if expected_log_path.exists():
+        os.remove(expected_log_path)
+    get_logger.configure_logger('htbtworker')
+    log.info("hi there")
+    assert expected_log_path.exists()
+    os.remove(expected_log_path)
diff --git a/tests/test_trapd_vnf_table.py b/tests/test_trapd_vnf_table.py
index 2110324..e8ef5d0 100644
--- a/tests/test_trapd_vnf_table.py
+++ b/tests/test_trapd_vnf_table.py
@@ -23,9 +23,8 @@
 """
 test_trapd_vnf_table contains test cases related to DB Tables and cbs polling.
 """
-
+import logging
 import unittest
-import get_logger
 from mod.trapd_vnf_table import (
     verify_DB_creation_1, verify_DB_creation_2, verify_DB_creation_hb_common,
     hb_properties, verify_cbspolling,
@@ -34,7 +33,7 @@ from mod.trapd_vnf_table import (
     verify_fetch_json_file, verify_misshtbtdmain, verify_dbmonitoring,
     verify_dbmon_startup)
 
-_logger = get_logger.get_logger(__name__)
+_logger = logging.getLogger(__name__)
 
 
 class test_vnf_tables(unittest.TestCase):