osdf/logging/onap_common_v1/CommonLogger.py

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