Fix indexing work to improve error handling

We fix the default "read timeout" to be very large so that we don't
timeout prematurely and retry needlessly for template operations.

We have enhanced the error handling so that we don't always assume we
get a response object, and we dump out error messages that are
unexpected for now.

Further we also:
  * add support for counting the number of times we retry a bulk
    request
  * add the new es_put_template wrapper which properly handles the
    retries
  * pull the print() function calls out of es_index() so that the
    caller can decide what they want to emit, not have that inside
    the library
  * fix the missing "math" library module reference
  * fix how we mock out the timestamps to avoid global vs. local
    variable namespace conflicts
  * move the changes to the urllib3 and elasticsearch1 logging
    libraries to the code path were we actually use Elasticsearch

Author: portante

server/pbench/bin/gold/test-7.10.txt

@@ -1,5 +1,8 @@
 +++ Running indexing for test-7.10
-	done (end ts: 1900-01-01T00:00:00-UTC, duration: 0.00s, success: 514, duplicates: 0, failures: 0)
+Template:  pbench-unittests.run
+Template:  pbench-unittests.tool-data-iostat
+Template:  pbench-unittests.tool-data-pidstat
+	done templates (end ts: 1970-01-01T00:00:00-UTC, duration: 0.00s, successes: 3, retries: 0)
 Index:  pbench-unittests.result-data.2018-02-02 5
 Index:  pbench-unittests.run.2018-02 47
 Index:  pbench-unittests.tool-data-iostat.2018-02-02 120
@@ -7511,6 +7514,7 @@ len(actions) = 50
         "_type": "pbench-tool-data-pidstat"
     }
 ]
+	done indexing (end ts: 1970-01-01T00:00:00-UTC, duration: 0.00s, successes: 514, duplicates: 0, failures: 0, retries: 0)
 --- Finished indexing for test-7.10 (status=0)
 +++ pbench tree state
 /var/tmp/pbench-test-server/pbench

server/pbench/bin/gold/test-7.11.txt

@@ -1,5 +1,8 @@
 +++ Running indexing for test-7.11
-	done (end ts: 1900-01-01T00:00:00-UTC, duration: 0.00s, success: 46, duplicates: 0, failures: 0)
+Template:  pbench-unittests.run
+Template:  pbench-unittests.tool-data-iostat
+Template:  pbench-unittests.tool-data-pidstat
+	done templates (end ts: 1970-01-01T00:00:00-UTC, duration: 0.00s, successes: 3, retries: 0)
 Index:  pbench-unittests.result-data.2018-02-01 3
 Index:  pbench-unittests.run.2018-02 28
 Index:  pbench-unittests.tool-data-iostat.2018-02-01 15
@@ -3846,6 +3849,7 @@ len(actions) = 33
         "_type": "pbench-tool-data-iostat"
     }
 ]
+	done indexing (end ts: 1970-01-01T00:00:00-UTC, duration: 0.00s, successes: 46, duplicates: 0, failures: 0, retries: 0)
 --- Finished indexing for test-7.11 (status=0)
 +++ pbench tree state
 /var/tmp/pbench-test-server/pbench

server/pbench/bin/gold/test-7.12.txt

@@ -1,5 +1,8 @@
 +++ Running indexing for test-7.12
-	done (end ts: 1900-01-01T00:00:00-UTC, duration: 0.00s, success: 42397, duplicates: 2254, failures: 0)
+Template:  pbench-unittests.run
+Template:  pbench-unittests.tool-data-iostat
+Template:  pbench-unittests.tool-data-pidstat
+	done templates (end ts: 1970-01-01T00:00:00-UTC, duration: 0.00s, successes: 3, retries: 0)
 Index:  pbench-unittests.run.2018-02 56
 Index:  pbench-unittests.tool-data-iostat.2018-02-05 36
 Index:  pbench-unittests.tool-data-pidstat.2018-02-05 1554
@@ -2948,6 +2951,7 @@ len(actions) = 60
         "_type": "pbench-tool-data-iostat"
     }
 ]
+	done indexing (end ts: 1970-01-01T00:00:00-UTC, duration: 0.00s, successes: 42397, duplicates: 2254, failures: 0, retries: 0)
 --- Finished indexing for test-7.12 (status=0)
 +++ pbench tree state
 /var/tmp/pbench-test-server/pbench

server/pbench/bin/gold/test-7.4.txt

@@ -1,4 +1,8 @@
 +++ Running indexing for test-7.4
+Template:  pbench-unittests.run
+Template:  pbench-unittests.tool-data-iostat
+Template:  pbench-unittests.tool-data-pidstat
+      done templates (end ts: 1970-01-01T00:00:00-UTC, duration: 0.00s, successes: 3, retries: 0)
 Bad hostname in sosreport:  The sosreport did not collect a hostname other than 'localhost'
 --- Finished indexing for test-7.4 (status=10)
 +++ pbench tree state

server/pbench/bin/gold/test-7.5.txt

@@ -1,4 +1,8 @@
 +++ Running indexing for test-7.5
+Template:  pbench-unittests.run
+Template:  pbench-unittests.tool-data-iostat
+Template:  pbench-unittests.tool-data-pidstat
+      done templates (end ts: 1970-01-01T00:00:00-UTC, duration: 0.00s, successes: 3, retries: 0)
 Bad hostname in sosreport:  The sosreport did not collect a hostname other than 'localhost'
 --- Finished indexing for test-7.5 (status=10)
 +++ pbench tree state

server/pbench/bin/gold/test-7.6.txt

@@ -1,5 +1,8 @@
 +++ Running indexing for test-7.6
-	done (end ts: 1900-01-01T00:00:00-UTC, duration: 0.00s, success: 5, duplicates: 0, failures: 0)
+Template:  pbench-unittests.run
+Template:  pbench-unittests.tool-data-iostat
+Template:  pbench-unittests.tool-data-pidstat
+	done templates (end ts: 1970-01-01T00:00:00-UTC, duration: 0.00s, successes: 3, retries: 0)
 Index:  pbench-unittests.run.2015-09 5
 len(actions) = 5
 [
@@ -120,6 +123,7 @@ len(actions) = 5
         "_type": "pbench-run-toc-entry"
     }
 ]
+	done indexing (end ts: 1970-01-01T00:00:00-UTC, duration: 0.00s, successes: 5, duplicates: 0, failures: 0, retries: 0)
 --- Finished indexing for test-7.6 (status=0)
 +++ pbench tree state
 /var/tmp/pbench-test-server/pbench

server/pbench/bin/gold/test-7.7.txt

@@ -1,5 +1,8 @@
 +++ Running indexing for test-7.7
-	done (end ts: 1900-01-01T00:00:00-UTC, duration: 0.00s, success: 5, duplicates: 0, failures: 0)
+Template:  pbench-unittests.run
+Template:  pbench-unittests.tool-data-iostat
+Template:  pbench-unittests.tool-data-pidstat
+	done templates (end ts: 1970-01-01T00:00:00-UTC, duration: 0.00s, successes: 3, retries: 0)
 Index:  pbench-unittests.run.2015-09 5
 len(actions) = 5
 [
@@ -120,6 +123,7 @@ len(actions) = 5
         "_type": "pbench-run-toc-entry"
     }
 ]
+	done indexing (end ts: 1970-01-01T00:00:00-UTC, duration: 0.00s, successes: 5, duplicates: 0, failures: 0, retries: 0)
 --- Finished indexing for test-7.7 (status=0)
 +++ pbench tree state
 /var/tmp/pbench-test-server/pbench

server/pbench/bin/gold/test-7.8.txt

@@ -1,5 +1,8 @@
 +++ Running indexing for test-7.8
-	done (end ts: 1900-01-01T00:00:00-UTC, duration: 0.00s, success: 11778, duplicates: 0, failures: 0)
+Template:  pbench-unittests.run
+Template:  pbench-unittests.tool-data-iostat
+Template:  pbench-unittests.tool-data-pidstat
+	done templates (end ts: 1970-01-01T00:00:00-UTC, duration: 0.00s, successes: 3, retries: 0)
 Index:  pbench-unittests.result-data.2016-10-06 3
 Index:  pbench-unittests.run.2016-10 63
 Index:  pbench-unittests.tool-data-iostat.2016-10-06 27
@@ -45803,6 +45806,7 @@ len(actions) = 48
         "_type": "pbench-tool-data-iostat"
     }
 ]
+	done indexing (end ts: 1970-01-01T00:00:00-UTC, duration: 0.00s, successes: 11778, duplicates: 0, failures: 0, retries: 0)
 --- Finished indexing for test-7.8 (status=0)
 +++ pbench tree state
 /var/tmp/pbench-test-server/pbench

server/pbench/bin/gold/test-7.9.txt

@@ -1,5 +1,8 @@
 +++ Running indexing for test-7.9
-	done (end ts: 1900-01-01T00:00:00-UTC, duration: 0.00s, success: 3144, duplicates: 0, failures: 0)
+Template:  pbench-unittests.run
+Template:  pbench-unittests.tool-data-iostat
+Template:  pbench-unittests.tool-data-pidstat
+	done templates (end ts: 1970-01-01T00:00:00-UTC, duration: 0.00s, successes: 3, retries: 0)
 Index:  pbench-unittests.run.2017-04 24
 Index:  pbench-unittests.tool-data-iostat.2017-04-21 60
 Index:  pbench-unittests.tool-data-pidstat.2017-04-21 3060
@@ -1726,6 +1729,7 @@ len(actions) = 45
         "_type": "pbench-tool-data-pidstat"
     }
 ]
+	done indexing (end ts: 1970-01-01T00:00:00-UTC, duration: 0.00s, successes: 3144, duplicates: 0, failures: 0, retries: 0)
 --- Finished indexing for test-7.9 (status=0)
 +++ pbench tree state
 /var/tmp/pbench-test-server/pbench

server/pbench/bin/index-pbench

@@ -23,7 +23,7 @@ try:
 except ImportError:
     from elasticsearch import VERSION as es_VERSION, Elasticsearch
 
-from pbench import es_index
+from pbench import tstos, es_index, es_put_template
 
 
 _VERSION_ = "0.2.0.0"
@@ -33,8 +33,10 @@ _DEBUG    = 0
 # global - defaults to normal dict, ordered dict for unittests
 _dict_const = dict
 
-# 30 second timeout talking to Elasticsearch
-_read_timeout = 30
+# 100,000 minute timeout talking to Elasticsearch; basically we just don't
+# want to timeout waiting for Elasticsearch and then have to retry, as that
+# can add undue burden to the Elasticsearch cluster.
+_read_timeout = 100000*60
 
 # All indexing uses "create" (instead of "index") to avoid updating
 # existing records, allowing us to detect duplicates.
@@ -112,16 +114,12 @@ def fetch_mapping(mapping_fn):
         raise MappingFileError("Invalid mapping file: %s" % mapping_fn)
     return keys[0], mapping
 
-def es_template(es, options, INDEX_PREFIX, INDEX_VERSION, config):
+def es_template(es, options, INDEX_PREFIX, INDEX_VERSION, config, dbg=0):
     """Load the various Elasticsearch index templates required by pbench.
 
     We first load the pbench-run index templates, and then we construct and
     load the templates for each tool data index.
     """
-    if not es:
-        # Don't do anything if we don't have an Elasticsearch client object.
-        return
-
     index_settings = _dict_const(
         gateway=_dict_const(
             local=_dict_const(
@@ -181,7 +179,7 @@ def es_template(es, options, INDEX_PREFIX, INDEX_VERSION, config):
     for toolname,frag in tool_mapping_frags.items():
         tool_skel = copy.deepcopy(skel)
         tool_skel['properties'][toolname] = frag
-        tool_mapping = _dict_const(("pbench-tool-data-%s" % toolname, tool_skel))
+        tool_mapping = _dict_const([("pbench-tool-data-%s" % toolname, tool_skel)])
         tool_template_body = _dict_const(
             template='%s.tool-data-%s.*' % (INDEX_PREFIX, toolname),
             settings=index_settings,
@@ -192,7 +190,7 @@ def es_template(es, options, INDEX_PREFIX, INDEX_VERSION, config):
     results_mappings = _dict_const()
     for mapping_fn in glob.iglob(os.path.join(MAPPING_DIR, "result-*.json")):
         key, mapping = fetch_mapping(mapping_fn)
-        if options.debug_unittest:
+        if dbg > 0:
             print("fetch_mapping: {}".format(key))
             from pprint import pprint;
             pprint(mapping)
@@ -204,25 +202,26 @@ def es_template(es, options, INDEX_PREFIX, INDEX_VERSION, config):
         settings=index_settings,
         mappings=results_mappings)
 
-    if not es:
-        # Don't do anything if we don't have an Elasticsearch client object.
-        print(run_template_name, json.dumps(run_template_body, indent=4, sort_keys=True))
-        for name, body in tool_templates:
-            print(name, json.dumps(body, indent=4, sort_keys=True))
-        return
-
     # FIXME: We should query to see if a template exists, and only
     # create it if it does not, or if the version of it is older than
     # expected.
     try:
         # Pbench Run template
-        res = es.indices.put_template(name=run_template_name, body=run_template_body)
+        beg, end, retries = es_put_template(es, name=run_template_name, body=run_template_body)
+        successes = 1
         # Pbench Tool Data templates
         for name, body in tool_templates:
             tool_template_name = '%s.tool-data-%s' % (INDEX_PREFIX,name)
-            res = es.indices.put_template(name=tool_template_name, body=body)
+            _, end, retry_count = es_put_template(es, name=tool_template_name, body=body)
+            retries += retry_count
+            successes += 1
     except Exception as e:
         raise TemplateError(e)
+    else:
+        print("\tdone templates (end ts: %s, duration: %.2fs,"
+                " successes: %d, retries: %d)" % (
+            tstos(end), end - beg, successes, retries))
+        sys.stdout.flush()
 
 
 ###########################################################################
@@ -1821,7 +1820,7 @@ def main(options, args):
 
         # Create the various index templates
         if options.debug_time_operations: ts("es_template")
-        es_template(es, options, INDEX_PREFIX, INDEX_VERSION, config)
+        es_template(es, options, INDEX_PREFIX, INDEX_VERSION, config, dbg=_DEBUG)
 
         # returns 0 or 1
         if options.indexing_errors:
@@ -1831,6 +1830,12 @@ def main(options, args):
         with open(ie_filename, "w") as fp:
             if options.debug_time_operations: ts("es_index")
             res = es_index(es, actions, fp, dbg=_DEBUG)
+            beg, end, successes, duplicates, failures, retries = res
+            print("\tdone indexing (end ts: %s, duration: %.2fs,"
+                    " successes: %d, duplicates: %d, failures: %d, retries: %d)" % (
+                tstos(end), end - beg, successes, duplicates, failures, retries))
+            sys.stdout.flush()
+            res = 1 if failures > 0 else 0
 
     except ConfigFileNotSpecified as e:
         print(e, file=sys.stderr)