github.com/ystia/yorc/v4@v4.3.0/storage/internal/elastic/es_utils.go (about)

     1  // Copyright 2019 Bull S.A.S. Atos Technologies - Bull, Rue Jean Jaures, B.P.68, 78340, Les Clayes-sous-Bois, France.
     2  //
     3  // Licensed under the Apache License, Version 2.0 (the "License");
     4  // you may not use this file except in compliance with the License.
     5  // You may obtain a copy of the License at
     6  //
     7  //      http://www.apache.org/licenses/LICENSE-2.0
     8  //
     9  // Unless required by applicable law or agreed to in writing, software
    10  // distributed under the License is distributed on an "AS IS" BASIS,
    11  // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
    12  // See the License for the specific language governing permissions and
    13  // limitations under the License.
    14  
    15  package elastic
    16  
    17  import (
    18  	"bytes"
    19  	"context"
    20  	"crypto/tls"
    21  	"crypto/x509"
    22  	"encoding/json"
    23  	"io"
    24  	"io/ioutil"
    25  	"net/http"
    26  	"strings"
    27  	"time"
    28  
    29  	elasticsearch6 "github.com/elastic/go-elasticsearch/v6"
    30  	"github.com/elastic/go-elasticsearch/v6/esapi"
    31  	"github.com/pkg/errors"
    32  	"github.com/ystia/yorc/v4/log"
    33  	"github.com/ystia/yorc/v4/storage/store"
    34  )
    35  
    36  var pfalse = false
    37  
    38  func prepareEsClient(elasticStoreConfig elasticStoreConf) (*elasticsearch6.Client, error) {
    39  	log.Printf("Elastic storage will run using this configuration: %+v", elasticStoreConfig)
    40  
    41  	esConfig := elasticsearch6.Config{Addresses: elasticStoreConfig.esUrls}
    42  
    43  	if len(elasticStoreConfig.caCertPath) > 0 {
    44  		log.Printf("Reading CACert file from %s", elasticStoreConfig.caCertPath)
    45  		caCert, err := ioutil.ReadFile(elasticStoreConfig.caCertPath)
    46  		if err != nil {
    47  			return nil, errors.Wrapf(err, "Not able to read Cert file from <%s>", elasticStoreConfig.caCertPath)
    48  		}
    49  		esConfig.CACert = caCert
    50  
    51  		if len(elasticStoreConfig.certPath) > 0 && len(elasticStoreConfig.keyPath) > 0 {
    52  			cert, err := tls.LoadX509KeyPair(elasticStoreConfig.certPath, elasticStoreConfig.keyPath)
    53  			if err != nil {
    54  				return nil, errors.Wrapf(err, "Not able to read cert and/or key file from <%s> and <%s>", elasticStoreConfig.certPath, elasticStoreConfig.keyPath)
    55  			}
    56  			caCertPool := x509.NewCertPool()
    57  			caCertPool.AppendCertsFromPEM(caCert)
    58  
    59  			// Setup HTTPS client
    60  			tlsConfig := &tls.Config{
    61  				Certificates: []tls.Certificate{cert},
    62  				RootCAs:      caCertPool,
    63  			}
    64  			tlsConfig.BuildNameToCertificate()
    65  			transport := &http.Transport{TLSClientConfig: tlsConfig}
    66  
    67  			esConfig.Transport = transport
    68  		}
    69  	}
    70  	if log.IsDebug() || elasticStoreConfig.traceRequests {
    71  		// In debug mode or when traceRequests option is activated, we add a custom logger that print requests & responses
    72  		log.Printf("\t- Tracing ES requests & response can be expensive and verbose !")
    73  		esConfig.Logger = &debugLogger{}
    74  	} else {
    75  		// otherwise log only failure are logger
    76  		esConfig.Logger = &defaultLogger{}
    77  	}
    78  
    79  	log.Printf("\t- Index prefix will be %s", elasticStoreConfig.indicePrefix+elasticStoreConfig.clusterID+"_")
    80  	log.Printf("\t- Will query ES for logs or events every %v and will wait for index refresh during %v",
    81  		elasticStoreConfig.esQueryPeriod, elasticStoreConfig.esRefreshWaitTimeout)
    82  	willRefresh := ""
    83  	if !elasticStoreConfig.esForceRefresh {
    84  		willRefresh = "not "
    85  	}
    86  	log.Printf("\t- Will %srefresh index before waiting for indexation", willRefresh)
    87  	log.Printf("\t- While migrating data, the max bulk request size will be %d documents and will never exceed %d kB",
    88  		elasticStoreConfig.maxBulkCount, elasticStoreConfig.maxBulkSize)
    89  	if log.IsDebug() {
    90  		log.Printf("\t- Will use this ES client configuration: %+v", esConfig)
    91  	}
    92  
    93  	esClient, e := elasticsearch6.NewClient(esConfig)
    94  	if e != nil {
    95  		return nil, errors.Wrapf(e, "Not able build ES client")
    96  	}
    97  	infoResponse, e := esClient.Info()
    98  	if e != nil {
    99  		return nil, errors.Wrapf(e, "The ES cluster info request failed")
   100  	}
   101  	log.Printf("Here is the ES cluster info: %+v", infoResponse)
   102  	return esClient, e
   103  }
   104  
   105  // Init ES index for logs or events storage: create it if not found.
   106  func initStorageIndex(c *elasticsearch6.Client, elasticStoreConfig elasticStoreConf, storeType string) error {
   107  
   108  	indexName := getIndexName(elasticStoreConfig, storeType)
   109  	log.Printf("Checking if index <%s> already exists", indexName)
   110  
   111  	// check if the sequences index exists
   112  	req := esapi.IndicesExistsRequest{
   113  		Index:           []string{indexName},
   114  		ExpandWildcards: "none",
   115  		AllowNoIndices:  &pfalse,
   116  	}
   117  	res, err := req.Do(context.Background(), c)
   118  	defer closeResponseBody("IndicesExistsRequest:"+indexName, res)
   119  
   120  	if err != nil {
   121  		return err
   122  	}
   123  
   124  	if res.StatusCode == 200 {
   125  		log.Printf("Indice %s was found, nothing to do !", indexName)
   126  		return nil
   127  	} else if res.StatusCode == 404 {
   128  		log.Printf("Indice %s was not found, let's create it !", indexName)
   129  
   130  		requestBodyData := buildInitStorageIndexQuery(elasticStoreConfig)
   131  
   132  		// indice doest not exist, let's create it
   133  		req := esapi.IndicesCreateRequest{
   134  			Index: indexName,
   135  			Body:  strings.NewReader(requestBodyData),
   136  		}
   137  		res, err := req.Do(context.Background(), c)
   138  		defer closeResponseBody("IndicesCreateRequest:"+indexName, res)
   139  		if err = handleESResponseError(res, "IndicesCreateRequest:"+indexName, requestBodyData, err); err != nil {
   140  			return err
   141  		}
   142  	} else {
   143  		return handleESResponseError(res, "IndicesExistsRequest:"+indexName, "", err)
   144  	}
   145  	return nil
   146  }
   147  
   148  // Perform a refresh query on ES cluster for this particular index.
   149  func refreshIndex(c *elasticsearch6.Client, indexName string) {
   150  	req := esapi.IndicesRefreshRequest{
   151  		Index:           []string{indexName},
   152  		ExpandWildcards: "none",
   153  		AllowNoIndices:  &pfalse,
   154  	}
   155  	res, err := req.Do(context.Background(), c)
   156  	err = handleESResponseError(res, "IndicesRefreshRequest:"+indexName, "", err)
   157  	if err != nil {
   158  		log.Println("An error occurred while refreshing index, due to : %+v", err)
   159  	}
   160  	defer closeResponseBody("IndicesRefreshRequest:"+indexName, res)
   161  }
   162  
   163  // Query ES for events or logs specifying the expected results 'size' and the sort 'order'.
   164  func doQueryEs(ctx context.Context, c *elasticsearch6.Client, conf elasticStoreConf,
   165  	index string,
   166  	query string,
   167  	waitIndex uint64,
   168  	size int,
   169  	order string,
   170  ) (hits int, values []store.KeyValueOut, lastIndex uint64, err error) {
   171  
   172  	log.Debugf("Search ES %s using query: %s", index, query)
   173  	lastIndex = waitIndex
   174  
   175  	res, e := c.Search(
   176  		c.Search.WithContext(ctx),
   177  		c.Search.WithIndex(index),
   178  		c.Search.WithSize(size),
   179  		c.Search.WithBody(strings.NewReader(query)),
   180  		// important sort on iid
   181  		c.Search.WithSort("iid:"+order),
   182  	)
   183  	if e != nil {
   184  		err = errors.Wrapf(e, "Failed to perform ES search on index %s, query was: <%s>, error was: %+v", index, query, e)
   185  		return
   186  	}
   187  	defer closeResponseBody("Search:"+index, res)
   188  
   189  	err = handleESResponseError(res, "Search:"+index, query, e)
   190  	if err != nil {
   191  		return
   192  	}
   193  
   194  	var r map[string]interface{}
   195  	if decodeErr := json.NewDecoder(res.Body).Decode(&r); decodeErr != nil {
   196  		err = errors.Wrapf(decodeErr,
   197  			"Not able to decode ES response while performing ES search on index %s, query was: <%s>, response code was %d (%s)",
   198  			index, query, res.StatusCode, res.Status(),
   199  		)
   200  		return
   201  	}
   202  
   203  	logShardsInfos(r)
   204  
   205  	hits = int(r["hits"].(map[string]interface{})["total"].(float64))
   206  	duration := int(r["took"].(float64))
   207  	log.Debugf("Search ES request on index %s took %dms, hits=%d, response code was %d (%s)", index, duration, hits, res.StatusCode, res.Status())
   208  
   209  	lastIndex = decodeEsQueryResponse(conf, index, waitIndex, size, r, &values)
   210  
   211  	log.Debugf("doQueryEs called result waitIndex: %d, LastIndex: %d, len(values): %d", waitIndex, lastIndex, len(values))
   212  	return hits, values, lastIndex, nil
   213  }
   214  
   215  // Decode the response and define the last index
   216  func decodeEsQueryResponse(conf elasticStoreConf, index string, waitIndex uint64, size int, r map[string]interface{}, values *[]store.KeyValueOut) (lastIndex uint64) {
   217  	lastIndex = waitIndex
   218  	// Print the ID and document source for each hit.
   219  	i := 0
   220  	for _, hit := range r["hits"].(map[string]interface{})["hits"].([]interface{}) {
   221  		id := hit.(map[string]interface{})["_id"].(string)
   222  		source := hit.(map[string]interface{})["_source"].(map[string]interface{})
   223  		iid := source["iidStr"]
   224  		iidUInt64, err := parseInt64StringToUint64(iid.(string))
   225  		if err != nil {
   226  			log.Printf("Not able to parse iid_str property %s as uint64, document id: %s, source: %+v, ignoring this document !", iid, id, source)
   227  		} else {
   228  			jsonString, err := json.Marshal(source)
   229  			if err != nil {
   230  				log.Printf("Not able to marshall document source, document id: %s, source: %+v, ignoring this document !", id, source)
   231  			} else {
   232  				// since the result is sorted on iid, we can use the last hit to define lastIndex
   233  				lastIndex = iidUInt64
   234  				if conf.traceEvents {
   235  					i++
   236  					waitTimestamp := _getTimestampFromUint64(waitIndex)
   237  					iidInt64 := _parseInt64StringToInt64(iid.(string))
   238  					iidTimestamp := time.Unix(0, iidInt64)
   239  					log.Printf("ESList-%s;%d,%v,%d,%d,%s,%v,%d,%d",
   240  						index, waitIndex, waitTimestamp, size, i, iid, iidTimestamp, iidInt64, lastIndex)
   241  				}
   242  				// append value to result
   243  				*values = append(*values, store.KeyValueOut{
   244  					Key:             id,
   245  					LastModifyIndex: iidUInt64,
   246  					Value:           source,
   247  					RawValue:        jsonString,
   248  				})
   249  			}
   250  		}
   251  	}
   252  	return
   253  }
   254  
   255  // Send the bulk request to ES and ensure no error is returned.
   256  func sendBulkRequest(c *elasticsearch6.Client, opeCount int, body *[]byte) error {
   257  	log.Printf("About to bulk request containing %d operations (%d bytes)", opeCount, len(*body))
   258  	if log.IsDebug() {
   259  		log.Debugf("About to send bulk request query to ES: %s", string(*body))
   260  	}
   261  
   262  	// Prepare ES bulk request
   263  	req := esapi.BulkRequest{
   264  		Body: bytes.NewReader(*body),
   265  	}
   266  	res, err := req.Do(context.Background(), c)
   267  	defer closeResponseBody("BulkRequest", res)
   268  
   269  	if err != nil {
   270  		return err
   271  	} else if res.IsError() {
   272  		return handleESResponseError(res, "BulkRequest", string(*body), err)
   273  	} else {
   274  		var rsp map[string]interface{}
   275  		err = json.NewDecoder(res.Body).Decode(&rsp)
   276  		if err != nil {
   277  			// Don't know if the bulk request response contains error so fail by default
   278  			return errors.Errorf(
   279  				"The bulk request succeeded (%s), but not able to decode the response, so not able to determine if bulk operations are correctly handled",
   280  				res.Status(),
   281  			)
   282  		}
   283  		if rsp["errors"].(bool) {
   284  			// The bulk request contains errors
   285  			return errors.Errorf("The bulk request succeeded, but the response contains errors : %+v", rsp)
   286  		}
   287  	}
   288  	log.Printf("Bulk request containing %d operations (%d bytes) has been accepted successfully", opeCount, len(*body))
   289  	return nil
   290  }
   291  
   292  // Consider the ES Response and wrap errors when needed
   293  func handleESResponseError(res *esapi.Response, requestDescription string, query string, requestError error) error {
   294  	if requestError != nil {
   295  		return errors.Wrapf(requestError, "Error while sending %s, query was: %s", requestDescription, query)
   296  	}
   297  	if res.IsError() {
   298  		return errors.Errorf(
   299  			"An error was returned by ES while sending %s, status was %s, query was: %s, response: %+v",
   300  			requestDescription, res.Status(), query, res.String())
   301  	}
   302  	return nil
   303  }
   304  
   305  // Close response body, if an error occur, just print it
   306  func closeResponseBody(requestDescription string, res *esapi.Response) {
   307  	if res != nil && res.Body != nil {
   308  		err := res.Body.Close()
   309  		if err != nil {
   310  			log.Printf("[%s] Was not able to close resource response body, error was: %+v", requestDescription, err)
   311  		}
   312  	}
   313  }
   314  
   315  // Log shards stats
   316  func logShardsInfos(r map[string]interface{}) {
   317  	si := r["_shards"].(map[string]interface{})
   318  
   319  	duration := int(r["took"].(float64))
   320  
   321  	tt := int(si["total"].(float64))
   322  	ts := int(si["successful"].(float64))
   323  
   324  	if ts < tt {
   325  		log.Printf("[Warn] ES Uncomplete response: %d/%d shards (%dms)", ts, tt, duration)
   326  	}
   327  }
   328  
   329  type debugLogger struct{}
   330  
   331  // RequestBodyEnabled makes the client pass request body to logger
   332  func (l *debugLogger) RequestBodyEnabled() bool { return true }
   333  
   334  // ResponseBodyEnabled makes the client pass response body to logger
   335  func (l *debugLogger) ResponseBodyEnabled() bool { return true }
   336  
   337  // LogRoundTrip will use log to debug ES request and response (when debug is activated)
   338  func (l *debugLogger) LogRoundTrip(
   339  	req *http.Request,
   340  	res *http.Response,
   341  	err error,
   342  	start time.Time,
   343  	dur time.Duration,
   344  ) error {
   345  
   346  	var level string
   347  	switch {
   348  	case err != nil:
   349  		level = "Exception"
   350  	case res != nil && res.StatusCode > 0 && res.StatusCode < 300:
   351  		level = "Success"
   352  	case res != nil && res.StatusCode > 299 && res.StatusCode < 500:
   353  		level = "Warn"
   354  	case res != nil && res.StatusCode > 499:
   355  		level = "Error"
   356  	default:
   357  		level = "Unknown"
   358  	}
   359  
   360  	var reqBuffer, resBuffer bytes.Buffer
   361  	if req != nil && req.Body != nil && req.Body != http.NoBody {
   362  		// We explicitly ignore errors here since it's a debug feature
   363  		_, _ = io.Copy(&reqBuffer, req.Body)
   364  	}
   365  	reqStr := reqBuffer.String()
   366  	if res != nil && res.Body != nil && res.Body != http.NoBody {
   367  		// We explicitly ignore errors here since it's a debug feature
   368  		_, _ = io.Copy(&resBuffer, res.Body)
   369  	}
   370  	resStr := resBuffer.String()
   371  	log.Printf("ES Request [%s][%v][%s][%s][%d][%v] [%+v] : [%+v]",
   372  		level, start, req.Method, req.URL.String(), res.StatusCode, dur, reqStr, resStr)
   373  
   374  	return nil
   375  }
   376  
   377  type defaultLogger struct{}
   378  
   379  // RequestBodyEnabled makes the client pass request body to logger
   380  func (l *defaultLogger) RequestBodyEnabled() bool { return true }
   381  
   382  // ResponseBodyEnabled makes the client pass response body to logger
   383  func (l *defaultLogger) ResponseBodyEnabled() bool { return true }
   384  
   385  // LogRoundTrip will use log to debug ES request and response (when debug is activated)
   386  func (l *defaultLogger) LogRoundTrip(
   387  	req *http.Request,
   388  	res *http.Response,
   389  	err error,
   390  	start time.Time,
   391  	dur time.Duration,
   392  ) error {
   393  
   394  	var level string
   395  	var errType string
   396  	var errReason string
   397  
   398  	switch {
   399  	case err != nil:
   400  		level = "Exception"
   401  	case res != nil && res.StatusCode > 0 && res.StatusCode < 300:
   402  		return nil
   403  	case res != nil && res.StatusCode > 299 && res.StatusCode < 500:
   404  		level = "Warn"
   405  	case res != nil && res.StatusCode > 499:
   406  		errType, errReason = extractEsError(res)
   407  		level = "Error"
   408  	default:
   409  		level = "Unknown"
   410  	}
   411  
   412  	if errType == "" && errReason == "" {
   413  		log.Printf("ES Request [%s][%v][%s][%s][%d][%v]",
   414  			level, start, req.Method, req.URL.String(), res.StatusCode, dur)
   415  	} else {
   416  		log.Printf("ES Request [%s][%v][%s][%s][%d][%v][%s][%s]",
   417  			level, start, req.Method, req.URL.String(), res.StatusCode, dur, errType, errReason)
   418  	}
   419  	return nil
   420  }
   421  
   422  func extractEsError(response *http.Response) (errType, errReason string) {
   423  	var rb map[string]interface{}
   424  	var rv interface{}
   425  	var ok bool
   426  
   427  	errType = "N/A"
   428  	errReason = "N/A"
   429  
   430  	if err := json.NewDecoder(response.Body).Decode(&rb); err != nil {
   431  		return
   432  	}
   433  
   434  	if rv, ok = rb["error"]; !ok {
   435  		return
   436  	}
   437  
   438  	if rb, ok = rv.(map[string]interface{}); !ok {
   439  		return
   440  	}
   441  
   442  	if rv, ok = rb["type"]; ok {
   443  		errType, _ = rv.(string)
   444  	}
   445  
   446  	if rv, ok = rb["reason"]; ok {
   447  		errReason, _ = rv.(string)
   448  	}
   449  
   450  	return
   451  }