fixed GH-7 by coping with commas in timestamps (and testing them in 001)

Author: ben-spiller

CHANGELOG.rst

@@ -1,8 +1,13 @@
 3.8 (in development)
 --------------------
+Enhancements:
 - Added support for analysing logs containing the "id    | " prefixes added when running a correlator inside docker. 
-- Improved sort order of log files to only include time unless we know there are multiple different instances. 
+- Improved sort order of log files to only include time when we know there are multiple different instances. 
+- Moved sent events/tx to a secondary axis so that the event rate chart lines up with other charts with two axes. 
+
+Bug fixes:
 - Fixed error when si/so have NaN values which can happen occasionally. 
+- Fixed parse failures when lines contain "," in the timestamp which can happen with some Java logging libraries. 
 
 3.7
 ---

apamax/log_analyzer.py

@@ -5,7 +5,7 @@
 It extracts and summarizes information from status lines and other log messages.
 
 
-Copyright (c) 2019-2021 Software AG, Darmstadt, Germany and/or its licensors
+Copyright (c) 2019-2022 Software AG, Darmstadt, Germany and/or its licensors
 
 Licensed under the Apache License, Version 2.0 (the "License"); you may not use this
 file except in compliance with the License. You may obtain a copy of the License at
@@ -19,7 +19,7 @@
 
 """
 
-__date__ = '2020-07-10' 
+__date__ = '2022-01-07' 
 __version__ = '3.8.dev/'+__date__
 __author__ = "Apama community"
 __license__ = "Apache 2.0"
@@ -137,7 +137,7 @@ class LogLine(object):
 	@ivar extraLines: unassigned, or a list of strings which are extra lines logically part of this one (typically for warn/error stacks etc)
 	"""
 	#                          date                                        level     thread       apama-ctrl/std cat  message
-	LINE_REGEX = re.compile(r'(\d\d\d\d-\d\d-\d\d \d\d:\d\d:\d\d[.]\d\d\d) ([A-Z#]+) +\[([^\]]+)\] ([^-]*)-( <[^>]+>)? (.*)')
+	LINE_REGEX = re.compile(r'(\d\d\d\d-\d\d-\d\d \d\d:\d\d:\d\d[.,]\d\d\d) ([A-Z#]+) +\[([^\]]+)\] ([^-]*)-( <[^>]+>)? (.*)')
 
 	__slots__ = ['line', 'lineno', 'message', 'level', '__details', 'extraLines'] # be memory-efficient
 	def __init__(self, line, lineno):
@@ -218,9 +218,16 @@ def getDateTime(self):
 			return det['datetime']
 
 		try:
-			d = datetime.datetime.strptime(self.getDetails()['datetimestring'], '%Y-%m-%d %H:%M:%S.%f')
+			dts = det['datetimestring']
+			if not dts: 
+				log.debug('Cannot find date time string in line: %s', det['datetimestring'], self.line)
+				return None
+			if dts[19:20] == ',': 
+				dts = dts[:19]+'.'+dts[20:] # for german locales
+			d = datetime.datetime.strptime(dts, '%Y-%m-%d %H:%M:%S.%f')
+			#assert d, line
 		except Exception as ex: # might not be a valid line
-			log.debug('Cannot parse date time from "%s": %s - from line: %s', self.getDetails()['datetimestring'], ex, self.line)
+			log.debug('Cannot parse date time from "%s": %s - from line: %s', det['datetimestring'], ex, self.line)
 			return None
 		det['datetime'] = d
 		return d
@@ -1076,15 +1083,17 @@ def handleWarnOrError(self, file, isError, line, **extra):
 
 		tracker = tracker.setdefault(normmsg, {})
 		tracker = tracker.setdefault(self.currentpath, {})
+		#assert line.getDateTime(), line
 		if not tracker:
 			tracker['first'] = tracker['last'] = line
 			tracker['count'] = 1
 			tracker['samples'] = []
 		else:
-			if tracker['first'].getDateTime() > line.getDateTime():
-				tracker['first'] = line
-			if tracker['last'].getDateTime() < line.getDateTime():
-				tracker['last'] = line
+			if line.getDateTime():
+				if tracker['first'].getDateTime() and tracker['first'].getDateTime() > line.getDateTime():
+					tracker['first'] = line
+				if tracker['last'].getDateTime() and tracker['last'].getDateTime() < line.getDateTime():
+					tracker['last'] = line
 			tracker['count'] += 1
 
 		tracker['samples'].append(line)

tests/correctness/Cor_001/Input/mycorrelator.log

@@ -74,5 +74,5 @@
 2019-04-09 13:57:22.774 ##### [32376] - Component ID: correlator (correlator/6677878040143647328/6677878040143647328)
 2019-04-09 13:57:22.774 ##### [32376] - Correlator, version 10.3.1.0.348044, running
 2019-04-09 13:57:27.770 INFO  [22872] - Correlator Status: sm=3 nctx=4 ls=50000 rq=6 iq=7 oq=8 icq=9 lcn="slowest consumer" lcq=10 lct=12.34 rx=13 tx=14 rt=15 nc=16 vm=17111222 pm=18111 runq=19 si=20.61 so=21.6 srn="slowest consumer" srq=22 jvm=231111
-2019-04-09 13:57:32.770 INFO  [22872] - Correlator Status: sm=0 nctx=1 ls=10 rq=0 iq=0 oq=0 icq=0 lcn="<none>" lcq=0 lct=0.0 rx=0 tx=0 rt=0 nc=0 vm=22580 pm=25312 runq=0 si=0.0 so=0.0 srn="<none>" srq=0 jvm=0
+2019-04-09 13:57:32,770 INFO  [22872] - Correlator Status: sm=0 nctx=1 ls=10 rq=0 iq=0 oq=0 icq=0 lcn="<none>" lcq=0 lct=0.0 rx=0 tx=0 rt=0 nc=0 vm=22580 pm=25312 runq=0 si=0.0 so=0.0 srn="<none>" srq=0 jvm=0
 2019-04-09 13:57:37.769 INFO  [22872] - Correlator Status: sm=0 nctx=1 ls=0 rq=0 iq=0 oq=0 icq=0 lcn="<none>" lcq=0 lct=0.0 rx=0 tx=0 rt=0 nc=0 vm=22580 pm=25312 runq=0 si=0.4 so=0.0 srn="<none>" srq=0 jvm=0

tests/correctness/Cor_001/pysystest.xml

@@ -7,6 +7,8 @@
     Check for correct extraction of main "Correlator Status:" lines, using canned log files. 
     Touch-tests CSV output format and JSON. 
     This is a general test that does not hardcode specific values. 
+    Also checks that lines with a comma delimiter for milliseconds can be read OK (happens with some Java logging 
+    libraries in European locales)
 ]]>
     </purpose>
   </description>