oti/event-handler/otihandler/onap/CommonLogger.py

   1 #!/usr/bin/python
   2 # -*- indent-tabs-mode: nil -*- vi: set expandtab:
   3
   4 # ================================================================================
   5 # Copyright (c) 2019-2020 AT&T Intellectual Property. All rights reserved.
   6 # ================================================================================
   7 # Licensed under the Apache License, Version 2.0 (the "License");
   8 # you may not use this file except in compliance with the License.
   9 # You may obtain a copy of the License at
  10 #
  11 #      http://www.apache.org/licenses/LICENSE-2.0
  12 #
  13 # Unless required by applicable law or agreed to in writing, software
  14 # distributed under the License is distributed on an "AS IS" BASIS,
  15 # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  16 # See the License for the specific language governing permissions and
  17 # limitations under the License.
  18 # ============LICENSE_END=========================================================
  19
  20 """ Common Logging library in Python.
  21
  22 CommonLogger.py
  23
  24 Original Written by:    Terry Schmalzried
  25 Date written:  October 1, 2015
  26 Last updated:  December 1, 2016
  27
  28 version 0.8
  29 """
  30
  31 import os
  32 import logging
  33 import logging.handlers
  34 import re
  35 import socket
  36 import sys
  37 import threading
  38 import time
  39
  40
  41 class CommonLogger:
  42     """ Common Logging object.
  43
  44     Public methods:
  45     __init__
  46     setFields
  47     debug
  48     info
  49     warn
  50     error
  51     fatal
  52     """
  53
  54     UnknownFile = -1
  55     ErrorFile = 0
  56     DebugFile = 1
  57     AuditFile = 2
  58     MetricsFile = 3
  59     DateFmt = '%Y-%m-%dT%H:%M:%S'
  60     verbose = False
  61
  62     def __init__(self, configFile, logKey, **kwargs):
  63         """Construct a Common Logger for one Log File.
  64
  65         Arguments:
  66         configFile             -- configuration filename.
  67         logKey                 -- the keyword in configFile that identifies the log filename.
  68
  69         Keyword arguments: Annotations are d:debug, a=audit, m=metrics, e=error
  70         style                       -- the log file format (style) to use when writing log messages,
  71                                        one of CommonLogger.ErrorFile, CommonLogger.DebugFile,
  72                                        CommonLogger.AuditFile and CommonLogger.MetricsFile, or
  73                                        one of the strings "error", "debug", "audit" or "metrics".
  74                                        May also be set in the config file using a field named
  75                                        <logKey>Style (where <logKey> is the value of the logKey
  76                                        parameter). The keyword value overrides the value in the
  77                                        config file.
  78         requestID (dame)            -- optional default value for this log record field.
  79         serviceInstanceID (am)      -- optional default value for this log record field.
  80         threadID (am)               -- optional default value for this log record field.
  81         serverName (am)             -- optional default value for this log record field.
  82         serviceName (am)            -- optional default value for this log record field.
  83         instanceUUID (am)           -- optional default value for this log record field.
  84         severity (am)               -- optional default value for this log record field.
  85         serverIPAddress (am)        -- optional default value for this log record field.
  86         server (am)                 -- optional default value for this log record field.
  87         IPAddress (am)              -- optional default value for this log record field.
  88         className (am)              -- optional default value for this log record field.
  89         timer (am)                  -- (ElapsedTime) optional default value for this log record field.
  90         partnerName (ame)           -- optional default value for this log record field.
  91         targetEntity (me)           -- optional default value for this log record field.
  92         targetServiceName (me)      -- optional default value for this log record field.
  93         statusCode (am)             -- optional default value for this log record field.
  94         responseCode (am)           -- optional default value for this log record field.
  95         responseDescription (am)    -- optional default value for this log record field.
  96         processKey (am)             -- optional default value for this log record field.
  97         targetVirtualEntity (m)     -- optional default value for this log record field.
  98         customField1 (am)           -- optional default value for this log record field.
  99         customField2 (am)           -- optional default value for this log record field.
 100         customField3 (am)           -- optional default value for this log record field.
 101         customField4 (am)           -- optional default value for this log record field.
 102         errorCategory (e)           -- optional default value for this log record field.
 103         errorCode (e)               -- optional default value for this log record field.
 104         errorDescription (e)        -- optional default value for this log record field.
 105
 106         Note:  the pipe '|' character is not allowed in any log record field.
 107         """
 108
 109         self._monitorFlag = False
 110
 111         # Get configuration parameters
 112         self._logKey = str(logKey)
 113         self._configFile = str(configFile)
 114         self._rotateMethod = 'time'
 115         self._timeRotateIntervalType = 'midnight'
 116         self._timeRotateInterval = 1
 117         self._sizeMaxBytes = 0
 118         self._sizeRotateMode = 'a'
 119         self._socketHost = None
 120         self._socketPort = 0
 121         self._typeLogger = 'filelogger'
 122         self._backupCount = 6
 123         self._logLevelThreshold = self._intLogLevel('')
 124         self._logFile = None
 125         self._begTime = None
 126         self._begMsec = 0
 127         self._fields = {}
 128         self._fields["style"] = CommonLogger.UnknownFile
 129         try:
 130             self._configFileModified = os.path.getmtime(self._configFile)
 131             for line in open(self._configFile):
 132                 line = line.split('#',1)[0]    # remove comments
 133                 if '=' in line:
 134                     key, value = [x.strip() for x in line.split('=',1)]
 135                     if key == 'rotateMethod' and value.lower() in ['time', 'size', 'none']:
 136                         self._rotateMethod = value.lower()
 137                     elif key == 'timeRotateIntervalType' and value in ['S', 'M', 'H', 'D', 'W0', 'W1', 'W2', 'W3', 'W4', 'W5', 'W6', 'midnight']:
 138                         self._timeRotateIntervalType = value
 139                     elif key == 'timeRotateInterval' and int( value ) > 0:
 140                         self._timeRotateInterval = int( value )
 141                     elif key == 'sizeMaxBytes' and int( value ) >= 0:
 142                         self._sizeMaxBytes = int( value )
 143                     elif key == 'sizeRotateMode' and value in ['a']:
 144                         self._sizeRotateMode = value
 145                     elif key == 'backupCount' and int( value ) >= 0:
 146                         self._backupCount = int( value )
 147                     elif key == self._logKey + 'SocketHost':
 148                         self._socketHost = value
 149                     elif key == self._logKey + 'SocketPort' and int( value ) == 0:
 150                         self._socketPort = int( value )
 151                     elif key == self._logKey + 'LogType' and value.lower() in ['filelogger', 'stdoutlogger', 'stderrlogger', 'socketlogger', 'nulllogger']:
 152                         self._typeLogger = value.lower()
 153                     elif key == self._logKey + 'LogLevel':
 154                         self._logLevelThreshold = self._intLogLevel(value.upper())
 155                     elif key == self._logKey + 'Style':
 156                         self._fields["style"] = value
 157                     elif key == self._logKey:
 158                         self._logFile = value
 159         except Exception as x:
 160             print("exception reading '%s' configuration file: %s" %(self._configFile, str(x)))
 161             sys.exit(2)
 162         except:
 163             print("exception reading '%s' configuration file" %(self._configFile))
 164             sys.exit(2)
 165
 166         if self._logFile is None:
 167             print('configuration file %s is missing definition %s for log file' %(self._configFile, self._logKey))
 168             sys.exit(2)
 169
 170
 171         # initialize default log fields
 172         # timestamp will automatically be generated
 173         for key in ['style', 'requestID', 'serviceInstanceID', 'threadID', 'serverName', 'serviceName', 'instanceUUID', \
 174                     'severity', 'serverIPAddress', 'server', 'IPAddress', 'className', 'timer', \
 175                     'partnerName', 'targetEntity', 'targetServiceName', 'statusCode', 'responseCode', \
 176                     'responseDescription', 'processKey', 'targetVirtualEntity', 'customField1', \
 177                     'customField2', 'customField3', 'customField4', 'errorCategory', 'errorCode', \
 178                     'errorDescription' ]:
 179             if key in kwargs and kwargs[key] != None:
 180                 self._fields[key] = kwargs[key]
 181
 182         self._resetStyleField()
 183
 184         # Set up logger
 185         self._logLock = threading.Lock()
 186         with self._logLock:
 187             self._logger = logging.getLogger(self._logKey)
 188             self._logger.propagate = False
 189             self._createLogger()
 190
 191         self._defaultServerInfo()
 192
 193         # spawn a thread to monitor configFile for logLevel and logFile changes
 194         self._monitorFlag = True
 195         self._monitorThread = threading.Thread(target=self._monitorConfigFile, args=())
 196         self._monitorThread.daemon = True
 197         self._monitorThread.start()
 198
 199
 200     def _createLogger(self):
 201         if self._typeLogger == 'filelogger':
 202             self._mkdir_p(self._logFile)
 203             if self._rotateMethod == 'time':
 204                 self._logHandler = logging.handlers.TimedRotatingFileHandler(self._logFile, \
 205                                                                              when=self._timeRotateIntervalType, interval=self._timeRotateInterval, \
 206                                                                              backupCount=self._backupCount, encoding=None, delay=False, utc=True)
 207             elif self._rotateMethod == 'size':
 208                 self._logHandler = logging.handlers.RotatingFileHandler(self._logFile, \
 209                                                                         mode=self._sizeRotateMode, maxBytes=self._sizeMaxBytes, \
 210                                                                         backupCount=self._backupCount, encoding=None, delay=False)
 211
 212             else:
 213                 self._logHandler = logging.handlers.WatchedFileHandler(self._logFile, \
 214                                                                        mode=self._sizeRotateMode, \
 215                                                                        encoding=None, delay=False)
 216         elif self._typeLogger == 'stderrlogger':
 217             self._logHandler = logging.handlers.StreamHandler(sys.stderr)
 218         elif self._typeLogger == 'stdoutlogger':
 219             self._logHandler = logging.handlers.StreamHandler(sys.stdout)
 220         elif self._typeLogger == 'socketlogger':
 221             self._logHandler = logging.handlers.SocketHandler(self._socketHost, self._socketPort)
 222         elif self._typeLogger == 'nulllogger':
 223             self._logHandler = logging.handlers.NullHandler()
 224
 225         if self._fields["style"] == CommonLogger.AuditFile or self._fields["style"] == CommonLogger.MetricsFile:
 226             self._logFormatter = logging.Formatter(fmt='%(begtime)s,%(begmsecs)03d+00:00|%(endtime)s,%(endmsecs)03d+00:00|%(message)s', datefmt=CommonLogger.DateFmt)
 227         else:
 228             self._logFormatter = logging.Formatter(fmt='%(asctime)s,%(msecs)03d+00:00|%(message)s', datefmt='%Y-%m-%dT%H:%M:%S')
 229         self._logFormatter.converter = time.gmtime
 230         self._logHandler.setFormatter(self._logFormatter)
 231         self._logger.addHandler(self._logHandler)
 232
 233     def _resetStyleField(self):
 234         styleFields = ["error", "debug", "audit", "metrics"]
 235         if self._fields['style'] in styleFields:
 236             self._fields['style'] = styleFields.index(self._fields['style'])
 237
 238     def __del__(self):
 239         if not self._monitorFlag:
 240             return
 241
 242         self._monitorFlag = False
 243
 244         if self._monitorThread is not None and self._monitorThread.is_alive():
 245             self._monitorThread.join()
 246
 247         self._monitorThread = None
 248
 249
 250     def _defaultServerInfo(self):
 251
 252         # If not set or purposely set = None, then set default
 253         if self._fields.get('server') is None:
 254             try:
 255                 self._fields['server']          = socket.getfqdn()
 256             except Exception as err:
 257                 try:
 258                     self._fields['server']      = socket.gethostname()
 259                 except Exception as err:
 260                     self._fields['server']      = ""
 261
 262         # If not set or purposely set = None, then set default
 263         if self._fields.get('serverIPAddress') is None:
 264             try:
 265                 self._fields['serverIPAddress'] = socket.gethostbyname(self._fields['server'])
 266             except Exception as err:
 267                 self._fields['serverIPAddress'] = ""
 268
 269
 270     def _monitorConfigFile(self):
 271         while self._monitorFlag:
 272             try:
 273                 fileTime = os.path.getmtime(self._configFile)
 274                 if fileTime > self._configFileModified:
 275                     self._configFileModified = fileTime
 276                     ReopenLogFile = False
 277                     logFile = self._logFile
 278                     with open(self._configFile) as fp:
 279                         for line in fp:
 280                             line = line.split('#',1)[0]    # remove comments
 281                             if '=' in line:
 282                                 key, value = [x.strip() for x in line.split('=',1)]
 283                                 if key == 'rotateMethod' and value.lower() in ['time', 'size', 'none'] and self._rotateMethod != value:
 284                                     self._rotateMethod = value.lower()
 285                                     ReopenLogFile = True
 286                                 elif key == 'timeRotateIntervalType' and value in ['S', 'M', 'H', 'D', 'W0', 'W1', 'W2', 'W3', 'W4', 'W5', 'W6', 'midnight']:
 287                                     self._timeRotateIntervalType = value
 288                                     ReopenLogFile = True
 289                                 elif key == 'timeRotateInterval' and int( value ) > 0:
 290                                     self._timeRotateInterval = int( value )
 291                                     ReopenLogFile = True
 292                                 elif key == 'sizeMaxBytes' and int( value ) >= 0:
 293                                     self._sizeMaxBytes = int( value )
 294                                     ReopenLogFile = True
 295                                 elif key == 'sizeRotateMode' and value in ['a']:
 296                                     self._sizeRotateMode = value
 297                                     ReopenLogFile = True
 298                                 elif key == 'backupCount' and int( value ) >= 0:
 299                                     self._backupCount = int( value )
 300                                     ReopenLogFile = True
 301                                 elif key == self._logKey + 'SocketHost' and self._socketHost != value:
 302                                     self._socketHost = value
 303                                     ReopenLogFile = True
 304                                 elif key == self._logKey + 'SocketPort' and self._socketPort > 0 and self._socketPort != int( value ):
 305                                     self._socketPort = int( value )
 306                                     ReopenLogFile = True
 307                                 elif key == self._logKey + 'LogLevel' and self._logLevelThreshold != self._intLogLevel( value.upper() ):
 308                                     self._logLevelThreshold = self._intLogLevel(value.upper())
 309                                 elif key == self._logKey + 'LogType' and self._typeLogger != value and value.lower() in ['filelogger', 'stdoutlogger', 'stderrlogger', 'socketlogger', 'nulllogger']:
 310                                     self._typeLogger = value.lower()
 311                                     ReopenLogFile = True
 312                                 elif key == self._logKey + 'Style':
 313                                     self._fields["style"] = value
 314                                     self._resetStyleField()
 315                                 elif key == self._logKey and self._logFile != value:
 316                                     logFile = value
 317                                     ReopenLogFile = True
 318                     if ReopenLogFile:
 319                         with self._logLock:
 320                             self._logger.removeHandler(self._logHandler)
 321                             self._logFile = logFile
 322                             self._createLogger()
 323             except Exception as err:
 324                 pass
 325
 326             time.sleep(5)
 327
 328
 329     def setFields(self, **kwargs):
 330         """Set default values for log fields.
 331
 332         Keyword arguments: Annotations are d:debug, a=audit, m=metrics, e=error
 333         style                       -- the log file format (style) to use when writing log messages
 334         requestID (dame)            -- optional default value for this log record field.
 335         serviceInstanceID (am)      -- optional default value for this log record field.
 336         threadID (am)               -- optional default value for this log record field.
 337         serverName (am)             -- optional default value for this log record field.
 338         serviceName (am)            -- optional default value for this log record field.
 339         instanceUUID (am)           -- optional default value for this log record field.
 340         severity (am)               -- optional default value for this log record field.
 341         serverIPAddress (am)        -- optional default value for this log record field.
 342         server (am)                 -- optional default value for this log record field.
 343         IPAddress (am)              -- optional default value for this log record field.
 344         className (am)              -- optional default value for this log record field.
 345         timer (am)                  -- (ElapsedTime) optional default value for this log record field.
 346         partnerName (ame)           -- optional default value for this log record field.
 347         targetEntity (me)           -- optional default value for this log record field.
 348         targetServiceName (me)      -- optional default value for this log record field.
 349         statusCode (am)             -- optional default value for this log record field.
 350         responseCode (am)           -- optional default value for this log record field.
 351         responseDescription (am)    -- optional default value for this log record field.
 352         processKey (am)             -- optional default value for this log record field.
 353         targetVirtualEntity (m)     -- optional default value for this log record field.
 354         customField1 (am)           -- optional default value for this log record field.
 355         customField2 (am)           -- optional default value for this log record field.
 356         customField3 (am)           -- optional default value for this log record field.
 357         customField4 (am)           -- optional default value for this log record field.
 358         errorCategory (e)           -- optional default value for this log record field.
 359         errorCode (e)               -- optional default value for this log record field.
 360         errorDescription (e)        -- optional default value for this log record field.
 361
 362         Note:  the pipe '|' character is not allowed in any log record field.
 363         """
 364
 365         for key in ['style', 'requestID', 'serviceInstanceID', 'threadID', 'serverName', 'serviceName', 'instanceUUID', \
 366                     'severity', 'serverIPAddress', 'server', 'IPAddress', 'className', 'timer', \
 367                     'partnerName', 'targetEntity', 'targetServiceName', 'statusCode', 'responseCode', \
 368                     'responseDescription', 'processKey', 'targetVirtualEntity', 'customField1', \
 369                     'customField2', 'customField3', 'customField4', 'errorCategory', 'errorCode', \
 370                     'errorDescription' ]:
 371             if key in kwargs:
 372                 if kwargs[key] != None:
 373                     self._fields[key] = kwargs[key]
 374                 elif key in self._fields:
 375                     del self._fields[key]
 376
 377         self._defaultServerInfo()
 378
 379
 380     def debug(self, message, **kwargs):
 381         """Write a DEBUG level message to the log file.
 382
 383         Arguments:
 384         message           -- value for the last log record field.
 385
 386         Keyword arguments: Annotations are d:debug, a=audit, m=metrics, e=error
 387         style                       -- the log file format (style) to use when writing log messages
 388         requestID (dame)            -- optional default value for this log record field.
 389         serviceInstanceID (am)      -- optional default value for this log record field.
 390         threadID (am)               -- optional default value for this log record field.
 391         serverName (am)             -- optional default value for this log record field.
 392         serviceName (am)            -- optional default value for this log record field.
 393         instanceUUID (am)           -- optional default value for this log record field.
 394         severity (am)               -- optional default value for this log record field.
 395         serverIPAddress (am)        -- optional default value for this log record field.
 396         server (am)                 -- optional default value for this log record field.
 397         IPAddress (am)              -- optional default value for this log record field.
 398         className (am)              -- optional default value for this log record field.
 399         timer (am)                  -- (ElapsedTime) optional default value for this log record field.
 400         partnerName (ame)           -- optional default value for this log record field.
 401         targetEntity (me)           -- optional default value for this log record field.
 402         targetServiceName (me)      -- optional default value for this log record field.
 403         statusCode (am)             -- optional default value for this log record field.
 404         responseCode (am)           -- optional default value for this log record field.
 405         responseDescription (am)    -- optional default value for this log record field.
 406         processKey (am)             -- optional default value for this log record field.
 407         targetVirtualEntity (m)     -- optional default value for this log record field.
 408         customField1 (am)           -- optional default value for this log record field.
 409         customField2 (am)           -- optional default value for this log record field.
 410         customField3 (am)           -- optional default value for this log record field.
 411         customField4 (am)           -- optional default value for this log record field.
 412         errorCategory (e)           -- optional default value for this log record field.
 413         errorCode (e)               -- optional default value for this log record field.
 414         errorDescription (e)        -- optional default value for this log record field.
 415         begTime (am)                -- optional starting time for this audit/metrics log record.
 416
 417         Note:  the pipe '|' character is not allowed in any log record field.
 418         """
 419
 420         self._log('DEBUG', message, errorCategory = 'DEBUG', **kwargs)
 421
 422     def info(self, message, **kwargs):
 423         """Write an INFO level message to the log file.
 424
 425         Arguments:
 426         message           -- value for the last log record field.
 427
 428         Keyword arguments: Annotations are d:debug, a=audit, m=metrics, e=error
 429         style                       -- the log file format (style) to use when writing log messages
 430         requestID (dame)            -- optional default value for this log record field.
 431         serviceInstanceID (am)      -- optional default value for this log record field.
 432         threadID (am)               -- optional default value for this log record field.
 433         serverName (am)             -- optional default value for this log record field.
 434         serviceName (am)            -- optional default value for this log record field.
 435         instanceUUID (am)           -- optional default value for this log record field.
 436         severity (am)               -- optional default value for this log record field.
 437         serverIPAddress (am)        -- optional default value for this log record field.
 438         server (am)                 -- optional default value for this log record field.
 439         IPAddress (am)              -- optional default value for this log record field.
 440         className (am)              -- optional default value for this log record field.
 441         timer (am)                  -- (ElapsedTime) optional default value for this log record field.
 442         partnerName (ame)           -- optional default value for this log record field.
 443         targetEntity (me)           -- optional default value for this log record field.
 444         targetServiceName (me)      -- optional default value for this log record field.
 445         statusCode (am)             -- optional default value for this log record field.
 446         responseCode (am)           -- optional default value for this log record field.
 447         responseDescription (am)    -- optional default value for this log record field.
 448         processKey (am)             -- optional default value for this log record field.
 449         targetVirtualEntity (m)     -- optional default value for this log record field.
 450         customField1 (am)           -- optional default value for this log record field.
 451         customField2 (am)           -- optional default value for this log record field.
 452         customField3 (am)           -- optional default value for this log record field.
 453         customField4 (am)           -- optional default value for this log record field.
 454         errorCategory (e)           -- optional default value for this log record field.
 455         errorCode (e)               -- optional default value for this log record field.
 456         errorDescription (e)        -- optional default value for this log record field.
 457         begTime (am)                -- optional starting time for this audit/metrics log record.
 458
 459         Note:  the pipe '|' character is not allowed in any log record field.
 460         """
 461
 462         self._log('INFO', message, errorCategory = 'INFO', **kwargs)
 463
 464     def warn(self, message, **kwargs):
 465         """Write a WARN level message to the log file.
 466
 467         Arguments:
 468         message           -- value for the last log record field.
 469
 470         Keyword arguments: Annotations are d:debug, a=audit, m=metrics, e=error
 471         style                       -- the log file format (style) to use when writing log messages
 472         requestID (dame)            -- optional default value for this log record field.
 473         serviceInstanceID (am)      -- optional default value for this log record field.
 474         threadID (am)               -- optional default value for this log record field.
 475         serverName (am)             -- optional default value for this log record field.
 476         serviceName (am)            -- optional default value for this log record field.
 477         instanceUUID (am)           -- optional default value for this log record field.
 478         severity (am)               -- optional default value for this log record field.
 479         serverIPAddress (am)        -- optional default value for this log record field.
 480         server (am)                 -- optional default value for this log record field.
 481         IPAddress (am)              -- optional default value for this log record field.
 482         className (am)              -- optional default value for this log record field.
 483         timer (am)                  -- (ElapsedTime) optional default value for this log record field.
 484         partnerName (ame)           -- optional default value for this log record field.
 485         targetEntity (me)           -- optional default value for this log record field.
 486         targetServiceName (me)      -- optional default value for this log record field.
 487         statusCode (am)             -- optional default value for this log record field.
 488         responseCode (am)           -- optional default value for this log record field.
 489         responseDescription (am)    -- optional default value for this log record field.
 490         processKey (am)             -- optional default value for this log record field.
 491         targetVirtualEntity (m)     -- optional default value for this log record field.
 492         customField1 (am)           -- optional default value for this log record field.
 493         customField2 (am)           -- optional default value for this log record field.
 494         customField3 (am)           -- optional default value for this log record field.
 495         customField4 (am)           -- optional default value for this log record field.
 496         errorCategory (e)           -- optional default value for this log record field.
 497         errorCode (e)               -- optional default value for this log record field.
 498         errorDescription (e)        -- optional default value for this log record field.
 499         begTime (am)                -- optional starting time for this audit/metrics log record.
 500
 501         Note:  the pipe '|' character is not allowed in any log record field.
 502         """
 503
 504         self._log('WARN', message, errorCategory = 'WARN', **kwargs)
 505
 506     def error(self, message, **kwargs):
 507         """Write an ERROR level message to the log file.
 508
 509         Arguments:
 510         message           -- value for the last log record field.
 511
 512         Keyword arguments: Annotations are d:debug, a=audit, m=metrics, e=error
 513         style                       -- the log file format (style) to use when writing log messages
 514         requestID (dame)            -- optional default value for this log record field.
 515         serviceInstanceID (am)      -- optional default value for this log record field.
 516         threadID (am)               -- optional default value for this log record field.
 517         serverName (am)             -- optional default value for this log record field.
 518         serviceName (am)            -- optional default value for this log record field.
 519         instanceUUID (am)           -- optional default value for this log record field.
 520         severity (am)               -- optional default value for this log record field.
 521         serverIPAddress (am)        -- optional default value for this log record field.
 522         server (am)                 -- optional default value for this log record field.
 523         IPAddress (am)              -- optional default value for this log record field.
 524         className (am)              -- optional default value for this log record field.
 525         timer (am)                  -- (ElapsedTime) optional default value for this log record field.
 526         partnerName (ame)           -- optional default value for this log record field.
 527         targetEntity (me)           -- optional default value for this log record field.
 528         targetServiceName (me)      -- optional default value for this log record field.
 529         statusCode (am)             -- optional default value for this log record field.
 530         responseCode (am)           -- optional default value for this log record field.
 531         responseDescription (am)    -- optional default value for this log record field.
 532         processKey (am)             -- optional default value for this log record field.
 533         targetVirtualEntity (m)     -- optional default value for this log record field.
 534         customField1 (am)           -- optional default value for this log record field.
 535         customField2 (am)           -- optional default value for this log record field.
 536         customField3 (am)           -- optional default value for this log record field.
 537         customField4 (am)           -- optional default value for this log record field.
 538         errorCategory (e)           -- optional default value for this log record field.
 539         errorCode (e)               -- optional default value for this log record field.
 540         errorDescription (e)        -- optional default value for this log record field.
 541         begTime (am)                -- optional starting time for this audit/metrics log record.
 542
 543         Note:  the pipe '|' character is not allowed in any log record field.
 544         """
 545
 546         self._log('ERROR', message, errorCategory = 'ERROR', **kwargs)
 547
 548     def fatal(self, message, **kwargs):
 549         """Write a FATAL level message to the log file.
 550
 551         Arguments:
 552         message           -- value for the last log record field.
 553
 554         Keyword arguments: Annotations are d:debug, a=audit, m=metrics, e=error
 555         style                       -- the log file format (style) to use when writing log messages
 556         requestID (dame)            -- optional default value for this log record field.
 557         serviceInstanceID (am)      -- optional default value for this log record field.
 558         threadID (am)               -- optional default value for this log record field.
 559         serverName (am)             -- optional default value for this log record field.
 560         serviceName (am)            -- optional default value for this log record field.
 561         instanceUUID (am)           -- optional default value for this log record field.
 562         severity (am)               -- optional default value for this log record field.
 563         serverIPAddress (am)        -- optional default value for this log record field.
 564         server (am)                 -- optional default value for this log record field.
 565         IPAddress (am)              -- optional default value for this log record field.
 566         className (am)              -- optional default value for this log record field.
 567         timer (am)                  -- (ElapsedTime) optional default value for this log record field.
 568         partnerName (ame)           -- optional default value for this log record field.
 569         targetEntity (me)           -- optional default value for this log record field.
 570         targetServiceName (me)      -- optional default value for this log record field.
 571         statusCode (am)             -- optional default value for this log record field.
 572         responseCode (am)           -- optional default value for this log record field.
 573         responseDescription (am)    -- optional default value for this log record field.
 574         processKey (am)             -- optional default value for this log record field.
 575         targetVirtualEntity (m)     -- optional default value for this log record field.
 576         customField1 (am)           -- optional default value for this log record field.
 577         customField2 (am)           -- optional default value for this log record field.
 578         customField3 (am)           -- optional default value for this log record field.
 579         customField4 (am)           -- optional default value for this log record field.
 580         errorCategory (e)           -- optional default value for this log record field.
 581         errorCode (e)               -- optional default value for this log record field.
 582         errorDescription (e)        -- optional default value for this log record field.
 583         begTime (am)                -- optional starting time for this audit/metrics log record.
 584
 585         Note:  the pipe '|' character is not allowed in any log record field.
 586         """
 587
 588         self._log('FATAL', message, errorCategory = 'FATAL', **kwargs)
 589
 590     def _log(self, logLevel, message, **kwargs):
 591         """Write a message to the log file.
 592
 593         Arguments:
 594         logLevel          -- value ('DEBUG', 'INFO', 'WARN', 'ERROR', 'FATAL', ...) for the log record.
 595         message           -- value for the last log record field.
 596
 597         Keyword arguments: Annotations are d:debug, a=audit, m=metrics, e=error
 598         style                       -- the log file format (style) to use when writing log messages
 599         requestID (dame)            -- optional default value for this log record field.
 600         serviceInstanceID (am)      -- optional default value for this log record field.
 601         threadID (am)               -- optional default value for this log record field.
 602         serverName (am)             -- optional default value for this log record field.
 603         serviceName (am)            -- optional default value for this log record field.
 604         instanceUUID (am)           -- optional default value for this log record field.
 605         severity (am)               -- optional default value for this log record field.
 606         serverIPAddress (am)        -- optional default value for this log record field.
 607         server (am)                 -- optional default value for this log record field.
 608         IPAddress (am)              -- optional default value for this log record field.
 609         className (am)              -- optional default value for this log record field.
 610         timer (am)                  -- (ElapsedTime) optional default value for this log record field.
 611         partnerName (ame)           -- optional default value for this log record field.
 612         targetEntity (me)           -- optional default value for this log record field.
 613         targetServiceName (me)      -- optional default value for this log record field.
 614         statusCode (am)             -- optional default value for this log record field.
 615         responseCode (am)           -- optional default value for this log record field.
 616         responseDescription (am)    -- optional default value for this log record field.
 617         processKey (am)             -- optional default value for this log record field.
 618         targetVirtualEntity (m)     -- optional default value for this log record field.
 619         customField1 (am)           -- optional default value for this log record field.
 620         customField2 (am)           -- optional default value for this log record field.
 621         customField3 (am)           -- optional default value for this log record field.
 622         customField4 (am)           -- optional default value for this log record field.
 623         errorCategory (e)           -- optional default value for this log record field.
 624         errorCode (e)               -- optional default value for this log record field.
 625         errorDescription (e)        -- optional default value for this log record field.
 626         begTime (am)                -- optional starting time for this audit/metrics log record.
 627
 628         Note:  the pipe '|' character is not allowed in any log record field.
 629         """
 630
 631         # timestamp will automatically be inserted
 632         style              = int(self._getVal('style',             '', **kwargs))
 633         requestID          = self._getVal('requestID',         '', **kwargs)
 634         serviceInstanceID  = self._getVal('serviceInstanceID', '', **kwargs)
 635         threadID           = self._getVal('threadID',          threading.currentThread().getName(), **kwargs)
 636         serverName         = self._getVal('serverName',        '', **kwargs)
 637         serviceName        = self._getVal('serviceName',       '', **kwargs)
 638         instanceUUID       = self._getVal('instanceUUID',      '', **kwargs)
 639         upperLogLevel      = self._noSep(logLevel.upper())
 640         severity           = self._getVal('severity',          '', **kwargs)
 641         serverIPAddress    = self._getVal('serverIPAddress',   '', **kwargs)
 642         server             = self._getVal('server',            '', **kwargs)
 643         IPAddress          = self._getVal('IPAddress',         '', **kwargs)
 644         className          = self._getVal('className',         '', **kwargs)
 645         timer              = self._getVal('timer',             '', **kwargs)
 646         partnerName        = self._getVal('partnerName', '', **kwargs)
 647         targetEntity       = self._getVal('targetEntity', '', **kwargs)
 648         targetServiceName  = self._getVal('targetServiceName', '', **kwargs)
 649         statusCode         = self._getVal('statusCode', '', **kwargs)
 650         responseCode       = self._getVal('responseCode', '', **kwargs)
 651         responseDescription = self._noSep(self._getVal('responseDescription', '', **kwargs))
 652         processKey          = self._getVal('processKey', '', **kwargs)
 653         targetVirtualEntity = self._getVal('targetVirtualEntity', '', **kwargs)
 654         customField1        = self._getVal('customField1', '', **kwargs)
 655         customField2        = self._getVal('customField2', '', **kwargs)
 656         customField3        = self._getVal('customField3', '', **kwargs)
 657         customField4        = self._getVal('customField4', '', **kwargs)
 658         errorCategory       = self._getVal('errorCategory', '', **kwargs)
 659         errorCode           = self._getVal('errorCode', '', **kwargs)
 660         errorDescription    = self._noSep(self._getVal('errorDescription', '', **kwargs))
 661         nbegTime            = self._getArg('begTime', {}, **kwargs)
 662
 663         detailMessage     = self._noSep(message)
 664         if bool(re.match(r" *$", detailMessage)):
 665             return  # don't log empty messages
 666
 667         useLevel = self._intLogLevel(upperLogLevel)
 668         if CommonLogger.verbose: print("logger STYLE=%s" % style)
 669         if useLevel < self._logLevelThreshold:
 670             if CommonLogger.verbose: print("skipping because of level")
 671             pass
 672         else:
 673             with self._logLock:
 674                 if style == CommonLogger.ErrorFile:
 675                     if CommonLogger.verbose: print("using CommonLogger.ErrorFile")
 676                     self._logger.log(50, '%s|%s|%s|%s|%s|%s|%s|%s|%s|%s' \
 677                                      %(requestID, threadID, serviceName, partnerName, targetEntity, targetServiceName,
 678                                        errorCategory, errorCode, errorDescription, detailMessage))
 679                 elif style == CommonLogger.DebugFile:
 680                     if CommonLogger.verbose: print("using CommonLogger.DebugFile")
 681                     self._logger.log(50, '%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s' \
 682                                      %(requestID, threadID, serverName, serviceName, instanceUUID, upperLogLevel,
 683                                        severity, serverIPAddress, server, IPAddress, className, timer, detailMessage))
 684                 elif style == CommonLogger.AuditFile:
 685                     if CommonLogger.verbose: print("using CommonLogger.AuditFile")
 686                     endAuditTime, endAuditMsec = self._getTime()
 687                     if type(nbegTime) is dict and 'begTime' in nbegTime and 'begMsec' in nbegTime:
 688                         d = { 'begtime': self._noSep(nbegTime['begTime']), 'begmsecs': float(self._noSep(nbegTime['begMsec'])), 'endtime': endAuditTime, 'endmsecs': endAuditMsec }
 689                     elif self._begTime is not None:
 690                         d = { 'begtime': self._begTime, 'begmsecs': self._begMsec, 'endtime': endAuditTime, 'endmsecs': endAuditMsec }
 691                     else:
 692                         d = { 'begtime': endAuditTime, 'begmsecs': endAuditMsec, 'endtime': endAuditTime, 'endmsecs': endAuditMsec }
 693                     self._begTime = None
 694                     unused = ""
 695                     self._logger.log(50, '%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s' \
 696                                      %(requestID, serviceInstanceID, threadID, serverName, serviceName, partnerName,
 697                                        statusCode, responseCode, responseDescription, instanceUUID, upperLogLevel,
 698                                        severity, serverIPAddress, timer, server, IPAddress, className, unused,
 699                                        processKey, customField1, customField2, customField3, customField4, detailMessage), extra=d)
 700                 elif style == CommonLogger.MetricsFile:
 701                     if CommonLogger.verbose: print("using CommonLogger.MetricsFile")
 702                     endMetricsTime, endMetricsMsec = self._getTime()
 703                     if type(nbegTime) is dict and 'begTime' in nbegTime and 'begMsec' in nbegTime:
 704                         d = { 'begtime': self._noSep(nbegTime['begTime']), 'begmsecs': float(self._noSep(nbegTime['begMsec'])), 'endtime': endMetricsTime, 'endmsecs': endMetricsMsec }
 705                     elif self._begTime is not None:
 706                         d = { 'begtime': self._begTime, 'begmsecs': self._begMsec, 'endtime': endMetricsTime, 'endmsecs': endMetricsMsec }
 707                     else:
 708                         d = { 'begtime': endMetricsTime, 'begmsecs': endMetricsMsec, 'endtime': endMetricsTime, 'endmsecs': endMetricsMsec }
 709                     self._begTime = None
 710                     unused = ""
 711                     self._logger.log(50, '%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s|%s' \
 712                                      %(requestID, serviceInstanceID, threadID, serverName, serviceName, partnerName,
 713                                        targetEntity, targetServiceName, statusCode, responseCode, responseDescription,
 714                                        instanceUUID, upperLogLevel, severity, serverIPAddress, timer, server, IPAddress,
 715                                        className, unused, processKey, targetVirtualEntity, customField1, customField2,
 716                                        customField3, customField4, detailMessage), extra=d)
 717                 else:
 718                     print("!!!!!!!!!!!!!!!! style not set: %s" % self._fields["style"])
 719
 720     def _getTime(self):
 721         ct = time.time()
 722         lt = time.localtime(ct)
 723         return (time.strftime(CommonLogger.DateFmt, lt), (ct - int(ct)) * 1000)
 724
 725     def setStartRecordEvent(self):
 726         """
 727         Set the start time to be saved for both audit and metrics records
 728         """
 729         self._begTime, self._begMsec = self._getTime()
 730
 731     def getStartRecordEvent(self):
 732         """
 733         Retrieve the start time to be used for either audit and metrics records
 734         """
 735         begTime, begMsec = self._getTime()
 736         return {'begTime':begTime, 'begMsec':begMsec}
 737
 738     def _getVal(self, key, default, **kwargs):
 739         val = self._fields.get(key)
 740         if key in kwargs: val = kwargs[key]
 741         if val is None: val = default
 742         return self._noSep(val)
 743
 744     def _getArg(self, key, default, **kwargs):
 745         val = None
 746         if key in kwargs: val = kwargs[key]
 747         if val is None: val = default
 748         return val
 749
 750     def _noSep(self, message):
 751         if message is None:  return ''
 752         return re.sub(r'[\|\n]', ' ', str(message))
 753
 754     def _intLogLevel(self, logLevel):
 755         if   logLevel == 'FATAL':  useLevel = 50
 756         elif logLevel == 'ERROR':  useLevel = 40
 757         elif logLevel == 'WARN':   useLevel = 30
 758         elif logLevel == 'INFO':   useLevel = 20
 759         elif logLevel == 'DEBUG':  useLevel = 10
 760         else:                      useLevel = 0
 761         return useLevel
 762
 763     def _mkdir_p(self, filename):
 764         """Create missing directories from a full filename path like mkdir -p"""
 765
 766         if filename is None:
 767             return
 768
 769         folder=os.path.dirname(filename)
 770
 771         if folder == "":
 772             return
 773
 774         if not os.path.exists(folder):
 775             try:
 776                 os.makedirs(folder)
 777             except OSError as err:
 778                 print("error number %d creating %s directory to hold %s logfile: %s" %(err.errno, err.filename, filename, err.strerror))
 779                 sys.exit(2)
 780             except Exception as err:
 781                 print("error creating %s directory to hold %s logfile: %s" %(folder, filename, str(err)))
 782                 sys.exit(2)
 783
 784 if __name__ == "__main__":   # pragma: no cover
 785
 786     def __checkOneTime(line):
 787         format = r'[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:[0-9]{2},[0-9]{3}[+]00:00[|]'
 788         m = re.match(format, line)
 789         if not m:
 790             print("ERROR: time string did not match proper time format, %s" %line)
 791             print("\t: format=%s" % format)
 792             return 1
 793         return 0
 794
 795     def __checkTwoTimes(line, different):
 796         format = r'[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:([0-9]{2}),([0-9]{3})[+]00:00[|][0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9]{2}:[0-9]{2}:([0-9]{2}),([0-9]{3})[+]00:00[|]'
 797         m = re.match(format, line)
 798         if not m:
 799             print("ERROR: time strings did not match proper time format, %s" %line)
 800             print("\t: format=%s" % format)
 801             return 1
 802         second1 = int(m.group(1))
 803         msec1 = int(m.group(2))
 804         second2 = int(m.group(3))
 805         msec2 = int(m.group(4))
 806         if second1 > second2: second2 += 60
 807         t1 = second1 * 1000 + msec1
 808         t2 = second2 * 1000 + msec2
 809         diff = t2 - t1
 810         # print("t1=%d (%d,%d)  t2=%d (%d,%d), diff = %d" % (t1, second1, msec1, t2, second2, msec2, diff))
 811         if different:
 812             if diff < 500:
 813                 print("ERROR: times did not differ enough: %s" % line)
 814                 return 1
 815         else:
 816             if diff > 10:
 817                 print("ERROR: times were too far apart: %s" % line)
 818                 return 1
 819         return 0
 820
 821     def __checkBegTime(line):
 822         format = "begTime should be ([-0-9T:]+)"
 823         # print("checkBegTime(%s)" % line)
 824         strt = 'begTime should be '
 825         i = line.index(strt)
 826         rest = line[i+len(strt):].rstrip()
 827         if not line.startswith(rest + ","):
 828             print("ERROR: line %s should start with %s" % (line,rest))
 829             return 1
 830         return 0
 831
 832     def __checkLog(logfile, numLines, numFields):
 833         lineCount = 0
 834         errorCount = 0
 835         with open(logfile, "r") as fp:
 836             for line in fp:
 837                 # print("saw line %s" % line)
 838                 lineCount += 1
 839                 c = line.count('|')
 840                 if c != numFields:
 841                     print("ERROR: wrong number of fields. Expected %d, got %d: %s" % (numFields, c, line))
 842                     errorCount += 1
 843                 if re.search("should not appear", line):
 844                     print("ERROR: a line appeared that should not have appeared, %s" % line)
 845                     errorCount += 1
 846                 elif re.search("single time", line):
 847                     errorCount += __checkOneTime(line)
 848                 elif re.search("time should be the same", line):
 849                     errorCount += __checkTwoTimes(line, different=False)
 850                 elif re.search("time should be ", line):
 851                     errorCount += __checkTwoTimes(line, different=True)
 852                 elif re.search("begTime should be ", line):
 853                     errorCount += __checkBegTime(line)
 854                 else:
 855                     print("ERROR: an unknown message appeared, %s" % line)
 856                     errorCount += 1
 857
 858         if lineCount != numLines:
 859             print("ERROR: expected %d lines, but got %d lines" % (numLines, lineCount))
 860             errorCount += 1
 861         return errorCount
 862
 863     import os, argparse
 864     parser = argparse.ArgumentParser(description="test the CommonLogger functions")
 865     parser.add_argument("-k", "--keeplogs", help="Keep the log files after finishing the tests", action="store_true")
 866     parser.add_argument("-v", "--verbose", help="Print debugging messages", action="store_true")
 867     args = parser.parse_args()
 868
 869     spid = str(os.getpid())
 870     if args.keeplogs:
 871         spid = ""
 872     logcfg = "/tmp/cl.log" + spid + ".cfg"
 873     errorLog = "/tmp/cl.error" + spid + ".log"
 874     metricsLog = "/tmp/cl.metrics" + spid + ".log"
 875     auditLog = "/tmp/cl.audit" + spid + ".log"
 876     debugLog = "/tmp/cl.debug" + spid + ".log"
 877     if args.verbose: CommonLogger.verbose = True
 878
 879     import atexit
 880     def cleanupTmps():
 881         for f in [ logcfg, errorLog, metricsLog, auditLog, debugLog ]:
 882             try:
 883                 os.remove(f)
 884             except:
 885                 pass
 886     if not args.keeplogs:
 887         atexit.register(cleanupTmps)
 888
 889     with open(logcfg, "w") as o:
 890         o.write("error = " + errorLog + "\n" +
 891                 "errorLogLevel   = WARN\n" +
 892                 "metrics = " + metricsLog + "\n" +
 893                 "metricsLogLevel = INFO\n" +
 894                 "audit = " + auditLog + "\n" +
 895                 "auditLogLevel   = INFO\n" +
 896                 "debug = " + debugLog + "\n" +
 897                 "debugLogLevel   = DEBUG\n")
 898
 899     import uuid
 900     instanceUUID = uuid.uuid1()
 901     serviceName = "testharness"
 902     errorLogger = CommonLogger(logcfg, "error", style=CommonLogger.ErrorFile, instanceUUID=instanceUUID, serviceName=serviceName)
 903     debugLogger = CommonLogger(logcfg, "debug", style=CommonLogger.DebugFile, instanceUUID=instanceUUID, serviceName=serviceName)
 904     auditLogger = CommonLogger(logcfg, "audit", style=CommonLogger.AuditFile, instanceUUID=instanceUUID, serviceName=serviceName)
 905     metricsLogger = CommonLogger(logcfg, "metrics", style=CommonLogger.MetricsFile, instanceUUID=instanceUUID, serviceName=serviceName)
 906
 907     testsRun = 0
 908     errorCount = 0
 909     errorLogger.debug("error calling debug (should not appear)")
 910     errorLogger.info("error calling info (should not appear)")
 911     errorLogger.warn("error calling warn (single time)")
 912     errorLogger.error("error calling error (single time)")
 913     errorLogger.setStartRecordEvent()
 914     time.sleep(1)
 915     errorLogger.fatal("error calling fatal, after setStartRecordEvent and sleep (start should be ignored, single time)")
 916     testsRun += 6
 917     errorCount += __checkLog(errorLog, 3, 10)
 918
 919     auditLogger.debug("audit calling debug (should not appear)")
 920     auditLogger.info("audit calling info (time should be the same)")
 921     auditLogger.warn("audit calling warn (time should be the same)")
 922     auditLogger.error("audit calling error (time should be the same)")
 923     bt = auditLogger.getStartRecordEvent()
 924     # print("bt=%s" % bt)
 925     time.sleep(1)
 926     auditLogger.setStartRecordEvent()
 927     time.sleep(1)
 928     auditLogger.fatal("audit calling fatal, after setStartRecordEvent and sleep, time should be different)")
 929     time.sleep(1)
 930     auditLogger.fatal("audit calling fatal, begTime should be %s" % bt['begTime'], begTime=bt)
 931     testsRun += 7
 932     errorCount += __checkLog(auditLog, 5, 25)
 933
 934     debugLogger.debug("debug calling debug (single time)")
 935     debugLogger.info("debug calling info (single time)")
 936     debugLogger.warn("debug calling warn (single time)")
 937     debugLogger.setStartRecordEvent()
 938     time.sleep(1)
 939     debugLogger.error("debug calling error, after SetStartRecordEvent and sleep (start should be ignored, single time)")
 940     debugLogger.fatal("debug calling fatal (single time)")
 941     errorCount += __checkLog(debugLog, 5, 13)
 942     testsRun += 6
 943
 944     metricsLogger.debug("metrics calling debug (should not appear)")
 945     metricsLogger.info("metrics calling info (time should be the same)")
 946     metricsLogger.warn("metrics calling warn (time should be the same)")
 947     bt = metricsLogger.getStartRecordEvent()
 948     time.sleep(1)
 949     metricsLogger.setStartRecordEvent()
 950     time.sleep(1)
 951     metricsLogger.error("metrics calling error, after SetStartRecordEvent and sleep, time should be different")
 952     metricsLogger.fatal("metrics calling fatal (time should be the same)")
 953     time.sleep(1)
 954     metricsLogger.fatal("metrics calling fatal, begTime should be %s" % bt['begTime'], begTime=bt)
 955     testsRun += 6
 956     errorCount += __checkLog(metricsLog, 5, 28)
 957
 958     print("%d tests run, %d errors found" % (testsRun, errorCount))