diff --git a/agents/libagents.go b/agents/libagents.go index 7f66a1e17..a880b999d 100644 --- a/agents/libagents.go +++ b/agents/libagents.go @@ -63,10 +63,17 @@ func processRequest(ctx *context.Context, reqProcessor *config.RequestProcessor, } } - if reqProcessor.Flags.Has(utils.MetaLog) { + if reqProcessor.Flags.Has(utils.MetaLog) || reqType == utils.MetaDryRun { + logPrefix := "LOG" + if reqType == utils.MetaDryRun { + logPrefix = "DRY_RUN" + } utils.Logger.Info( - fmt.Sprintf("<%s> LOG, processorID: %s, %s message: %s", - agentName, reqProcessor.ID, strings.ToLower(agentName[:len(agentName)-5]), agReq.Request.String())) + fmt.Sprintf("<%s> %s, processorID: %s, %s message: %s", + agentName, logPrefix, reqProcessor.ID, strings.ToLower(agentName[:len(agentName)-5]), agReq.Request.String())) + utils.Logger.Info( + fmt.Sprintf("<%s> %s, processorID: %s, CGREvent: %s", + agentName, logPrefix, reqProcessor.ID, utils.ToIJSON(cgrEv))) } replyState := utils.OK @@ -74,10 +81,7 @@ func processRequest(ctx *context.Context, reqProcessor *config.RequestProcessor, default: return false, fmt.Errorf("unknown request type: <%s>", reqType) case utils.MetaNone: // do nothing on CGRateS side - case utils.MetaDryRun: - utils.Logger.Info( - fmt.Sprintf("<%s> DRY_RUN, processorID: %s, %sMessage: %s", - agentName, reqProcessor.ID, agentName[:len(agentName)-5], agReq.Request.String())) + case utils.MetaDryRun: // do nothing on CGRateS side, logging handled above case utils.MetaAuthorize: authArgs := sessions.NewV1AuthorizeArgs( reqProcessor.Flags.GetBool(utils.MetaAttributes), @@ -229,15 +233,14 @@ func processRequest(ctx *context.Context, reqProcessor *config.RequestProcessor, return } endTime := time.Now() - if reqProcessor.Flags.Has(utils.MetaLog) { + if reqProcessor.Flags.Has(utils.MetaLog) || reqType == utils.MetaDryRun { + logPrefix := "LOG" + if reqType == utils.MetaDryRun { + logPrefix = "DRY_RUN" + } utils.Logger.Info( - fmt.Sprintf("<%s> LOG, %s reply: %s", - agentName, agentName[:len(agentName)-5], agReq.Reply)) - } - if reqType == utils.MetaDryRun { - utils.Logger.Info( - fmt.Sprintf("<%s> DRY_RUN, %s reply: %s", - agentName, agentName[:len(agentName)-5], agReq.Reply)) + fmt.Sprintf("<%s> %s, %s reply: %s", + agentName, logPrefix, agentName[:len(agentName)-5], agReq.Reply)) } if reqProcessor.Flags.Has(utils.MetaDryRun) { return true, nil diff --git a/agents/radagent.go b/agents/radagent.go index ad0d21abe..155ec64bb 100644 --- a/agents/radagent.go +++ b/agents/radagent.go @@ -335,10 +335,17 @@ func (ra *RadiusAgent) processRequest(req *radigo.Packet, reqProcessor *config.R err = nil // reset the error and continue the processing } } - if reqProcessor.Flags.Has(utils.MetaLog) { + if reqProcessor.Flags.Has(utils.MetaLog) || reqType == utils.MetaDryRun { + logPrefix := "LOG" + if reqType == utils.MetaDryRun { + logPrefix = "DRY_RUN" + } utils.Logger.Info( - fmt.Sprintf("<%s> LOG, processorID: %s, radius message: %s", - utils.RadiusAgent, reqProcessor.ID, agReq.Request.String())) + fmt.Sprintf("<%s> %s, processorID: %s, radius message: %s", + utils.RadiusAgent, logPrefix, reqProcessor.ID, agReq.Request.String())) + utils.Logger.Info( + fmt.Sprintf("<%s> %s, processorID: %s, CGREvent: %s", + utils.RadiusAgent, logPrefix, reqProcessor.ID, utils.ToIJSON(cgrEv))) } replyState := utils.OK @@ -346,10 +353,7 @@ func (ra *RadiusAgent) processRequest(req *radigo.Packet, reqProcessor *config.R default: return false, fmt.Errorf("unknown request type: <%s>", reqType) case utils.MetaNone: // do nothing on CGRateS side - case utils.MetaDryRun: - utils.Logger.Info( - fmt.Sprintf("<%s> DRY_RUN, processorID: %s, CGREvent: %s", - utils.RadiusAgent, reqProcessor.ID, utils.ToJSON(cgrEv))) + case utils.MetaDryRun: // do nothing on CGRateS side, logging handled above case utils.MetaAuthorize: authArgs := sessions.NewV1AuthorizeArgs( reqProcessor.Flags.GetBool(utils.MetaAttributes), @@ -509,15 +513,14 @@ func (ra *RadiusAgent) processRequest(req *radigo.Packet, reqProcessor *config.R return false, err } endTime := time.Now() - if reqProcessor.Flags.Has(utils.MetaLog) { + if reqProcessor.Flags.Has(utils.MetaLog) || reqType == utils.MetaDryRun { + logPrefix := "LOG" + if reqType == utils.MetaDryRun { + logPrefix = "DRY_RUN" + } utils.Logger.Info( - fmt.Sprintf("<%s> LOG, Radius reply: %s", - utils.RadiusAgent, agReq.Reply)) - } - if reqType == utils.MetaDryRun { - utils.Logger.Info( - fmt.Sprintf("<%s> DRY_RUN, Radius reply: %s", - utils.RadiusAgent, agReq.Reply)) + fmt.Sprintf("<%s> %s, Radius reply: %s", + utils.RadiusAgent, logPrefix, agReq.Reply)) } if reqProcessor.Flags.Has(utils.MetaDryRun) { return true, nil diff --git a/agents/sipagent.go b/agents/sipagent.go index 97a522ad5..2985bd78a 100644 --- a/agents/sipagent.go +++ b/agents/sipagent.go @@ -409,19 +409,23 @@ func (sa *SIPAgent) processRequest(reqProcessor *config.RequestProcessor, err = nil // reset the error and continue the processing } } - if reqProcessor.Flags.Has(utils.MetaLog) { + if reqProcessor.Flags.Has(utils.MetaLog) || reqType == utils.MetaDryRun { + logPrefix := "LOG" + if reqType == utils.MetaDryRun { + logPrefix = "DRY_RUN" + } utils.Logger.Info( - fmt.Sprintf("<%s> LOG, processorID: %s, SIP message: %s", - utils.SIPAgent, reqProcessor.ID, agReq.Request.String())) + fmt.Sprintf("<%s> %s, processorID: %s, SIP message: %s", + utils.SIPAgent, logPrefix, reqProcessor.ID, agReq.Request.String())) + utils.Logger.Info( + fmt.Sprintf("<%s> %s, processorID: %s, CGREvent: %s", + utils.SIPAgent, logPrefix, reqProcessor.ID, utils.ToIJSON(cgrEv))) } switch reqType { default: return false, fmt.Errorf("unknown request type: <%s>", reqType) case utils.MetaNone: // do nothing on CGRateS side - case utils.MetaDryRun: - utils.Logger.Info( - fmt.Sprintf("<%s> DRY_RUN, processorID: %s, CGREvent: %s", - utils.SIPAgent, reqProcessor.ID, utils.ToJSON(cgrEv))) + case utils.MetaDryRun: // do nothing on CGRateS side, logging handled above case utils.MetaAuthorize: authArgs := sessions.NewV1AuthorizeArgs( reqProcessor.Flags.GetBool(utils.MetaAttributes), @@ -472,15 +476,14 @@ func (sa *SIPAgent) processRequest(reqProcessor *config.RequestProcessor, return false, err } endTime := time.Now() - if reqProcessor.Flags.Has(utils.MetaLog) { + if reqProcessor.Flags.Has(utils.MetaLog) || reqType == utils.MetaDryRun { + logPrefix := "LOG" + if reqType == utils.MetaDryRun { + logPrefix = "DRY_RUN" + } utils.Logger.Info( - fmt.Sprintf("<%s> LOG, SIP reply: %s", - utils.SIPAgent, agReq.Reply)) - } - if reqType == utils.MetaDryRun { - utils.Logger.Info( - fmt.Sprintf("<%s> DRY_RUN, SIP reply: %s", - utils.SIPAgent, agReq.Reply)) + fmt.Sprintf("<%s> %s, SIP reply: %s", + utils.SIPAgent, logPrefix, agReq.Reply)) } if reqProcessor.Flags.Has(utils.MetaDryRun) { return true, nil diff --git a/ers/ers.go b/ers/ers.go index ec310e8ca..c558599e7 100644 --- a/ers/ers.go +++ b/ers/ers.go @@ -288,12 +288,6 @@ func (erS *ERService) processEvent(cgrEv *utils.CGREvent, } } }() - // log the event created if requested by flags - if rdrCfg.Flags.Has(utils.MetaLog) { - utils.Logger.Info( - fmt.Sprintf("<%s> LOG, reader: <%s>, message: %s", - utils.ERs, rdrCfg.ID, utils.ToIJSON(cgrEv))) - } // find out reqType var reqType string for _, typ := range []string{ @@ -317,15 +311,21 @@ func (erS *ERService) processEvent(cgrEv *utils.CGREvent, err = nil // reset the error and continue the processing } } + if rdrCfg.Flags.Has(utils.MetaLog) || reqType == utils.MetaDryRun { + logPrefix := "LOG" + if reqType == utils.MetaDryRun { + logPrefix = "DRY_RUN" + } + utils.Logger.Info( + fmt.Sprintf("<%s> %s, reader: <%s>, CGREvent: %s", + utils.ERs, logPrefix, rdrCfg.ID, utils.ToIJSON(cgrEv))) + } // execute the action based on reqType switch reqType { default: return fmt.Errorf("unsupported reqType: <%s>", reqType) case utils.MetaNone: // do nothing on CGRateS side - case utils.MetaDryRun: - utils.Logger.Info( - fmt.Sprintf("<%s> DRYRUN, reader: <%s>, CGREvent: <%s>", - utils.ERs, rdrCfg.ID, utils.ToJSON(cgrEv))) + case utils.MetaDryRun: // do nothing on CGRateS side, logging handled above case utils.MetaAuthorize: authArgs := sessions.NewV1AuthorizeArgs( rdrCfg.Flags.Has(utils.MetaAttributes), diff --git a/general_tests/diam_uli_it_test.go b/general_tests/diam_uli_it_test.go index 26dd2cc64..4360b1bc0 100644 --- a/general_tests/diam_uli_it_test.go +++ b/general_tests/diam_uli_it_test.go @@ -34,7 +34,7 @@ import ( ) func TestDiamULI(t *testing.T) { - // t.Skip("configuration reference for *3gpp_uli request_fields; does not assert values") + t.Skip("configuration reference for *3gpp_uli request_fields; does not verify anything") switch *utils.DBType { case utils.MetaInternal: case utils.MetaMySQL, utils.MetaMongo, utils.MetaPostgres: diff --git a/general_tests/ers_linenr_it_test.go b/general_tests/ers_linenr_it_test.go index ad17faf83..c3fb1887f 100644 --- a/general_tests/ers_linenr_it_test.go +++ b/general_tests/ers_linenr_it_test.go @@ -18,14 +18,12 @@ along with this program. If not, see package general_tests import ( - "bufio" "bytes" + "encoding/json" "fmt" "io" "os" "path/filepath" - "regexp" - "strconv" "strings" "testing" "time" @@ -122,42 +120,28 @@ func TestERsLineNr(t *testing.T) { } verifyLogLines := func(t *testing.T, reader io.Reader) { - fieldRegex := regexp.MustCompile(`"Field":"test(\d+)"`) - lineNumberRegex := regexp.MustCompile(`"LineNumber":"(\d+)"`) - records := 0 - scanner := bufio.NewScanner(reader) - for scanner.Scan() { - line := scanner.Text() - if !strings.Contains(line, `"Field":"test`) { + t.Helper() + data, err := io.ReadAll(reader) + if err != nil { + t.Fatal(err) + } + parts := strings.Split(string(data), "CGREvent: ") + var records int + for _, part := range parts[1:] { + var cgrEv utils.CGREvent + if err := json.NewDecoder(strings.NewReader(part)).Decode(&cgrEv); err != nil { + t.Fatalf("failed to decode CGREvent: %v", err) + } + field, _ := cgrEv.Event["Field"].(string) + if !strings.HasPrefix(field, "test") { continue } - records++ - - fieldMatch := fieldRegex.FindStringSubmatch(line) - lineNumberMatch := lineNumberRegex.FindStringSubmatch(line) - - if len(fieldMatch) != 2 || len(lineNumberMatch) != 2 { - t.Fatalf("invalid log line format: %s", line) - } - - testNumber, err := strconv.Atoi(fieldMatch[1]) - if err != nil { - t.Fatal(err) - } - lineNumber, err := strconv.Atoi(lineNumberMatch[1]) - if err != nil { - t.Fatal(err) - } - if testNumber != lineNumber { - t.Errorf("mismatch in line: %s, field number: %d, line number: %d", line, testNumber, lineNumber) + lineNumber, _ := cgrEv.Event["LineNumber"].(string) + if want := strings.TrimPrefix(field, "test"); lineNumber != want { + t.Errorf("got LineNumber=%s, want %s (Field=%s)", lineNumber, want, field) } } - - if err := scanner.Err(); err != nil { - t.Errorf("error reading input: %v", err) - } - if records != 18 { t.Errorf("expected ERs to process 18 records, but it processed %d records", records) } @@ -184,7 +168,7 @@ TRL6 test6 `) - time.Sleep(5 * time.Millisecond) // wait for the files to be processed + time.Sleep(20 * time.Millisecond) // wait for the files to be processed // Check that the suffixes of the 'test' fields match the LineNumber field. logData := strings.NewReader(buf.String()) diff --git a/general_tests/ers_sql_filters_it_test.go b/general_tests/ers_sql_filters_it_test.go index 3a6f99458..35ce38195 100644 --- a/general_tests/ers_sql_filters_it_test.go +++ b/general_tests/ers_sql_filters_it_test.go @@ -23,6 +23,7 @@ package general_tests import ( "bufio" "bytes" + "encoding/json" "fmt" "path" "strings" @@ -368,25 +369,20 @@ cgrates.org,FLTR_VARS,*string,~*vars.*readerID,mysql,`, GracefulShutdown: true, } ng.Run(t) - time.Sleep(1 * time.Second) + time.Sleep(500 * time.Millisecond) t.Run("VerifyProcessedFieldsFromLogs", func(t *testing.T) { time.Sleep(100 * time.Millisecond) // give enough time to process from sql table records := 0 scanner := bufio.NewScanner(strings.NewReader(buf.String())) - timeStartFormated := timeStart.Format("2006-01-02T15:04:05Z07:00") - expectedLog := fmt.Sprintf("\"Event\":{\"Account\":\"1001\",\"AnswerTime\":\"%s\",\"CGRID\":\"%s\",\"Category\":\"call\",\"CostDetails\":\"{\\\"CGRID\\\":\\\"test1\\\",\\\"RunID\\\":\\\"*default\\\",\\\"StartTime\\\":\\\"2017-01-09T16:18:21Z\\\",\\\"Usage\\\":180000000000,\\\"Cost\\\":2.3,\\\"Charges\\\":[{\\\"RatingID\\\":\\\"RatingID2\\\",\\\"Increments\\\":[{\\\"Usage\\\":120000000000,\\\"Cost\\\":2,\\\"AccountingID\\\":\\\"a012888\\\",\\\"CompressFactor\\\":1},{\\\"Usage\\\":1000000000,\\\"Cost\\\":0.005,\\\"AccountingID\\\":\\\"44d6c02\\\",\\\"CompressFactor\\\":60}],\\\"CompressFactor\\\":1}],\\\"AccountSummary\\\":{\\\"Tenant\\\":\\\"cgrates.org\\\",\\\"ID\\\":\\\"1001\\\",\\\"BalanceSummaries\\\":[{\\\"UUID\\\":\\\"uuid1\\\",\\\"ID\\\":\\\"\\\",\\\"Type\\\":\\\"*monetary\\\",\\\"Initial\\\":0,\\\"Value\\\":50,\\\"Disabled\\\":false}],\\\"AllowNegative\\\":false,\\\"Disabled\\\":false},\\\"Rating\\\":{\\\"c1a5ab9\\\":{\\\"ConnectFee\\\":0.1,\\\"RoundingMethod\\\":\\\"*up\\\",\\\"RoundingDecimals\\\":5,\\\"MaxCost\\\":0,\\\"MaxCostStrategy\\\":\\\"\\\",\\\"TimingID\\\":\\\"\\\",\\\"RatesID\\\":\\\"ec1a177\\\",\\\"RatingFiltersID\\\":\\\"43e77dc\\\"}},\\\"Accounting\\\":{\\\"44d6c02\\\":{\\\"AccountID\\\":\\\"cgrates.org:1001\\\",\\\"BalanceUUID\\\":\\\"uuid1\\\",\\\"RatingID\\\":\\\"\\\",\\\"Units\\\":120.7,\\\"ExtraChargeID\\\":\\\"\\\"},\\\"a012888\\\":{\\\"AccountID\\\":\\\"cgrates.org:1001\\\",\\\"BalanceUUID\\\":\\\"uuid1\\\",\\\"RatingID\\\":\\\"\\\",\\\"Units\\\":120.7,\\\"ExtraChargeID\\\":\\\"\\\"}},\\\"RatingFilters\\\":null,\\\"Rates\\\":{\\\"ec1a177\\\":[{\\\"GroupIntervalStart\\\":0,\\\"Value\\\":0.01,\\\"RateIncrement\\\":60000000000,\\\"RateUnit\\\":1000000000}]},\\\"Timings\\\":null}\",\"Destination\":\"1002\",\"OriginID\":\"oid2\",\"RequestType\":\"*rated\",\"SetupTime\":\"%s\",\"Subject\":\"1001\",\"Tenant\":\"cgrates.org\",\"ToR\":\"*voice\",\"Usage\":\"10000000000\"},\"APIOpts\":{}}>", timeStartFormated, cgrID, timeStartFormated) var ersLogsCount int for scanner.Scan() { line := scanner.Text() - if !strings.Contains(line, " DRYRUN, reader: ") { + if !strings.Contains(line, " DRY_RUN, reader: ") { continue } records++ - if !strings.Contains(line, expectedLog) { - t.Errorf("expected \n<%q>, \nreceived\n<%q>", expectedLog, line) - } - if strings.Contains(line, "[INFO] DRYRUN") { + if strings.Contains(line, "[INFO] DRY_RUN") { ersLogsCount++ } } @@ -399,6 +395,33 @@ cgrates.org,FLTR_VARS,*string,~*vars.*readerID,mysql,`, if ersLogsCount != 1 { t.Error("Expected only 1 ERS Dryrun log, received: ", ersLogsCount) } + idx := strings.Index(buf.String(), "CGREvent: ") + if idx == -1 { + t.Fatal("CGREvent not found in log output") + } + var cgrEv utils.CGREvent + if err := json.NewDecoder(strings.NewReader(buf.String()[idx+len("CGREvent: "):])).Decode(&cgrEv); err != nil { + t.Fatal(err) + } + timeStartFormatted := timeStart.Format("2006-01-02T15:04:05Z07:00") + expectedEvent := map[string]any{ + "Account": "1001", + "AnswerTime": timeStartFormatted, + "CGRID": cgrID, + "Category": "call", + "CostDetails": utils.ToJSON(cdr2.CostDetails), + "Destination": "1002", + "OriginID": "oid2", + "RequestType": "*rated", + "SetupTime": timeStartFormatted, + "Subject": "1001", + "Tenant": "cgrates.org", + "ToR": "*voice", + "Usage": "10000000000", + } + if got, want := utils.ToJSON(cgrEv.Event), utils.ToJSON(expectedEvent); got != want { + t.Errorf("got event\n%s\nwant\n%s", got, want) + } }) t.Run("VerifyRowsNotDeleted", func(t *testing.T) { @@ -531,25 +554,20 @@ cgrates.org,FLTR_VARS,*string,~*vars.*readerID,mysql,`, GracefulShutdown: true, } ng.Run(t) - time.Sleep(1 * time.Second) + time.Sleep(500 * time.Millisecond) t.Run("VerifyProcessedFieldsFromLogs", func(t *testing.T) { time.Sleep(100 * time.Millisecond) // give enough time to process from sql table records := 0 scanner := bufio.NewScanner(strings.NewReader(buf.String())) - timeStartFormated := timeStart.Format("2006-01-02T15:04:05Z07:00") - expectedLog := fmt.Sprintf("\"Event\":{\"Account\":\"1001\",\"AnswerTime\":\"%s\",\"CGRID\":\"%s\",\"Category\":\"call\",\"CostDetails\":\"{\\\"CGRID\\\":\\\"test1\\\",\\\"RunID\\\":\\\"*default\\\",\\\"StartTime\\\":\\\"2017-01-09T16:18:21Z\\\",\\\"Usage\\\":180000000000,\\\"Cost\\\":2.3,\\\"Charges\\\":[{\\\"RatingID\\\":\\\"RatingID2\\\",\\\"Increments\\\":[{\\\"Usage\\\":120000000000,\\\"Cost\\\":2,\\\"AccountingID\\\":\\\"a012888\\\",\\\"CompressFactor\\\":1},{\\\"Usage\\\":1000000000,\\\"Cost\\\":0.005,\\\"AccountingID\\\":\\\"44d6c02\\\",\\\"CompressFactor\\\":60}],\\\"CompressFactor\\\":1}],\\\"AccountSummary\\\":{\\\"Tenant\\\":\\\"cgrates.org\\\",\\\"ID\\\":\\\"1001\\\",\\\"BalanceSummaries\\\":[{\\\"UUID\\\":\\\"uuid1\\\",\\\"ID\\\":\\\"\\\",\\\"Type\\\":\\\"*monetary\\\",\\\"Initial\\\":0,\\\"Value\\\":50,\\\"Disabled\\\":false}],\\\"AllowNegative\\\":false,\\\"Disabled\\\":false},\\\"Rating\\\":{\\\"c1a5ab9\\\":{\\\"ConnectFee\\\":0.1,\\\"RoundingMethod\\\":\\\"*up\\\",\\\"RoundingDecimals\\\":5,\\\"MaxCost\\\":0,\\\"MaxCostStrategy\\\":\\\"\\\",\\\"TimingID\\\":\\\"\\\",\\\"RatesID\\\":\\\"ec1a177\\\",\\\"RatingFiltersID\\\":\\\"43e77dc\\\"}},\\\"Accounting\\\":{\\\"44d6c02\\\":{\\\"AccountID\\\":\\\"cgrates.org:1001\\\",\\\"BalanceUUID\\\":\\\"uuid1\\\",\\\"RatingID\\\":\\\"\\\",\\\"Units\\\":120.7,\\\"ExtraChargeID\\\":\\\"\\\"},\\\"a012888\\\":{\\\"AccountID\\\":\\\"cgrates.org:1001\\\",\\\"BalanceUUID\\\":\\\"uuid1\\\",\\\"RatingID\\\":\\\"\\\",\\\"Units\\\":120.7,\\\"ExtraChargeID\\\":\\\"\\\"}},\\\"RatingFilters\\\":null,\\\"Rates\\\":{\\\"ec1a177\\\":[{\\\"GroupIntervalStart\\\":0,\\\"Value\\\":0.01,\\\"RateIncrement\\\":60000000000,\\\"RateUnit\\\":1000000000}]},\\\"Timings\\\":null}\",\"Destination\":\"1002\",\"OriginID\":\"oid2\",\"RequestType\":\"*rated\",\"SetupTime\":\"%s\",\"Subject\":\"1001\",\"Tenant\":\"cgrates.org\",\"ToR\":\"*voice\",\"Usage\":\"10000000000\"},\"APIOpts\":{}}>", timeStartFormated, cgrID, timeStartFormated) var ersLogsCount int for scanner.Scan() { line := scanner.Text() - if !strings.Contains(line, " DRYRUN, reader: ") { + if !strings.Contains(line, " DRY_RUN, reader: ") { continue } records++ - if !strings.Contains(line, expectedLog) { - t.Errorf("expected \n<%q>, \nreceived\n<%q>", expectedLog, line) - } - if strings.Contains(line, "[INFO] DRYRUN") { + if strings.Contains(line, "[INFO] DRY_RUN") { ersLogsCount++ } } @@ -562,6 +580,33 @@ cgrates.org,FLTR_VARS,*string,~*vars.*readerID,mysql,`, if ersLogsCount != 1 { t.Error("Expected only 1 ERS Dryrun log, received: ", ersLogsCount) } + idx := strings.Index(buf.String(), "CGREvent: ") + if idx == -1 { + t.Fatal("CGREvent not found in log output") + } + var cgrEv utils.CGREvent + if err := json.NewDecoder(strings.NewReader(buf.String()[idx+len("CGREvent: "):])).Decode(&cgrEv); err != nil { + t.Fatal(err) + } + timeStartFormatted := timeStart.Format("2006-01-02T15:04:05Z07:00") + expectedEvent := map[string]any{ + "Account": "1001", + "AnswerTime": timeStartFormatted, + "CGRID": cgrID, + "Category": "call", + "CostDetails": utils.ToJSON(cdr2.CostDetails), + "Destination": "1002", + "OriginID": "oid2", + "RequestType": "*rated", + "SetupTime": timeStartFormatted, + "Subject": "1001", + "Tenant": "cgrates.org", + "ToR": "*voice", + "Usage": "10000000000", + } + if got, want := utils.ToJSON(cgrEv.Event), utils.ToJSON(expectedEvent); got != want { + t.Errorf("got event\n%s\nwant\n%s", got, want) + } }) t.Run("VerifyRowsNotDeleted", func(t *testing.T) { @@ -700,25 +745,20 @@ cgrates.org,FLTR_VARS,*string,~*vars.*readerID,mysql,`, GracefulShutdown: true, } ng.Run(t) - time.Sleep(1 * time.Second) + time.Sleep(500 * time.Millisecond) t.Run("VerifyProcessedFieldsFromLogs", func(t *testing.T) { time.Sleep(100 * time.Millisecond) // give enough time to process from sql table records := 0 scanner := bufio.NewScanner(strings.NewReader(buf.String())) - timeStartFormated := timeStart.Format("2006-01-02T15:04:05Z07:00") - expectedLog := fmt.Sprintf("\"Event\":{\"Account\":\"1001\",\"AnswerTime\":\"%s\",\"CGRID\":\"%s\",\"Category\":\"call\",\"CostDetails\":\"{\\\"CGRID\\\":\\\"test1\\\",\\\"RunID\\\":\\\"*default\\\",\\\"StartTime\\\":\\\"2017-01-09T16:18:21Z\\\",\\\"Usage\\\":180000000000,\\\"Cost\\\":2.3,\\\"Charges\\\":[{\\\"RatingID\\\":\\\"RatingID2\\\",\\\"Increments\\\":[{\\\"Usage\\\":120000000000,\\\"Cost\\\":2,\\\"AccountingID\\\":\\\"a012888\\\",\\\"CompressFactor\\\":1},{\\\"Usage\\\":1000000000,\\\"Cost\\\":0.005,\\\"AccountingID\\\":\\\"44d6c02\\\",\\\"CompressFactor\\\":60}],\\\"CompressFactor\\\":1}],\\\"AccountSummary\\\":{\\\"Tenant\\\":\\\"cgrates.org\\\",\\\"ID\\\":\\\"1001\\\",\\\"BalanceSummaries\\\":[{\\\"UUID\\\":\\\"uuid1\\\",\\\"ID\\\":\\\"\\\",\\\"Type\\\":\\\"*monetary\\\",\\\"Initial\\\":0,\\\"Value\\\":50,\\\"Disabled\\\":false}],\\\"AllowNegative\\\":false,\\\"Disabled\\\":false},\\\"Rating\\\":{\\\"c1a5ab9\\\":{\\\"ConnectFee\\\":0.1,\\\"RoundingMethod\\\":\\\"*up\\\",\\\"RoundingDecimals\\\":5,\\\"MaxCost\\\":0,\\\"MaxCostStrategy\\\":\\\"\\\",\\\"TimingID\\\":\\\"\\\",\\\"RatesID\\\":\\\"ec1a177\\\",\\\"RatingFiltersID\\\":\\\"43e77dc\\\"}},\\\"Accounting\\\":{\\\"44d6c02\\\":{\\\"AccountID\\\":\\\"cgrates.org:1001\\\",\\\"BalanceUUID\\\":\\\"uuid1\\\",\\\"RatingID\\\":\\\"\\\",\\\"Units\\\":120.7,\\\"ExtraChargeID\\\":\\\"\\\"},\\\"a012888\\\":{\\\"AccountID\\\":\\\"cgrates.org:1001\\\",\\\"BalanceUUID\\\":\\\"uuid1\\\",\\\"RatingID\\\":\\\"\\\",\\\"Units\\\":120.7,\\\"ExtraChargeID\\\":\\\"\\\"}},\\\"RatingFilters\\\":null,\\\"Rates\\\":{\\\"ec1a177\\\":[{\\\"GroupIntervalStart\\\":0,\\\"Value\\\":0.01,\\\"RateIncrement\\\":60000000000,\\\"RateUnit\\\":1000000000}]},\\\"Timings\\\":null}\",\"Destination\":\"1002\",\"OriginID\":\"oid2\",\"RequestType\":\"*rated\",\"SetupTime\":\"%s\",\"Subject\":\"1001\",\"Tenant\":\"cgrates.org\",\"ToR\":\"*voice\",\"Usage\":\"10000000000\"},\"APIOpts\":{}}>", timeStartFormated, cgrID, timeStartFormated) var ersLogsCount int for scanner.Scan() { line := scanner.Text() - if !strings.Contains(line, " DRYRUN, reader: ") { + if !strings.Contains(line, " DRY_RUN, reader: ") { continue } records++ - if !strings.Contains(line, expectedLog) { - t.Errorf("expected \n<%q>, \nreceived\n<%q>", expectedLog, line) - } - if strings.Contains(line, "[INFO] DRYRUN") { + if strings.Contains(line, "[INFO] DRY_RUN") { ersLogsCount++ } } @@ -731,6 +771,33 @@ cgrates.org,FLTR_VARS,*string,~*vars.*readerID,mysql,`, if ersLogsCount != 1 { t.Error("Expected only 1 ERS Dryrun log, received: ", ersLogsCount) } + idx := strings.Index(buf.String(), "CGREvent: ") + if idx == -1 { + t.Fatal("CGREvent not found in log output") + } + var cgrEv utils.CGREvent + if err := json.NewDecoder(strings.NewReader(buf.String()[idx+len("CGREvent: "):])).Decode(&cgrEv); err != nil { + t.Fatal(err) + } + timeStartFormatted := timeStart.Format("2006-01-02T15:04:05Z07:00") + expectedEvent := map[string]any{ + "Account": "1001", + "AnswerTime": timeStartFormatted, + "CGRID": cgrID, + "Category": "call", + "CostDetails": utils.ToJSON(cdr2.CostDetails), + "Destination": "1002", + "OriginID": "oid2", + "RequestType": "*rated", + "SetupTime": timeStartFormatted, + "Subject": "1001", + "Tenant": "cgrates.org", + "ToR": "*voice", + "Usage": "10000000000", + } + if got, want := utils.ToJSON(cgrEv.Event), utils.ToJSON(expectedEvent); got != want { + t.Errorf("got event\n%s\nwant\n%s", got, want) + } }) t.Run("VerifyRowsNotDeleted", func(t *testing.T) { @@ -909,25 +976,20 @@ cgrates.org,FLTR_VARS,*string,~*vars.*readerID,mysql,`, GracefulShutdown: true, } ng.Run(t) - time.Sleep(1 * time.Second) + time.Sleep(500 * time.Millisecond) t.Run("VerifyProcessedFieldsFromLogs", func(t *testing.T) { time.Sleep(100 * time.Millisecond) // give enough time to process from sql table records := 0 scanner := bufio.NewScanner(strings.NewReader(buf.String())) - timeStartFormated := timeStart.Format("2006-01-02T15:04:05Z07:00") - expectedLog := fmt.Sprintf("\"Event\":{\"Account\":\"1001\",\"AnswerTime\":\"%s\",\"CGRID\":\"%s\",\"Category\":\"call\",\"CostDetails\":\"{\\\"CGRID\\\":\\\"test1\\\",\\\"RunID\\\":\\\"*default\\\",\\\"StartTime\\\":\\\"2017-01-09T16:18:21Z\\\",\\\"Usage\\\":180000000000,\\\"Cost\\\":2.3,\\\"Charges\\\":[{\\\"RatingID\\\":\\\"RatingID2\\\",\\\"Increments\\\":[{\\\"Usage\\\":120000000000,\\\"Cost\\\":2,\\\"AccountingID\\\":\\\"a012888\\\",\\\"CompressFactor\\\":1},{\\\"Usage\\\":1000000000,\\\"Cost\\\":0.005,\\\"AccountingID\\\":\\\"44d6c02\\\",\\\"CompressFactor\\\":60}],\\\"CompressFactor\\\":1}],\\\"AccountSummary\\\":{\\\"Tenant\\\":\\\"cgrates.org\\\",\\\"ID\\\":\\\"1001\\\",\\\"BalanceSummaries\\\":[{\\\"UUID\\\":\\\"uuid1\\\",\\\"ID\\\":\\\"\\\",\\\"Type\\\":\\\"*monetary\\\",\\\"Initial\\\":0,\\\"Value\\\":50,\\\"Disabled\\\":false}],\\\"AllowNegative\\\":false,\\\"Disabled\\\":false},\\\"Rating\\\":{\\\"c1a5ab9\\\":{\\\"ConnectFee\\\":0.1,\\\"RoundingMethod\\\":\\\"*up\\\",\\\"RoundingDecimals\\\":5,\\\"MaxCost\\\":0,\\\"MaxCostStrategy\\\":\\\"\\\",\\\"TimingID\\\":\\\"\\\",\\\"RatesID\\\":\\\"ec1a177\\\",\\\"RatingFiltersID\\\":\\\"43e77dc\\\"}},\\\"Accounting\\\":{\\\"44d6c02\\\":{\\\"AccountID\\\":\\\"cgrates.org:1001\\\",\\\"BalanceUUID\\\":\\\"uuid1\\\",\\\"RatingID\\\":\\\"\\\",\\\"Units\\\":120.7,\\\"ExtraChargeID\\\":\\\"\\\"},\\\"a012888\\\":{\\\"AccountID\\\":\\\"cgrates.org:1001\\\",\\\"BalanceUUID\\\":\\\"uuid1\\\",\\\"RatingID\\\":\\\"\\\",\\\"Units\\\":120.7,\\\"ExtraChargeID\\\":\\\"\\\"}},\\\"RatingFilters\\\":null,\\\"Rates\\\":{\\\"ec1a177\\\":[{\\\"GroupIntervalStart\\\":0,\\\"Value\\\":0.01,\\\"RateIncrement\\\":60000000000,\\\"RateUnit\\\":1000000000}]},\\\"Timings\\\":null}\",\"Destination\":\"1002\",\"OriginID\":\"oid2\",\"RequestType\":\"*rated\",\"SetupTime\":\"%s\",\"Subject\":\"1001\",\"Tenant\":\"cgrates.org\",\"ToR\":\"*voice\",\"Usage\":\"10000000000\"},\"APIOpts\":{}}>", timeStartFormated, cgrID, timeStartFormated) var ersLogsCount int for scanner.Scan() { line := scanner.Text() - if !strings.Contains(line, " DRYRUN, reader: ") { + if !strings.Contains(line, " DRY_RUN, reader: ") { continue } records++ - if !strings.Contains(line, expectedLog) { - t.Errorf("expected \n<%q>, \nreceived\n<%q>", expectedLog, line) - } - if strings.Contains(line, "[INFO] DRYRUN") { + if strings.Contains(line, "[INFO] DRY_RUN") { ersLogsCount++ } } @@ -940,6 +1002,33 @@ cgrates.org,FLTR_VARS,*string,~*vars.*readerID,mysql,`, if ersLogsCount != 1 { t.Error("Expected only 1 ERS Dryrun log, received: ", ersLogsCount) } + idx := strings.Index(buf.String(), "CGREvent: ") + if idx == -1 { + t.Fatal("CGREvent not found in log output") + } + var cgrEv utils.CGREvent + if err := json.NewDecoder(strings.NewReader(buf.String()[idx+len("CGREvent: "):])).Decode(&cgrEv); err != nil { + t.Fatal(err) + } + timeStartFormatted := timeStart.Format("2006-01-02T15:04:05Z07:00") + expectedEvent := map[string]any{ + "Account": "1001", + "AnswerTime": timeStartFormatted, + "CGRID": cgrID, + "Category": "call", + "CostDetails": utils.ToJSON(cdr2.CostDetails), + "Destination": "1002", + "OriginID": "oid2", + "RequestType": "*rated", + "SetupTime": timeStartFormatted, + "Subject": "1001", + "Tenant": "cgrates.org", + "ToR": "*voice", + "Usage": "10000000000", + } + if got, want := utils.ToJSON(cgrEv.Event), utils.ToJSON(expectedEvent); got != want { + t.Errorf("got event\n%s\nwant\n%s", got, want) + } }) t.Run("VerifyRowsCount", func(t *testing.T) { @@ -1098,25 +1187,20 @@ cgrates.org,FLTR_VARS,*string,~*vars.*readerID,mysql,`, GracefulShutdown: true, } ng.Run(t) - time.Sleep(1 * time.Second) + time.Sleep(500 * time.Millisecond) t.Run("VerifyProcessedFieldsFromLogs", func(t *testing.T) { time.Sleep(100 * time.Millisecond) // give enough time to process from sql table records := 0 scanner := bufio.NewScanner(strings.NewReader(buf.String())) - timeStartFormated := timeStart.Format("2006-01-02T15:04:05Z07:00") - expectedLog := fmt.Sprintf("\"Event\":{\"Account\":\"1001\",\"AnswerTime\":\"%s\",\"CGRID\":\"%s\",\"Category\":\"call\",\"CostDetails\":\"{\\\"CGRID\\\":\\\"test1\\\",\\\"RunID\\\":\\\"*default\\\",\\\"StartTime\\\":\\\"2017-01-09T16:18:21Z\\\",\\\"Usage\\\":180000000000,\\\"Cost\\\":2.3,\\\"Charges\\\":[{\\\"RatingID\\\":\\\"RatingID2\\\",\\\"Increments\\\":[{\\\"Usage\\\":120000000000,\\\"Cost\\\":2,\\\"AccountingID\\\":\\\"a012888\\\",\\\"CompressFactor\\\":1},{\\\"Usage\\\":1000000000,\\\"Cost\\\":0.005,\\\"AccountingID\\\":\\\"44d6c02\\\",\\\"CompressFactor\\\":60}],\\\"CompressFactor\\\":1}],\\\"AccountSummary\\\":{\\\"Tenant\\\":\\\"cgrates.org\\\",\\\"ID\\\":\\\"1001\\\",\\\"BalanceSummaries\\\":[{\\\"UUID\\\":\\\"uuid1\\\",\\\"ID\\\":\\\"\\\",\\\"Type\\\":\\\"*monetary\\\",\\\"Initial\\\":0,\\\"Value\\\":50,\\\"Disabled\\\":false}],\\\"AllowNegative\\\":false,\\\"Disabled\\\":false},\\\"Rating\\\":{\\\"c1a5ab9\\\":{\\\"ConnectFee\\\":0.1,\\\"RoundingMethod\\\":\\\"*up\\\",\\\"RoundingDecimals\\\":5,\\\"MaxCost\\\":0,\\\"MaxCostStrategy\\\":\\\"\\\",\\\"TimingID\\\":\\\"\\\",\\\"RatesID\\\":\\\"ec1a177\\\",\\\"RatingFiltersID\\\":\\\"43e77dc\\\"}},\\\"Accounting\\\":{\\\"44d6c02\\\":{\\\"AccountID\\\":\\\"cgrates.org:1001\\\",\\\"BalanceUUID\\\":\\\"uuid1\\\",\\\"RatingID\\\":\\\"\\\",\\\"Units\\\":120.7,\\\"ExtraChargeID\\\":\\\"\\\"},\\\"a012888\\\":{\\\"AccountID\\\":\\\"cgrates.org:1001\\\",\\\"BalanceUUID\\\":\\\"uuid1\\\",\\\"RatingID\\\":\\\"\\\",\\\"Units\\\":120.7,\\\"ExtraChargeID\\\":\\\"\\\"}},\\\"RatingFilters\\\":null,\\\"Rates\\\":{\\\"ec1a177\\\":[{\\\"GroupIntervalStart\\\":0,\\\"Value\\\":0.01,\\\"RateIncrement\\\":60000000000,\\\"RateUnit\\\":1000000000}]},\\\"Timings\\\":null}\",\"Destination\":\"1002\",\"ExtraInfo\":\"extraInfo\",\"Id\":\"2\",\"OriginID\":\"oid2\",\"RequestType\":\"*rated\",\"SetupTime\":\"%s\",\"Subject\":\"1001\",\"Tenant\":\"cgrates.org\",\"ToR\":\"*voice\",\"Usage\":\"10000000000\"},\"APIOpts\":{}}>", timeStartFormated, cgrID, timeStartFormated) var ersLogsCount int for scanner.Scan() { line := scanner.Text() - if !strings.Contains(line, " DRYRUN, reader: ") { + if !strings.Contains(line, " DRY_RUN, reader: ") { continue } records++ - if !strings.Contains(line, expectedLog) { - t.Errorf("expected \n<%q>, \nreceived\n<%q>", expectedLog, line) - } - if strings.Contains(line, "[INFO] DRYRUN") { + if strings.Contains(line, "[INFO] DRY_RUN") { ersLogsCount++ } } @@ -1129,6 +1213,35 @@ cgrates.org,FLTR_VARS,*string,~*vars.*readerID,mysql,`, if ersLogsCount != 1 { t.Error("Expected only 1 ERS Dryrun log, received: ", ersLogsCount) } + idx := strings.Index(buf.String(), "CGREvent: ") + if idx == -1 { + t.Fatal("CGREvent not found in log output") + } + var cgrEv utils.CGREvent + if err := json.NewDecoder(strings.NewReader(buf.String()[idx+len("CGREvent: "):])).Decode(&cgrEv); err != nil { + t.Fatal(err) + } + timeStartFormatted := timeStart.Format("2006-01-02T15:04:05Z07:00") + expectedEvent := map[string]any{ + "Account": "1001", + "AnswerTime": timeStartFormatted, + "CGRID": cgrID, + "Category": "call", + "CostDetails": utils.ToJSON(cdr2.CostDetails), + "Destination": "1002", + "ExtraInfo": "extraInfo", + "Id": "2", + "OriginID": "oid2", + "RequestType": "*rated", + "SetupTime": timeStartFormatted, + "Subject": "1001", + "Tenant": "cgrates.org", + "ToR": "*voice", + "Usage": "10000000000", + } + if got, want := utils.ToJSON(cgrEv.Event), utils.ToJSON(expectedEvent); got != want { + t.Errorf("got event\n%s\nwant\n%s", got, want) + } }) t.Run("VerifyRowsCount", func(t *testing.T) { @@ -1279,25 +1392,20 @@ cgrates.org,FLTR_VARS,*string,~*vars.*readerID,mysql,`, GracefulShutdown: true, } ng.Run(t) - time.Sleep(1 * time.Second) + time.Sleep(500 * time.Millisecond) t.Run("VerifyProcessedFieldsFromLogs", func(t *testing.T) { time.Sleep(100 * time.Millisecond) // give enough time to process from sql table records := 0 scanner := bufio.NewScanner(strings.NewReader(buf.String())) - timeStartFormated := timeStart.Format("2006-01-02T15:04:05Z07:00") - expectedLog := fmt.Sprintf("\"Event\":{\"Account\":\"1001\",\"AnswerTime\":\"%s\",\"CGRID\":\"%s\",\"Category\":\"call\",\"CostDetails\":\"{\\\"CGRID\\\":\\\"test1\\\",\\\"RunID\\\":\\\"*default\\\",\\\"StartTime\\\":\\\"2017-01-09T16:18:21Z\\\",\\\"Usage\\\":180000000000,\\\"Cost\\\":2.3,\\\"Charges\\\":[{\\\"RatingID\\\":\\\"RatingID2\\\",\\\"Increments\\\":[{\\\"Usage\\\":120000000000,\\\"Cost\\\":2,\\\"AccountingID\\\":\\\"a012888\\\",\\\"CompressFactor\\\":1},{\\\"Usage\\\":1000000000,\\\"Cost\\\":0.005,\\\"AccountingID\\\":\\\"44d6c02\\\",\\\"CompressFactor\\\":60}],\\\"CompressFactor\\\":1}],\\\"AccountSummary\\\":{\\\"Tenant\\\":\\\"cgrates.org\\\",\\\"ID\\\":\\\"1001\\\",\\\"BalanceSummaries\\\":[{\\\"UUID\\\":\\\"uuid1\\\",\\\"ID\\\":\\\"\\\",\\\"Type\\\":\\\"*monetary\\\",\\\"Initial\\\":0,\\\"Value\\\":50,\\\"Disabled\\\":false}],\\\"AllowNegative\\\":false,\\\"Disabled\\\":false},\\\"Rating\\\":{\\\"c1a5ab9\\\":{\\\"ConnectFee\\\":0.1,\\\"RoundingMethod\\\":\\\"*up\\\",\\\"RoundingDecimals\\\":5,\\\"MaxCost\\\":0,\\\"MaxCostStrategy\\\":\\\"\\\",\\\"TimingID\\\":\\\"\\\",\\\"RatesID\\\":\\\"ec1a177\\\",\\\"RatingFiltersID\\\":\\\"43e77dc\\\"}},\\\"Accounting\\\":{\\\"44d6c02\\\":{\\\"AccountID\\\":\\\"cgrates.org:1001\\\",\\\"BalanceUUID\\\":\\\"uuid1\\\",\\\"RatingID\\\":\\\"\\\",\\\"Units\\\":120.7,\\\"ExtraChargeID\\\":\\\"\\\"},\\\"a012888\\\":{\\\"AccountID\\\":\\\"cgrates.org:1001\\\",\\\"BalanceUUID\\\":\\\"uuid1\\\",\\\"RatingID\\\":\\\"\\\",\\\"Units\\\":120.7,\\\"ExtraChargeID\\\":\\\"\\\"}},\\\"RatingFilters\\\":null,\\\"Rates\\\":{\\\"ec1a177\\\":[{\\\"GroupIntervalStart\\\":0,\\\"Value\\\":0.01,\\\"RateIncrement\\\":60000000000,\\\"RateUnit\\\":1000000000}]},\\\"Timings\\\":null}\",\"Destination\":\"1002\",\"OriginID\":\"oid2\",\"RequestType\":\"*rated\",\"SetupTime\":\"%s\",\"Subject\":\"1001\",\"Tenant\":\"cgrates.org\",\"ToR\":\"*voice\",\"Usage\":\"10000000000\"},\"APIOpts\":{}}>", timeStartFormated, cgrID, timeStartFormated) var ersLogsCount int for scanner.Scan() { line := scanner.Text() - if !strings.Contains(line, " DRYRUN, reader: ") { + if !strings.Contains(line, " DRY_RUN, reader: ") { continue } records++ - if !strings.Contains(line, expectedLog) { - t.Errorf("expected \n<%q>, \nreceived\n<%q>", expectedLog, line) - } - if strings.Contains(line, "[INFO] DRYRUN") { + if strings.Contains(line, "[INFO] DRY_RUN") { ersLogsCount++ } } @@ -1310,6 +1418,33 @@ cgrates.org,FLTR_VARS,*string,~*vars.*readerID,mysql,`, if ersLogsCount != 1 { t.Error("Expected only 1 ERS Dryrun log, received: ", ersLogsCount) } + idx := strings.Index(buf.String(), "CGREvent: ") + if idx == -1 { + t.Fatal("CGREvent not found in log output") + } + var cgrEv utils.CGREvent + if err := json.NewDecoder(strings.NewReader(buf.String()[idx+len("CGREvent: "):])).Decode(&cgrEv); err != nil { + t.Fatal(err) + } + timeStartFormatted := timeStart.Format("2006-01-02T15:04:05Z07:00") + expectedEvent := map[string]any{ + "Account": "1001", + "AnswerTime": timeStartFormatted, + "CGRID": cgrID, + "Category": "call", + "CostDetails": utils.ToJSON(cdr2.CostDetails), + "Destination": "1002", + "OriginID": "oid2", + "RequestType": "*rated", + "SetupTime": timeStartFormatted, + "Subject": "1001", + "Tenant": "cgrates.org", + "ToR": "*voice", + "Usage": "10000000000", + } + if got, want := utils.ToJSON(cgrEv.Event), utils.ToJSON(expectedEvent); got != want { + t.Errorf("got event\n%s\nwant\n%s", got, want) + } }) t.Run("VerifyRowsCount", func(t *testing.T) { @@ -1520,7 +1655,7 @@ cgrates.org,FLTR_VARS,*string,~*vars.*readerID,mysql,`, GracefulShutdown: true, } ng.Run(t) - time.Sleep(1 * time.Second) + time.Sleep(500 * time.Millisecond) t.Run("VerifyProcessedFieldsFromLogs", func(t *testing.T) { time.Sleep(100 * time.Millisecond) // give enough time to process from sql table