From 93d7080cc0b21cd562bc73ff39817febb4c99208 Mon Sep 17 00:00:00 2001 From: Nishant Bhardwaj Date: Wed, 11 Oct 2017 11:10:31 +0530 Subject: [PATCH] Fix #518: Add mloginfo --connections support for connection duration metrics (#530) * Add min/max/avg connection durations with new argument option --connstats. * Add nosetests for --connstats. * Add folder connstats to mtools/test/logfiles with more logfiles specific for connstats test. --- .../mloginfo/sections/connection_section.py | 103 +++++++++++++++++- ...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 +++++ mtools/test/test_mloginfo.py | 97 +++++++++++++++++ 10 files changed, 399 insertions(+), 3 deletions(-) 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/mloginfo/sections/connection_section.py b/mtools/mloginfo/sections/connection_section.py index 4d9aa55e..969e97bd 100644 --- a/mtools/mloginfo/sections/connection_section.py +++ b/mtools/mloginfo/sections/connection_section.py @@ -17,14 +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('--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): @@ -37,10 +37,33 @@ def run(self): ip_opened = defaultdict(lambda: 0) ip_closed = defaultdict(lambda: 0) + socket_exceptions = 0 + 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: + connections_start = defaultdict(lambda: START_TIME_EMPTY) + ipwise_sum_durations = defaultdict(lambda:0) + ipwise_count = defaultdict(lambda:0) + ipwise_min_connection_duration = defaultdict(lambda:MIN_DURATION_EMPTY) + ipwise_max_connection_duration = defaultdict(lambda:MAX_DURATION_EMPTY) + + min_connection_duration = MIN_DURATION_EMPTY + max_connection_duration = MAX_DURATION_EMPTY + + sum_durations = 0 + fullconn_counts = 0 + for logevent in self.mloginfo.logfile: line = logevent.line_str + pos = line.find('connection accepted') if pos != -1: # connection was opened, increase counter @@ -51,6 +74,20 @@ def run(self): ip, _ = tokens[3].split(':') ip_opened[ip] += 1 + if genstats: + connid = tokens[4].strip('#') + dt = logevent.datetime + + #Sanity checks + if connid.isdigit() == False or dt == None : + continue + + 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: # connection was closed, increase counter @@ -61,6 +98,47 @@ def run(self): ip, _ = tokens[2].split(':') 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) + dt = logevent.datetime + + #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)) + + 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 > 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 + + connections_start[end_connid] = END_TIME_ALREADY_FOUND + + if "SocketException" in line: socket_exceptions += 1 @@ -78,11 +156,30 @@ def run(self): print " total closed:", total_closed print " no unique IPs:", len(unique_ips) print "socket exceptions:", socket_exceptions + 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): opened = ip_opened[ip] if ip in ip_opened else 0 closed = ip_closed[ip] if ip in ip_closed else 0 - print "%-15s opened: %-8i closed: %-8i" % (ip, opened, closed) + 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 + 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 + 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) diff --git a/mtools/test/test_mloginfo.py b/mtools/test/test_mloginfo.py index 7323865f..0f0ddb1a 100644 --- a/mtools/test/test_mloginfo.py +++ b/mtools/test/test_mloginfo.py @@ -144,6 +144,103 @@ 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_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 self.tool.run('%s --queries' % self.logfile_path)