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 }