From d3bf6b0975e4824520bf97b772c19f78744f8dd9 Mon Sep 17 00:00:00 2001 From: Nishant Bhardwaj Date: Mon, 9 Oct 2017 17:30:18 +0530 Subject: [PATCH 1/6] Fix 518: Add min/max/avg connection durations --- .../mloginfo/sections/connection_section.py | 76 ++++++++++++++++++- mtools/test/logfiles/mongod_3_4_2.log | 27 +++++++ 2 files changed, 101 insertions(+), 2 deletions(-) create mode 100644 mtools/test/logfiles/mongod_3_4_2.log diff --git a/mtools/mloginfo/sections/connection_section.py b/mtools/mloginfo/sections/connection_section.py index 4d9aa55e..8bad0044 100644 --- a/mtools/mloginfo/sections/connection_section.py +++ b/mtools/mloginfo/sections/connection_section.py @@ -1,6 +1,6 @@ from base_section import BaseSection from collections import defaultdict -import re +from datetime import datetime, date, time try: from mtools.util.profile_collection import ProfileCollection @@ -37,10 +37,31 @@ def run(self): ip_opened = defaultdict(lambda: 0) ip_closed = defaultdict(lambda: 0) + socket_exceptions = 0 + connections_start = defaultdict(lambda: 0) + ipwise_sum_durations = defaultdict(lambda:0) + ipwise_count = defaultdict(lambda:0) + ipwise_min_connection_duration = defaultdict(lambda:9999999999) + ipwise_max_connection_duration = defaultdict(lambda:-1) + + min_connection_duration = 9999999999 + max_connection_duration = -1 + + sum_durations = 0 + fullconn_counts = 0 + for logevent in self.mloginfo.logfile: line = logevent.line_str + + dt = logevent.datetime + + #dt is type datetime is the start time +# print type(dt) +# print '{:%Y-%m-%d %H:%M:%S.%f%z}'.format(dt) +# print "Connection id %s, Date entry is %s" % (connid, '{:%Y-%m-%d %H:%M:%S.%f%z}'.format(dt)) + pos = line.find('connection accepted') if pos != -1: # connection was opened, increase counter @@ -51,6 +72,17 @@ def run(self): ip, _ = tokens[3].split(':') ip_opened[ip] += 1 + #initialize using default constructor + ipwise_min_connection_duration[ip] + ipwise_max_connection_duration[ip] + + connid = tokens[4].strip('#') + + if dt != None: + connections_start[connid] = dt +# print "connection id %s start %s" % (connid, connections_start[connid]) + + pos = line.find('end connection') if pos != -1: # connection was closed, increase counter @@ -61,6 +93,39 @@ def run(self): ip, _ = tokens[2].split(':') ip_closed[ip] += 1 + #The connection id value is stored just before end connection -> [conn385] end connection + tokens_conn = line[:pos].split(' ') + end_connid = tokens_conn[3].strip('[|conn|]') +# print "End connection id %s " % (end_connid) + + #Check if the log file recorded start of this connid + if connections_start[end_connid]: +# print "connection id end %s" % (connections_start[end_connid]) + + if dt != None: + dur = dt - connections_start[end_connid] + dur_in_sec = dur.seconds +# print "Duration of connection id %s is %d seconds" % (end_connid, dur_in_sec) + + if dur_in_sec < min_connection_duration: + min_connection_duration = dur_in_sec + + if dur_in_sec > max_connection_duration: + max_connection_duration = dur_in_sec + + if dur_in_sec < ipwise_min_connection_duration[ip]: + ipwise_min_connection_duration[ip] = dur_in_sec + + if dur_in_sec > ipwise_max_connection_duration[ip]: + ipwise_max_connection_duration[ip] = dur_in_sec + + sum_durations += dur.seconds + fullconn_counts += 1 + + ipwise_sum_durations[ip] += dur_in_sec + ipwise_count[ip] += 1 + + if "SocketException" in line: socket_exceptions += 1 @@ -83,6 +148,13 @@ def run(self): for ip in sorted(unique_ips, key=lambda x: ip_opened[x], reverse=True): opened = ip_opened[ip] if ip in ip_opened else 0 closed = ip_closed[ip] if ip in ip_closed else 0 + covered_count = ipwise_count[ip] if ip in ipwise_count else 1 + connection_duration_ip = ipwise_sum_durations[ip] if ip in ipwise_sum_durations else 0 + + print "%-15s opened: %-8i closed: %-8i dur-avg(s): %-8i dur-min(s): %-8i dur-max(s): %-8i" % (ip, opened, closed, connection_duration_ip/covered_count, ipwise_min_connection_duration[ip], ipwise_max_connection_duration[ip]) - print "%-15s opened: %-8i closed: %-8i" % (ip, opened, closed) print + + if fullconn_counts > 0: + print "Average connection duration across all IPs %d seconds, Minimum duration %d , Maximum duration %d" % (sum_durations/fullconn_counts, min_connection_duration, max_connection_duration) + diff --git a/mtools/test/logfiles/mongod_3_4_2.log b/mtools/test/logfiles/mongod_3_4_2.log new file mode 100644 index 00000000..62209c22 --- /dev/null +++ b/mtools/test/logfiles/mongod_3_4_2.log @@ -0,0 +1,27 @@ +2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] MongoDB starting : pid=10686 port=27017 dbpath=/Users/nishant/testcase/data 64-bit host=Nishants-MacBook-Pro.local +2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] db version v3.4.2 +2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] git version: 3f76e40c105fc223b3e5aac3e20dcd026b83b38b +2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] OpenSSL version: OpenSSL 0.9.8zh 14 Jan 2016 +2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] allocator: system +2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] modules: enterprise +2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] build environment: +2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] distarch: x86_64 +2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] target_arch: x86_64 +2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] options: { processManagement: { fork: true }, storage: { dbPath: "data" }, systemLog: { destination: "file", path: "data/log.file" } } +2017-10-09T12:44:35.031+0530 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=7680M,session_max=20000,eviction=(threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0), +2017-10-09T12:44:35.621+0530 I CONTROL [initandlisten] +2017-10-09T12:44:35.621+0530 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database. +2017-10-09T12:44:35.621+0530 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted. +2017-10-09T12:44:35.621+0530 I CONTROL [initandlisten] +2017-10-09T12:44:35.621+0530 I CONTROL [initandlisten] +2017-10-09T12:44:35.621+0530 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000 +2017-10-09T12:44:35.796+0530 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/Users/nishant/testcase/data/diagnostic.data' +2017-10-09T12:44:35.982+0530 I INDEX [initandlisten] build index on: admin.system.version properties: { v: 2, key: { version: 1 }, name: "incompatible_with_version_32", ns: "admin.system.version" } +2017-10-09T12:44:35.982+0530 I INDEX [initandlisten] building index using bulk method; build may temporarily use up to 500 megabytes of RAM +2017-10-09T12:44:36.005+0530 I INDEX [initandlisten] build index done. scanned 0 total records. 0 secs +2017-10-09T12:44:36.005+0530 I COMMAND [initandlisten] setting featureCompatibilityVersion to 3.4 +2017-10-09T12:44:36.005+0530 I NETWORK [thread1] waiting for connections on port 27017 +2017-10-09T12:44:40.143+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:54104 #1 (1 connection now open) +2017-10-09T12:44:43.673+0530 I - [conn1] end connection 127.0.0.1:54104 (1 connection now open) +2017-10-09T14:05:39.829+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:55065 #2 (1 connection now open) +2017-10-09T14:05:55.918+0530 I - [conn2] end connection 127.0.0.1:55065 (1 connection now open) From c89df5a22591941e0cd2ab79ec85004f73224777 Mon Sep 17 00:00:00 2001 From: Nishant Bhardwaj Date: Tue, 10 Oct 2017 11:18:14 +0530 Subject: [PATCH 2/6] Added option --stats to show min/max/avg connection durations --- .../mloginfo/sections/connection_section.py | 108 ++++++++++-------- 1 file changed, 58 insertions(+), 50 deletions(-) diff --git a/mtools/mloginfo/sections/connection_section.py b/mtools/mloginfo/sections/connection_section.py index 8bad0044..44cd412f 100644 --- a/mtools/mloginfo/sections/connection_section.py +++ b/mtools/mloginfo/sections/connection_section.py @@ -19,6 +19,7 @@ def __init__(self, mloginfo): # add --restarts flag to argparser self.mloginfo.argparser_sectiongroup.add_argument('--connections', action='store_true', help='outputs information about opened and closed connections') + self.mloginfo.argparser_sectiongroup.add_argument('--stats', action='store_true', help='outputs helpful statistics for connection duration (min/max/avg)') @property @@ -40,28 +41,25 @@ def run(self): socket_exceptions = 0 - connections_start = defaultdict(lambda: 0) - ipwise_sum_durations = defaultdict(lambda:0) - ipwise_count = defaultdict(lambda:0) - ipwise_min_connection_duration = defaultdict(lambda:9999999999) - ipwise_max_connection_duration = defaultdict(lambda:-1) + genstats = self.mloginfo.args['stats'] + if genstats: + genstats = True + connections_start = defaultdict(lambda: 0) + ipwise_sum_durations = defaultdict(lambda:0) + ipwise_count = defaultdict(lambda:0) + ipwise_min_connection_duration = defaultdict(lambda:9999999999) + ipwise_max_connection_duration = defaultdict(lambda:-1) - min_connection_duration = 9999999999 - max_connection_duration = -1 + min_connection_duration = 9999999999 + max_connection_duration = -1 - sum_durations = 0 - fullconn_counts = 0 + sum_durations = 0 + fullconn_counts = 0 for logevent in self.mloginfo.logfile: line = logevent.line_str - dt = logevent.datetime - - #dt is type datetime is the start time -# print type(dt) -# print '{:%Y-%m-%d %H:%M:%S.%f%z}'.format(dt) -# print "Connection id %s, Date entry is %s" % (connid, '{:%Y-%m-%d %H:%M:%S.%f%z}'.format(dt)) - + pos = line.find('connection accepted') if pos != -1: # connection was opened, increase counter @@ -72,15 +70,18 @@ def run(self): ip, _ = tokens[3].split(':') ip_opened[ip] += 1 - #initialize using default constructor - ipwise_min_connection_duration[ip] - ipwise_max_connection_duration[ip] + if genstats: + dt = logevent.datetime + + #initialize using default constructor + ipwise_min_connection_duration[ip] + ipwise_max_connection_duration[ip] - connid = tokens[4].strip('#') + connid = tokens[4].strip('#') - if dt != None: - connections_start[connid] = dt -# print "connection id %s start %s" % (connid, connections_start[connid]) + if dt != None: + connections_start[connid] = dt + # print "connection id %s start %s" % (connid, connections_start[connid]) pos = line.find('end connection') @@ -93,37 +94,40 @@ def run(self): ip, _ = tokens[2].split(':') ip_closed[ip] += 1 - #The connection id value is stored just before end connection -> [conn385] end connection - tokens_conn = line[:pos].split(' ') - end_connid = tokens_conn[3].strip('[|conn|]') -# print "End connection id %s " % (end_connid) + if genstats: + dt = logevent.datetime - #Check if the log file recorded start of this connid - if connections_start[end_connid]: -# print "connection id end %s" % (connections_start[end_connid]) + #The connection id value is stored just before end connection -> [conn385] end connection + tokens_conn = line[:pos].split(' ') + end_connid = tokens_conn[3].strip('[|conn|]') + # print "End connection id %s " % (end_connid) - if dt != None: - dur = dt - connections_start[end_connid] - dur_in_sec = dur.seconds -# print "Duration of connection id %s is %d seconds" % (end_connid, dur_in_sec) + #Check if the log file recorded start of this connid + if connections_start[end_connid]: + # print "connection id end %s" % (connections_start[end_connid]) - if dur_in_sec < min_connection_duration: - min_connection_duration = dur_in_sec + if dt != None: + dur = dt - connections_start[end_connid] + dur_in_sec = dur.seconds + # print "Duration of connection id %s is %d seconds" % (end_connid, dur_in_sec) - if dur_in_sec > max_connection_duration: - max_connection_duration = dur_in_sec + if dur_in_sec < min_connection_duration: + min_connection_duration = dur_in_sec - if dur_in_sec < ipwise_min_connection_duration[ip]: - ipwise_min_connection_duration[ip] = dur_in_sec + if dur_in_sec > max_connection_duration: + max_connection_duration = dur_in_sec - if dur_in_sec > ipwise_max_connection_duration[ip]: - ipwise_max_connection_duration[ip] = dur_in_sec + if dur_in_sec < ipwise_min_connection_duration[ip]: + ipwise_min_connection_duration[ip] = dur_in_sec - sum_durations += dur.seconds - fullconn_counts += 1 + if dur_in_sec > ipwise_max_connection_duration[ip]: + ipwise_max_connection_duration[ip] = dur_in_sec - ipwise_sum_durations[ip] += dur_in_sec - ipwise_count[ip] += 1 + sum_durations += dur.seconds + fullconn_counts += 1 + + ipwise_sum_durations[ip] += dur_in_sec + ipwise_count[ip] += 1 if "SocketException" in line: @@ -148,13 +152,17 @@ def run(self): for ip in sorted(unique_ips, key=lambda x: ip_opened[x], reverse=True): opened = ip_opened[ip] if ip in ip_opened else 0 closed = ip_closed[ip] if ip in ip_closed else 0 - covered_count = ipwise_count[ip] if ip in ipwise_count else 1 - connection_duration_ip = ipwise_sum_durations[ip] if ip in ipwise_sum_durations else 0 - print "%-15s opened: %-8i closed: %-8i dur-avg(s): %-8i dur-min(s): %-8i dur-max(s): %-8i" % (ip, opened, closed, connection_duration_ip/covered_count, ipwise_min_connection_duration[ip], ipwise_max_connection_duration[ip]) + if genstats: + covered_count = ipwise_count[ip] if ip in ipwise_count else 1 + connection_duration_ip = ipwise_sum_durations[ip] if ip in ipwise_sum_durations else 0 + + print "%-15s opened: %-8i closed: %-8i dur-avg(s): %-8i dur-min(s): %-8i dur-max(s): %-8i" % (ip, opened, closed, connection_duration_ip/covered_count, ipwise_min_connection_duration[ip], ipwise_max_connection_duration[ip]) + else: + print "%-15s opened: %-8i closed: %-8i" % (ip, opened, closed) print - if fullconn_counts > 0: + if genstats and fullconn_counts > 0: print "Average connection duration across all IPs %d seconds, Minimum duration %d , Maximum duration %d" % (sum_durations/fullconn_counts, min_connection_duration, max_connection_duration) From e67043efb856c91c1bfbbd7456fac565c4156948 Mon Sep 17 00:00:00 2001 From: Nishant Bhardwaj Date: Tue, 10 Oct 2017 12:27:08 +0530 Subject: [PATCH 3/6] Fix 518: Removed debug print commands and added import re as per original --- mtools/mloginfo/sections/connection_section.py | 11 +++-------- 1 file changed, 3 insertions(+), 8 deletions(-) diff --git a/mtools/mloginfo/sections/connection_section.py b/mtools/mloginfo/sections/connection_section.py index 44cd412f..67e13949 100644 --- a/mtools/mloginfo/sections/connection_section.py +++ b/mtools/mloginfo/sections/connection_section.py @@ -1,6 +1,7 @@ from base_section import BaseSection from collections import defaultdict from datetime import datetime, date, time +import re try: from mtools.util.profile_collection import ProfileCollection @@ -80,9 +81,7 @@ def run(self): connid = tokens[4].strip('#') if dt != None: - connections_start[connid] = dt - # print "connection id %s start %s" % (connid, connections_start[connid]) - + connections_start[connid] = dt pos = line.find('end connection') if pos != -1: @@ -100,16 +99,12 @@ def run(self): #The connection id value is stored just before end connection -> [conn385] end connection tokens_conn = line[:pos].split(' ') end_connid = tokens_conn[3].strip('[|conn|]') - # print "End connection id %s " % (end_connid) - #Check if the log file recorded start of this connid + #Check if we have the starting of this connid if connections_start[end_connid]: - # print "connection id end %s" % (connections_start[end_connid]) - if dt != None: dur = dt - connections_start[end_connid] dur_in_sec = dur.seconds - # print "Duration of connection id %s is %d seconds" % (end_connid, dur_in_sec) if dur_in_sec < min_connection_duration: min_connection_duration = dur_in_sec From 8861223a834f78fba0144088d98fccf850283f71 Mon Sep 17 00:00:00 2001 From: Nishant Bhardwaj Date: Tue, 10 Oct 2017 18:08:57 +0530 Subject: [PATCH 4/6] Fix:518: Implemented the review comment changes and additional following improvements: - Replace magic numbers with symbolic Constants - Fixed a bug where magic numbers were returned if the related ip does not cover all the ips - Raise NotImplemented Error if Multiple start/end datetimes were found for the same connection ID - Check for connection id is a digit - Add more performant/robust re pattern search on connid - Add nosetests for --connstats - Added folder connstats to mtools/test/logfiles with more logfiles specific to connstats testing ToDO: - Write nosetests for connstats using logfiles in mtools/test/logfiles/connstats folder --- .../mloginfo/sections/connection_section.py | 100 ++++++++++-------- mtools/test/logfiles/mongod_3_4_2.log | 27 ----- mtools/test/test_mloginfo.py | 20 ++++ 3 files changed, 76 insertions(+), 71 deletions(-) delete mode 100644 mtools/test/logfiles/mongod_3_4_2.log diff --git a/mtools/mloginfo/sections/connection_section.py b/mtools/mloginfo/sections/connection_section.py index 67e13949..d337a46c 100644 --- a/mtools/mloginfo/sections/connection_section.py +++ b/mtools/mloginfo/sections/connection_section.py @@ -1,6 +1,5 @@ from base_section import BaseSection from collections import defaultdict -from datetime import datetime, date, time import re try: @@ -18,15 +17,14 @@ class ConnectionSection(BaseSection): def __init__(self, mloginfo): BaseSection.__init__(self, mloginfo) - # add --restarts flag to argparser self.mloginfo.argparser_sectiongroup.add_argument('--connections', action='store_true', help='outputs information about opened and closed connections') - self.mloginfo.argparser_sectiongroup.add_argument('--stats', action='store_true', help='outputs helpful statistics for connection duration (min/max/avg)') + self.mloginfo.argparser_sectiongroup.add_argument('--connstats', action='store_true', help='outputs helpful statistics for connection duration (min/max/avg)') @property def active(self): """ return boolean if this section is active. """ - return self.mloginfo.args['connections'] + return self.mloginfo.args['connections'] or self.mloginfo.args['connstats'] def run(self): @@ -42,17 +40,23 @@ def run(self): socket_exceptions = 0 - genstats = self.mloginfo.args['stats'] + START_TIME_EMPTY=-11 + END_TIME_ALREADY_FOUND=-111 + MIN_DURATION_EMPTY=9999999999 + MAX_DURATION_EMPTY=-1 + + end_connid_pattern = re.compile(r'\[conn(\d+)\]') + + genstats = self.mloginfo.args['connstats'] if genstats: - genstats = True - connections_start = defaultdict(lambda: 0) + connections_start = defaultdict(lambda: START_TIME_EMPTY) ipwise_sum_durations = defaultdict(lambda:0) ipwise_count = defaultdict(lambda:0) - ipwise_min_connection_duration = defaultdict(lambda:9999999999) - ipwise_max_connection_duration = defaultdict(lambda:-1) + ipwise_min_connection_duration = defaultdict(lambda:MIN_DURATION_EMPTY) + ipwise_max_connection_duration = defaultdict(lambda:MAX_DURATION_EMPTY) - min_connection_duration = 9999999999 - max_connection_duration = -1 + min_connection_duration = MIN_DURATION_EMPTY + max_connection_duration = MAX_DURATION_EMPTY sum_durations = 0 fullconn_counts = 0 @@ -60,7 +64,6 @@ def run(self): for logevent in self.mloginfo.logfile: line = logevent.line_str - pos = line.find('connection accepted') if pos != -1: # connection was opened, increase counter @@ -72,16 +75,18 @@ def run(self): ip_opened[ip] += 1 if genstats: + connid = tokens[4].strip('#') dt = logevent.datetime - #initialize using default constructor - ipwise_min_connection_duration[ip] - ipwise_max_connection_duration[ip] + #Sanity checks + if connid.isdigit() == False or dt == None : + continue - connid = tokens[4].strip('#') - - if dt != None: - connections_start[connid] = dt + if connections_start[connid] != START_TIME_EMPTY: + raise NotImplementedError("Multiple start datetimes found for the same connection ID. Consider analysing one log sequence.") + + connections_start[connid] = dt + pos = line.find('end connection') if pos != -1: @@ -94,35 +99,39 @@ def run(self): ip_closed[ip] += 1 if genstats: + #The connection id value is stored just before end connection -> [conn385] end connection + end_connid = end_connid_pattern.search(line, re.M | re.I).group(1) dt = logevent.datetime - #The connection id value is stored just before end connection -> [conn385] end connection - tokens_conn = line[:pos].split(' ') - end_connid = tokens_conn[3].strip('[|conn|]') + #Sanity checks + if end_connid.isdigit() == False or dt == None or connections_start[end_connid] == START_TIME_EMPTY : + continue + + if connections_start[end_connid] == END_TIME_ALREADY_FOUND: + raise NotImplementedError("Multiple end datetimes found for the same connection ID %s. Consider analysing one log sequence." % (end_connid)) - #Check if we have the starting of this connid - if connections_start[end_connid]: - if dt != None: - dur = dt - connections_start[end_connid] - dur_in_sec = dur.seconds + dur = dt - connections_start[end_connid] + dur_in_sec = dur.seconds - if dur_in_sec < min_connection_duration: - min_connection_duration = dur_in_sec + if dur_in_sec < min_connection_duration: + min_connection_duration = dur_in_sec - if dur_in_sec > max_connection_duration: - max_connection_duration = dur_in_sec + if dur_in_sec > max_connection_duration: + max_connection_duration = dur_in_sec - if dur_in_sec < ipwise_min_connection_duration[ip]: - ipwise_min_connection_duration[ip] = dur_in_sec + if dur_in_sec < ipwise_min_connection_duration[ip]: + ipwise_min_connection_duration[ip] = dur_in_sec - if dur_in_sec > ipwise_max_connection_duration[ip]: - ipwise_max_connection_duration[ip] = dur_in_sec + if dur_in_sec > ipwise_max_connection_duration[ip]: + ipwise_max_connection_duration[ip] = dur_in_sec - sum_durations += dur.seconds - fullconn_counts += 1 + sum_durations += dur.seconds + fullconn_counts += 1 - ipwise_sum_durations[ip] += dur_in_sec - ipwise_count[ip] += 1 + ipwise_sum_durations[ip] += dur_in_sec + ipwise_count[ip] += 1 + + connections_start[end_connid] = END_TIME_ALREADY_FOUND if "SocketException" in line: @@ -142,6 +151,10 @@ def run(self): print " total closed:", total_closed print " no unique IPs:", len(unique_ips) print "socket exceptions:", socket_exceptions + if genstats and fullconn_counts > 0: + print "overall average connection duration(s):", sum_durations/fullconn_counts + print "overall minimum connection duration(s):", min_connection_duration + print "overall maximum connection duration(s):", max_connection_duration print for ip in sorted(unique_ips, key=lambda x: ip_opened[x], reverse=True): @@ -151,13 +164,12 @@ def run(self): if genstats: covered_count = ipwise_count[ip] if ip in ipwise_count else 1 connection_duration_ip = ipwise_sum_durations[ip] if ip in ipwise_sum_durations else 0 - - print "%-15s opened: %-8i closed: %-8i dur-avg(s): %-8i dur-min(s): %-8i dur-max(s): %-8i" % (ip, opened, closed, connection_duration_ip/covered_count, ipwise_min_connection_duration[ip], ipwise_max_connection_duration[ip]) + ipwise_min_connection_duration_final = ipwise_min_connection_duration[ip] if ipwise_min_connection_duration[ip]!=MIN_DURATION_EMPTY else 0 + ipwise_max_connection_duration_final = ipwise_max_connection_duration[ip] if ipwise_max_connection_duration[ip]!=MAX_DURATION_EMPTY else 0 + + print "%-15s opened: %-8i closed: %-8i dur-avg(s): %-8i dur-min(s): %-8i dur-max(s): %-8i" % (ip, opened, closed, connection_duration_ip/covered_count, ipwise_min_connection_duration_final, ipwise_max_connection_duration_final) else: print "%-15s opened: %-8i closed: %-8i" % (ip, opened, closed) print - if genstats and fullconn_counts > 0: - print "Average connection duration across all IPs %d seconds, Minimum duration %d , Maximum duration %d" % (sum_durations/fullconn_counts, min_connection_duration, max_connection_duration) - diff --git a/mtools/test/logfiles/mongod_3_4_2.log b/mtools/test/logfiles/mongod_3_4_2.log deleted file mode 100644 index 62209c22..00000000 --- a/mtools/test/logfiles/mongod_3_4_2.log +++ /dev/null @@ -1,27 +0,0 @@ -2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] MongoDB starting : pid=10686 port=27017 dbpath=/Users/nishant/testcase/data 64-bit host=Nishants-MacBook-Pro.local -2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] db version v3.4.2 -2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] git version: 3f76e40c105fc223b3e5aac3e20dcd026b83b38b -2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] OpenSSL version: OpenSSL 0.9.8zh 14 Jan 2016 -2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] allocator: system -2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] modules: enterprise -2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] build environment: -2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] distarch: x86_64 -2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] target_arch: x86_64 -2017-10-09T12:44:35.031+0530 I CONTROL [initandlisten] options: { processManagement: { fork: true }, storage: { dbPath: "data" }, systemLog: { destination: "file", path: "data/log.file" } } -2017-10-09T12:44:35.031+0530 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=7680M,session_max=20000,eviction=(threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0), -2017-10-09T12:44:35.621+0530 I CONTROL [initandlisten] -2017-10-09T12:44:35.621+0530 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database. -2017-10-09T12:44:35.621+0530 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted. -2017-10-09T12:44:35.621+0530 I CONTROL [initandlisten] -2017-10-09T12:44:35.621+0530 I CONTROL [initandlisten] -2017-10-09T12:44:35.621+0530 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000 -2017-10-09T12:44:35.796+0530 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/Users/nishant/testcase/data/diagnostic.data' -2017-10-09T12:44:35.982+0530 I INDEX [initandlisten] build index on: admin.system.version properties: { v: 2, key: { version: 1 }, name: "incompatible_with_version_32", ns: "admin.system.version" } -2017-10-09T12:44:35.982+0530 I INDEX [initandlisten] building index using bulk method; build may temporarily use up to 500 megabytes of RAM -2017-10-09T12:44:36.005+0530 I INDEX [initandlisten] build index done. scanned 0 total records. 0 secs -2017-10-09T12:44:36.005+0530 I COMMAND [initandlisten] setting featureCompatibilityVersion to 3.4 -2017-10-09T12:44:36.005+0530 I NETWORK [thread1] waiting for connections on port 27017 -2017-10-09T12:44:40.143+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:54104 #1 (1 connection now open) -2017-10-09T12:44:43.673+0530 I - [conn1] end connection 127.0.0.1:54104 (1 connection now open) -2017-10-09T14:05:39.829+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:55065 #2 (1 connection now open) -2017-10-09T14:05:55.918+0530 I - [conn2] end connection 127.0.0.1:55065 (1 connection now open) diff --git a/mtools/test/test_mloginfo.py b/mtools/test/test_mloginfo.py index 7323865f..b157b322 100644 --- a/mtools/test/test_mloginfo.py +++ b/mtools/test/test_mloginfo.py @@ -144,6 +144,26 @@ def test_connections_output(self): assert len(filter(lambda line: re.match(r'\d+\.\d+\.\d+\.\d+', line), lines)) > 1 + def test_connstats_output(self): + # different log file + self.tool.run('%s --connstats' % self.logfile_path) + output = sys.stdout.getvalue() + lines = output.splitlines() + assert any(map(lambda line: 'CONNECTIONS' in line, lines)) + + assert any(map(lambda line: 'total opened' in line, lines)) + assert any(map(lambda line: 'total closed' in line, lines)) + assert any(map(lambda line: 'unique IPs' in line, lines)) + assert any(map(lambda line: 'socket exceptions' in line, lines)) + assert any(map(lambda line: 'overall average connection duration(s):' in line, lines)) + assert any(map(lambda line: 'overall minimum connection duration(s):' in line, lines)) + assert any(map(lambda line: 'overall maximum connection duration(s):' in line, lines)) + + assert len(filter(lambda line: re.match(r'\d+\.\d+\.\d+\.\d+', line), lines)) > 1 + + + + def test_queries_output(self): # different log file self.tool.run('%s --queries' % self.logfile_path) From 3e6e14c33a437e1d1635ba577dff3f782111eac9 Mon Sep 17 00:00:00 2001 From: Nishant Bhardwaj Date: Tue, 10 Oct 2017 18:14:17 +0530 Subject: [PATCH 5/6] Fix-518: - Add logfiles specific to connstats --- ...9_connection_stats_end_connid_notdigit.log | 26 +++++++++++++++++++ ...9_connection_stats_end_connid_repeated.log | 26 +++++++++++++++++++ ...nection_stats_only_connection_accepted.log | 23 ++++++++++++++++ ...9_connection_stats_only_connection_end.log | 23 ++++++++++++++++ ...connection_stats_start_connid_notdigit.log | 26 +++++++++++++++++++ ...connection_stats_start_connid_repeated.log | 26 +++++++++++++++++++ ...ection_stats_start_end_connid_repeated.log | 26 +++++++++++++++++++ .../mongod_3_4-9_connection_stats.log | 26 +++++++++++++++++++ 8 files changed, 202 insertions(+) create mode 100644 mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_end_connid_notdigit.log create mode 100644 mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_end_connid_repeated.log create mode 100644 mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_only_connection_accepted.log create mode 100644 mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_only_connection_end.log create mode 100644 mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_start_connid_notdigit.log create mode 100644 mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_start_connid_repeated.log create mode 100644 mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_start_end_connid_repeated.log create mode 100644 mtools/test/logfiles/mongod_3_4-9_connection_stats.log diff --git a/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_end_connid_notdigit.log b/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_end_connid_notdigit.log new file mode 100644 index 00000000..a3864e54 --- /dev/null +++ b/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_end_connid_notdigit.log @@ -0,0 +1,26 @@ +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] MongoDB starting : pid=17340 port=27017 dbpath=/Users/nishant/testcase/data 64-bit host=Nishants-MacBook-Pro.local +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] db version v3.4.9 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] git version: 876ebee8c7dd0e2d992f36a848ff4dc50ee6603e +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] OpenSSL version: OpenSSL 0.9.8zh 14 Jan 2016 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] allocator: system +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] modules: none +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] build environment: +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] distarch: x86_64 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] target_arch: x86_64 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] options: { processManagement: { fork: true }, storage: { dbPath: "data" }, systemLog: { destination: "file", path: "data/log.file" } } +2017-10-10T16:46:52.604+0530 I - [initandlisten] Detected data files in /Users/nishant/testcase/data created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'. +2017-10-10T16:46:52.604+0530 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=7680M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0), +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database. +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted. +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000 +2017-10-10T16:46:53.555+0530 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/Users/nishant/testcase/data/diagnostic.data' +2017-10-10T16:46:53.556+0530 I NETWORK [thread1] waiting for connections on port 27017 +2017-10-10T16:47:06.585+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63573 #1 (1 connection now open) +2017-10-10T16:47:08.582+0530 I - [conn1] end connection 127.0.0.1:63573 (1 connection now open) +2017-10-10T16:47:29.081+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63579 #2 (1 connection now open) +2017-10-10T16:47:30.991+0530 I - [conn2] end connection 127.0.0.1:63579 (1 connection now open) +2017-10-10T16:47:35.446+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63580 #3 (1 connection now open) +2017-10-10T16:48:08.656+0530 I - [conn3TEST] end connection 127.0.0.1:63580 (1 connection now open) diff --git a/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_end_connid_repeated.log b/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_end_connid_repeated.log new file mode 100644 index 00000000..8ef48d81 --- /dev/null +++ b/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_end_connid_repeated.log @@ -0,0 +1,26 @@ +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] MongoDB starting : pid=17340 port=27017 dbpath=/Users/nishant/testcase/data 64-bit host=Nishants-MacBook-Pro.local +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] db version v3.4.9 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] git version: 876ebee8c7dd0e2d992f36a848ff4dc50ee6603e +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] OpenSSL version: OpenSSL 0.9.8zh 14 Jan 2016 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] allocator: system +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] modules: none +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] build environment: +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] distarch: x86_64 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] target_arch: x86_64 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] options: { processManagement: { fork: true }, storage: { dbPath: "data" }, systemLog: { destination: "file", path: "data/log.file" } } +2017-10-10T16:46:52.604+0530 I - [initandlisten] Detected data files in /Users/nishant/testcase/data created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'. +2017-10-10T16:46:52.604+0530 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=7680M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0), +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database. +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted. +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000 +2017-10-10T16:46:53.555+0530 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/Users/nishant/testcase/data/diagnostic.data' +2017-10-10T16:46:53.556+0530 I NETWORK [thread1] waiting for connections on port 27017 +2017-10-10T16:47:06.585+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63573 #1 (1 connection now open) +2017-10-10T16:47:08.582+0530 I - [conn1] end connection 127.0.0.1:63573 (1 connection now open) +2017-10-10T16:47:29.081+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63579 #2 (1 connection now open) +2017-10-10T16:47:30.991+0530 I - [conn2] end connection 127.0.0.1:63579 (1 connection now open) +2017-10-10T16:47:35.446+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63580 #3 (1 connection now open) +2017-10-10T16:48:08.656+0530 I - [conn2] end connection 127.0.0.1:63580 (1 connection now open) diff --git a/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_only_connection_accepted.log b/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_only_connection_accepted.log new file mode 100644 index 00000000..04243f9e --- /dev/null +++ b/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_only_connection_accepted.log @@ -0,0 +1,23 @@ +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] MongoDB starting : pid=17340 port=27017 dbpath=/Users/nishant/testcase/data 64-bit host=Nishants-MacBook-Pro.local +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] db version v3.4.9 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] git version: 876ebee8c7dd0e2d992f36a848ff4dc50ee6603e +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] OpenSSL version: OpenSSL 0.9.8zh 14 Jan 2016 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] allocator: system +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] modules: none +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] build environment: +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] distarch: x86_64 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] target_arch: x86_64 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] options: { processManagement: { fork: true }, storage: { dbPath: "data" }, systemLog: { destination: "file", path: "data/log.file" } } +2017-10-10T16:46:52.604+0530 I - [initandlisten] Detected data files in /Users/nishant/testcase/data created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'. +2017-10-10T16:46:52.604+0530 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=7680M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0), +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database. +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted. +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000 +2017-10-10T16:46:53.555+0530 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/Users/nishant/testcase/data/diagnostic.data' +2017-10-10T16:46:53.556+0530 I NETWORK [thread1] waiting for connections on port 27017 +2017-10-10T16:47:06.585+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63573 #1 (1 connection now open) +2017-10-10T16:47:29.081+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63579 #2 (1 connection now open) +2017-10-10T16:47:35.446+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63580 #3 (1 connection now open) diff --git a/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_only_connection_end.log b/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_only_connection_end.log new file mode 100644 index 00000000..f7b18b18 --- /dev/null +++ b/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_only_connection_end.log @@ -0,0 +1,23 @@ +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] MongoDB starting : pid=17340 port=27017 dbpath=/Users/nishant/testcase/data 64-bit host=Nishants-MacBook-Pro.local +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] db version v3.4.9 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] git version: 876ebee8c7dd0e2d992f36a848ff4dc50ee6603e +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] OpenSSL version: OpenSSL 0.9.8zh 14 Jan 2016 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] allocator: system +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] modules: none +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] build environment: +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] distarch: x86_64 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] target_arch: x86_64 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] options: { processManagement: { fork: true }, storage: { dbPath: "data" }, systemLog: { destination: "file", path: "data/log.file" } } +2017-10-10T16:46:52.604+0530 I - [initandlisten] Detected data files in /Users/nishant/testcase/data created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'. +2017-10-10T16:46:52.604+0530 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=7680M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0), +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database. +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted. +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000 +2017-10-10T16:46:53.555+0530 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/Users/nishant/testcase/data/diagnostic.data' +2017-10-10T16:46:53.556+0530 I NETWORK [thread1] waiting for connections on port 27017 +2017-10-10T16:47:08.582+0530 I - [conn1] end connection 127.0.0.1:63573 (1 connection now open) +2017-10-10T16:47:30.991+0530 I - [conn2] end connection 127.0.0.1:63579 (1 connection now open) +2017-10-10T16:48:08.656+0530 I - [conn3] end connection 127.0.0.1:63580 (1 connection now open) diff --git a/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_start_connid_notdigit.log b/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_start_connid_notdigit.log new file mode 100644 index 00000000..8c848df1 --- /dev/null +++ b/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_start_connid_notdigit.log @@ -0,0 +1,26 @@ +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] MongoDB starting : pid=17340 port=27017 dbpath=/Users/nishant/testcase/data 64-bit host=Nishants-MacBook-Pro.local +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] db version v3.4.9 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] git version: 876ebee8c7dd0e2d992f36a848ff4dc50ee6603e +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] OpenSSL version: OpenSSL 0.9.8zh 14 Jan 2016 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] allocator: system +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] modules: none +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] build environment: +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] distarch: x86_64 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] target_arch: x86_64 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] options: { processManagement: { fork: true }, storage: { dbPath: "data" }, systemLog: { destination: "file", path: "data/log.file" } } +2017-10-10T16:46:52.604+0530 I - [initandlisten] Detected data files in /Users/nishant/testcase/data created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'. +2017-10-10T16:46:52.604+0530 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=7680M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0), +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database. +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted. +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000 +2017-10-10T16:46:53.555+0530 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/Users/nishant/testcase/data/diagnostic.data' +2017-10-10T16:46:53.556+0530 I NETWORK [thread1] waiting for connections on port 27017 +2017-10-10T16:47:06.585+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63573 #1TEST (1 connection now open) +2017-10-10T16:47:08.582+0530 I - [conn1] end connection 127.0.0.1:63573 (1 connection now open) +2017-10-10T16:47:29.081+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63579 #2 (1 connection now open) +2017-10-10T16:47:30.991+0530 I - [conn2] end connection 127.0.0.1:63579 (1 connection now open) +2017-10-10T16:47:35.446+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63580 #3 (1 connection now open) +2017-10-10T16:48:08.656+0530 I - [conn3] end connection 127.0.0.1:63580 (1 connection now open) diff --git a/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_start_connid_repeated.log b/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_start_connid_repeated.log new file mode 100644 index 00000000..55ab6964 --- /dev/null +++ b/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_start_connid_repeated.log @@ -0,0 +1,26 @@ +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] MongoDB starting : pid=17340 port=27017 dbpath=/Users/nishant/testcase/data 64-bit host=Nishants-MacBook-Pro.local +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] db version v3.4.9 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] git version: 876ebee8c7dd0e2d992f36a848ff4dc50ee6603e +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] OpenSSL version: OpenSSL 0.9.8zh 14 Jan 2016 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] allocator: system +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] modules: none +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] build environment: +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] distarch: x86_64 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] target_arch: x86_64 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] options: { processManagement: { fork: true }, storage: { dbPath: "data" }, systemLog: { destination: "file", path: "data/log.file" } } +2017-10-10T16:46:52.604+0530 I - [initandlisten] Detected data files in /Users/nishant/testcase/data created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'. +2017-10-10T16:46:52.604+0530 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=7680M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0), +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database. +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted. +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000 +2017-10-10T16:46:53.555+0530 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/Users/nishant/testcase/data/diagnostic.data' +2017-10-10T16:46:53.556+0530 I NETWORK [thread1] waiting for connections on port 27017 +2017-10-10T16:47:06.585+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63573 #1 (1 connection now open) +2017-10-10T16:47:08.582+0530 I - [conn1] end connection 127.0.0.1:63573 (1 connection now open) +2017-10-10T16:47:29.081+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63579 #1 (1 connection now open) +2017-10-10T16:47:30.991+0530 I - [conn2] end connection 127.0.0.1:63579 (1 connection now open) +2017-10-10T16:47:35.446+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63580 #3 (1 connection now open) +2017-10-10T16:48:08.656+0530 I - [conn3] end connection 127.0.0.1:63580 (1 connection now open) diff --git a/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_start_end_connid_repeated.log b/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_start_end_connid_repeated.log new file mode 100644 index 00000000..d607dae8 --- /dev/null +++ b/mtools/test/logfiles/connstats/mongod_3_4-9_connection_stats_start_end_connid_repeated.log @@ -0,0 +1,26 @@ +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] MongoDB starting : pid=17340 port=27017 dbpath=/Users/nishant/testcase/data 64-bit host=Nishants-MacBook-Pro.local +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] db version v3.4.9 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] git version: 876ebee8c7dd0e2d992f36a848ff4dc50ee6603e +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] OpenSSL version: OpenSSL 0.9.8zh 14 Jan 2016 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] allocator: system +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] modules: none +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] build environment: +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] distarch: x86_64 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] target_arch: x86_64 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] options: { processManagement: { fork: true }, storage: { dbPath: "data" }, systemLog: { destination: "file", path: "data/log.file" } } +2017-10-10T16:46:52.604+0530 I - [initandlisten] Detected data files in /Users/nishant/testcase/data created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'. +2017-10-10T16:46:52.604+0530 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=7680M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0), +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database. +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted. +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000 +2017-10-10T16:46:53.555+0530 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/Users/nishant/testcase/data/diagnostic.data' +2017-10-10T16:46:53.556+0530 I NETWORK [thread1] waiting for connections on port 27017 +2017-10-10T16:47:06.585+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63573 #1 (1 connection now open) +2017-10-10T16:47:08.582+0530 I - [conn1] end connection 127.0.0.1:63573 (1 connection now open) +2017-10-10T16:47:29.081+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63579 #1 (1 connection now open) +2017-10-10T16:47:30.991+0530 I - [conn2] end connection 127.0.0.1:63579 (1 connection now open) +2017-10-10T16:47:35.446+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63580 #3 (1 connection now open) +2017-10-10T16:48:08.656+0530 I - [conn2] end connection 127.0.0.1:63580 (1 connection now open) diff --git a/mtools/test/logfiles/mongod_3_4-9_connection_stats.log b/mtools/test/logfiles/mongod_3_4-9_connection_stats.log new file mode 100644 index 00000000..00af2dcc --- /dev/null +++ b/mtools/test/logfiles/mongod_3_4-9_connection_stats.log @@ -0,0 +1,26 @@ +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] MongoDB starting : pid=17340 port=27017 dbpath=/Users/nishant/testcase/data 64-bit host=Nishants-MacBook-Pro.local +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] db version v3.4.9 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] git version: 876ebee8c7dd0e2d992f36a848ff4dc50ee6603e +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] OpenSSL version: OpenSSL 0.9.8zh 14 Jan 2016 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] allocator: system +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] modules: none +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] build environment: +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] distarch: x86_64 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] target_arch: x86_64 +2017-10-10T16:46:52.602+0530 I CONTROL [initandlisten] options: { processManagement: { fork: true }, storage: { dbPath: "data" }, systemLog: { destination: "file", path: "data/log.file" } } +2017-10-10T16:46:52.604+0530 I - [initandlisten] Detected data files in /Users/nishant/testcase/data created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'. +2017-10-10T16:46:52.604+0530 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=7680M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0), +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database. +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted. +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] +2017-10-10T16:46:53.553+0530 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000 +2017-10-10T16:46:53.555+0530 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/Users/nishant/testcase/data/diagnostic.data' +2017-10-10T16:46:53.556+0530 I NETWORK [thread1] waiting for connections on port 27017 +2017-10-10T16:47:06.585+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63573 #1 (1 connection now open) +2017-10-10T16:47:08.582+0530 I - [conn1] end connection 127.0.0.1:63573 (1 connection now open) +2017-10-10T16:47:29.081+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63579 #2 (1 connection now open) +2017-10-10T16:47:30.991+0530 I - [conn2] end connection 127.0.0.1:63579 (1 connection now open) +2017-10-10T16:47:35.446+0530 I NETWORK [thread1] connection accepted from 127.0.0.1:63580 #3 (1 connection now open) +2017-10-10T16:48:08.656+0530 I - [conn3] end connection 127.0.0.1:63580 (1 connection now open) From 6410659c8417348d7c26e635a5c51f9a88b61b0c Mon Sep 17 00:00:00 2001 From: Nishant Bhardwaj Date: Wed, 11 Oct 2017 10:29:28 +0530 Subject: [PATCH 6/6] Fix:518: - Fixed bug that raises an exception when connection id in end connection string is not a digit. - Now shows a dash(-) when no complete connections are found - Add nosetests for --connstats --- .../mloginfo/sections/connection_section.py | 20 +++-- mtools/test/test_mloginfo.py | 77 +++++++++++++++++++ 2 files changed, 92 insertions(+), 5 deletions(-) diff --git a/mtools/mloginfo/sections/connection_section.py b/mtools/mloginfo/sections/connection_section.py index d337a46c..969e97bd 100644 --- a/mtools/mloginfo/sections/connection_section.py +++ b/mtools/mloginfo/sections/connection_section.py @@ -99,8 +99,13 @@ def run(self): ip_closed[ip] += 1 if genstats: + + #Sanity check + if end_connid_pattern.search(line, re.M | re.I) == None : + continue + #The connection id value is stored just before end connection -> [conn385] end connection - end_connid = end_connid_pattern.search(line, re.M | re.I).group(1) + end_connid = end_connid_pattern.search(line, re.M | re.I).group(1) dt = logevent.datetime #Sanity checks @@ -151,10 +156,15 @@ def run(self): print " total closed:", total_closed print " no unique IPs:", len(unique_ips) print "socket exceptions:", socket_exceptions - if genstats and fullconn_counts > 0: - print "overall average connection duration(s):", sum_durations/fullconn_counts - print "overall minimum connection duration(s):", min_connection_duration - print "overall maximum connection duration(s):", max_connection_duration + if genstats : + if fullconn_counts > 0: + print "overall average connection duration(s):", sum_durations/fullconn_counts + print "overall minimum connection duration(s):", min_connection_duration + print "overall maximum connection duration(s):", max_connection_duration + else: + print "overall average connection duration(s): -" + print "overall minimum connection duration(s): -" + print "overall maximum connection duration(s): -" print for ip in sorted(unique_ips, key=lambda x: ip_opened[x], reverse=True): diff --git a/mtools/test/test_mloginfo.py b/mtools/test/test_mloginfo.py index b157b322..0f0ddb1a 100644 --- a/mtools/test/test_mloginfo.py +++ b/mtools/test/test_mloginfo.py @@ -161,8 +161,85 @@ def test_connstats_output(self): assert len(filter(lambda line: re.match(r'\d+\.\d+\.\d+\.\d+', line), lines)) > 1 + def test_connections_connstats_output(self): + # different log file + self.tool.run('%s --connections --connstats' % self.logfile_path) + output = sys.stdout.getvalue() + lines = output.splitlines() + assert any(map(lambda line: 'CONNECTIONS' in line, lines)) + assert any(map(lambda line: 'total opened' in line, lines)) + assert any(map(lambda line: 'total closed' in line, lines)) + assert any(map(lambda line: 'unique IPs' in line, lines)) + assert any(map(lambda line: 'socket exceptions' in line, lines)) + assert any(map(lambda line: 'overall average connection duration(s):' in line, lines)) + assert any(map(lambda line: 'overall minimum connection duration(s):' in line, lines)) + assert any(map(lambda line: 'overall maximum connection duration(s):' in line, lines)) + + def test_connstats_connid_repeated(self): + logfile_path = os.path.join(os.path.dirname(mtools.__file__), 'test/logfiles/connstats', 'mongod_3_4-9_connection_stats_start_connid_repeated.log') + try: + self.tool.run('%s --connstats' % logfile_path) + except NotImplementedError as e: + assert "Multiple start datetimes found for the same connection ID" in e.message + + def test_connstats_endconnid_repeated(self): + logfile_path = os.path.join(os.path.dirname(mtools.__file__), 'test/logfiles/connstats', 'mongod_3_4-9_connection_stats_end_connid_repeated.log') + try: + self.tool.run('%s --connstats' % logfile_path) + except NotImplementedError as e: + assert "Multiple end datetimes found for the same connection ID" in e.message + + def test_connstats_start_endconnid_repeated(self): + logfile_path = os.path.join(os.path.dirname(mtools.__file__), 'test/logfiles/connstats', 'mongod_3_4-9_connection_stats_start_end_connid_repeated.log') + try: + self.tool.run('%s --connstats' % logfile_path) + except NotImplementedError as e: + assert "Multiple start datetimes found for the same connection ID" in e.message + + def test_connstats_connid_not_digit(self): + logfile_path = os.path.join(os.path.dirname(mtools.__file__), 'test/logfiles/connstats', 'mongod_3_4-9_connection_stats_start_connid_notdigit.log') + + self.tool.run('%s --connstats' % logfile_path) + output = sys.stdout.getvalue() + lines = output.splitlines() + + assert any(map(lambda line: 'overall average connection duration(s): 17' in line, lines)) + assert any(map(lambda line: 'overall minimum connection duration(s): 1' in line, lines)) + assert any(map(lambda line: 'overall maximum connection duration(s): 33' in line, lines)) + def test_connstats_end_connid_not_digit(self): + logfile_path = os.path.join(os.path.dirname(mtools.__file__), 'test/logfiles/connstats', 'mongod_3_4-9_connection_stats_end_connid_notdigit.log') + + self.tool.run('%s --connstats' % logfile_path) + output = sys.stdout.getvalue() + lines = output.splitlines() + + assert any(map(lambda line: 'overall average connection duration(s): 1' in line, lines)) + assert any(map(lambda line: 'overall minimum connection duration(s): 1' in line, lines)) + assert any(map(lambda line: 'overall maximum connection duration(s): 1' in line, lines)) + + def test_connstats_only_connection_end(self): + logfile_path = os.path.join(os.path.dirname(mtools.__file__), 'test/logfiles/connstats', 'mongod_3_4-9_connection_stats_only_connection_end.log') + + self.tool.run('%s --connstats' % logfile_path) + output = sys.stdout.getvalue() + lines = output.splitlines() + + assert any(map(lambda line: 'overall average connection duration(s): -' in line, lines)) + assert any(map(lambda line: 'overall minimum connection duration(s): -' in line, lines)) + assert any(map(lambda line: 'overall maximum connection duration(s): -' in line, lines)) + + def test_connstats_only_connection_accepted(self): + logfile_path = os.path.join(os.path.dirname(mtools.__file__), 'test/logfiles/connstats', 'mongod_3_4-9_connection_stats_only_connection_accepted.log') + + self.tool.run('%s --connstats' % logfile_path) + output = sys.stdout.getvalue() + lines = output.splitlines() + + assert any(map(lambda line: 'overall average connection duration(s): -' in line, lines)) + assert any(map(lambda line: 'overall minimum connection duration(s): -' in line, lines)) + assert any(map(lambda line: 'overall maximum connection duration(s): -' in line, lines)) def test_queries_output(self): # different log file