Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[release-1.18] Fix bug report missing all logs for json logs #45026

Merged
merged 6 commits into from
May 23, 2023
Merged

[release-1.18] Fix bug report missing all logs for json logs #45026

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
4f96531
Add json log parsing
syw14 May 15, 2023
6f2eb56
Remove bug report file
syw14 May 15, 2023
5943cde
Omit filter and add tests
syw14 May 17, 2023
bcfa337
Extract to parseLog
syw14 May 18, 2023
ebce495
Fix test failures
syw14 May 19, 2023
153544a
Fix format
syw14 May 19, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions tools/bug-report/pkg/bugreport/flags.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -145,6 +145,12 @@ func parseConfig() (*config2.BugReportConfig, error) {
}

func parseTimes(config *config2.BugReportConfig, startTime, endTime string, duration time.Duration) error {
if startTime == "" && endTime == "" {
config.TimeFilterApplied = false
} else {
config.TimeFilterApplied = true
}

config.EndTime = time.Now()
config.Since = config2.Duration(duration)
if endTime != "" {
Expand Down
4 changes: 4 additions & 0 deletions tools/bug-report/pkg/config/config.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -162,6 +162,10 @@ type BugReportConfig struct {
// If set, StartTime must be unset.
Since Duration `json:"since,omitempty"`

// TimeFilterApplied stores if user has provided any time filtering flags.
// If Since, StartTime, EndTime are all not applied by the user, set TimeFilterApplied as false; Otherwise set true
TimeFilterApplied bool `json:"timeFilterApplied,omitempty"`

// CriticalErrors is a list of glob pattern matches for errors that,
// if found in a log, set the highest priority for the log to ensure
// that it is Include in the capture archive.
Expand Down
56 changes: 53 additions & 3 deletions tools/bug-report/pkg/processlog/processlog.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@
package processlog

import (
"encoding/json"
"regexp"
"strings"
"time"
Expand Down Expand Up @@ -52,6 +53,9 @@ func (s *Stats) Importance() int {

// Process processes logStr based on the supplied config and returns the processed log along with statistics on it.
func Process(config *config.BugReportConfig, logStr string) (string, *Stats) {
if !config.TimeFilterApplied {
return logStr, getStats(config, logStr)
}
out := getTimeRange(logStr, config.StartTime, config.EndTime)
return out, getStats(config, out)
}
Expand All @@ -61,7 +65,7 @@ func getTimeRange(logStr string, start, end time.Time) string {
var sb strings.Builder
write := false
for _, l := range strings.Split(logStr, "\n") {
t, _, _, valid := processLogLine(l)
t, _, _, valid := parseLog(l)
if valid {
write = false
if (t.Equal(start) || t.After(start)) && (t.Equal(end) || t.Before(end)) {
Expand All @@ -81,7 +85,7 @@ func getTimeRange(logStr string, start, end time.Time) string {
func getStats(config *config.BugReportConfig, logStr string) *Stats {
out := &Stats{}
for _, l := range strings.Split(logStr, "\n") {
_, level, text, valid := processLogLine(l)
_, level, text, valid := parseLog(l)
if !valid {
continue
}
Expand All @@ -104,7 +108,14 @@ func getStats(config *config.BugReportConfig, logStr string) *Stats {
return out
}

func processLogLine(line string) (timeStamp *time.Time, level string, text string, valid bool) {
func parseLog(line string) (timeStamp *time.Time, level string, text string, valid bool) {
if isJSONLog(line) {
return parseJSONLog(line)
}
return processPlainLog(line)
}

func processPlainLog(line string) (timeStamp *time.Time, level string, text string, valid bool) {
lv := strings.Split(line, "\t")
if len(lv) < 3 {
// maybe ztunnel logs
Expand All @@ -130,3 +141,42 @@ func processLogLine(line string) (timeStamp *time.Time, level string, text strin
valid = true
return
}

type logJSON struct {
Time string
Level string
Msg string
}

func parseJSONLog(line string) (timeStamp *time.Time, level string, text string, valid bool) {
lj := logJSON{}

err := json.Unmarshal([]byte(line), &lj)
if err != nil {
return nil, "", "", false
}

// todo: add logging for err
m := lj.Msg
if m == "" {
return nil, "", "", false
}

t := lj.Time
ts, err := time.Parse(time.RFC3339Nano, t)
if err != nil {
return nil, "", "", false
}

l := lj.Level
switch l {
case levelFatal, levelError, levelWarn, levelInfo, levelDebug, levelTrace:
default:
return nil, "", "", false
}
return &ts, l, m, true
}

func isJSONLog(logStr string) bool {
return strings.HasPrefix(logStr, "{")
}
82 changes: 82 additions & 0 deletions tools/bug-report/pkg/processlog/processlog_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,82 @@
// Copyright Istio Authors
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
// http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.

package processlog

import (
"path/filepath"
"testing"
"time"

"github.com/google/go-cmp/cmp"

"istio.io/istio/pilot/test/util"
"istio.io/istio/pkg/test/env"
"istio.io/istio/tools/bug-report/pkg/config"
)

func TestProcessLogsFormat(t *testing.T) {
testDataDir := filepath.Join(env.IstioSrc, "tools/bug-report/pkg/testdata/")

tests := []struct {
name string
inputLogFilePath string
wantOutputLogPath string
startTime string
endTime string
timeFilterApplied bool
}{
{
name: "input_log_of_text_format",
inputLogFilePath: "input/format_txt.log",
wantOutputLogPath: "output/format_txt_no_time_filter.log",
timeFilterApplied: false,
},
{
name: "input_log_of_json_format",
inputLogFilePath: "input/format_json.log",
wantOutputLogPath: "output/format_json_no_time_filter.log",
timeFilterApplied: false,
},
{
name: "input_log_of_text_format",
inputLogFilePath: "input/format_txt.log",
wantOutputLogPath: "output/format_txt_with_time_filter.log",
startTime: "2020-06-29T23:37:27.336155Z",
endTime: "2020-06-29T23:37:27.349559Z",
timeFilterApplied: true,
},
{
name: "input_log_of_json_format",
inputLogFilePath: "input/format_json.log",
wantOutputLogPath: "output/format_json_with_time_filter.log",
startTime: "2023-05-10T17:43:55.356647Z",
endTime: "2023-05-10T17:43:55.356691Z",
timeFilterApplied: true,
},
}
for _, tt := range tests {
t.Run(tt.name, func(t *testing.T) {
inputLog := string(util.ReadFile(t, filepath.Join(testDataDir, tt.inputLogFilePath)))
wantOutputLog := string(util.ReadFile(t, filepath.Join(testDataDir, tt.wantOutputLogPath)))
start, _ := time.Parse(time.RFC3339Nano, tt.startTime)
end, _ := time.Parse(time.RFC3339Nano, tt.endTime)
c := config.BugReportConfig{StartTime: start, EndTime: end, TimeFilterApplied: tt.timeFilterApplied}
gotOutputLog, _ := Process(&c, inputLog)
if wantOutputLog != gotOutputLog {
t.Errorf("got:\n%s\nwant:\n%s\n\ndiff (-got, +want):\n%s\n", gotOutputLog, wantOutputLog, cmp.Diff(gotOutputLog, wantOutputLog))
}
})
}
}
12 changes: 12 additions & 0 deletions tools/bug-report/pkg/testdata/input/format_json.log
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,12 @@
{"level":"info","time":"2023-05-10T17:43:55.356626Z","msg":"FLAG: --keepaliveTimeout=\"10s\""}
{"level":"info","time":"2023-05-10T17:43:55.356630Z","msg":"FLAG: --kubeconfig=\"\""}
{"level":"info","time":"2023-05-10T17:43:55.356636Z","msg":"FLAG: --kubernetesApiBurst=\"160\""}
{"level":"info","time":"2023-05-10T17:43:55.356643Z","msg":"FLAG: --kubernetesApiQPS=\"80\""}
{"level":"info","time":"2023-05-10T17:43:55.356647Z","msg":"FLAG: --log_as_json=\"true\""}
{"level":"info","time":"2023-05-10T17:43:55.356669Z","msg":"FLAG: --log_caller=\"\""}
{"level":"info","time":"2023-05-10T17:43:55.356675Z","msg":"FLAG: --log_output_level=\"default:info\""}
{"level":"info","time":"2023-05-10T17:43:55.356681Z","msg":"FLAG: --log_rotate=\"\""}
{"level":"info","time":"2023-05-10T17:43:55.356685Z","msg":"FLAG: --log_rotate_max_age=\"30\""}
{"level":"info","time":"2023-05-10T17:43:55.356691Z","msg":"FLAG: --log_rotate_max_backups=\"1000\""}
{"level":"info","time":"2023-05-10T17:43:55.356696Z","msg":"FLAG: --log_rotate_max_size=\"104857600\""}
{"level":"info","time":"2023-05-10T17:43:55.356701Z","msg":"FLAG: --log_stacktrace_level=\"default:none\""}
14 changes: 14 additions & 0 deletions tools/bug-report/pkg/testdata/input/format_txt.log
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,14 @@
2020-06-29T23:37:27.335928Z info parsed scheme: ""
2020-06-29T23:37:27.335940Z info scheme "" not registered, fallback to default scheme
2020-06-29T23:37:27.336128Z info ccResolverWrapper: sending update to cc: {[{istiod.istio-system.svc:15012 <nil> 0 <nil>}] <nil> <nil>}
2020-06-29T23:37:27.336149Z info ClientConn switching balancer to "pick_first"
2020-06-29T23:37:27.336155Z info Channel switches to new LB policy "pick_first"
2020-06-29T23:37:27.336189Z info Subchannel Connectivity change to CONNECTING
2020-06-29T23:37:27.336222Z info Starting gateway SDS
2020-06-29T23:37:27.336491Z info pickfirstBalancer: HandleSubConnStateChange: 0xc00087d1e0, {CONNECTING <nil>}
2020-06-29T23:37:27.336645Z info Channel Connectivity change to CONNECTING
2020-06-29T23:37:27.336838Z info Subchannel picks a new address "istiod.istio-system.svc:15012" to connect
2020-06-29T23:37:27.349559Z info Subchannel Connectivity change to READY
2020-06-29T23:37:27.349600Z info pickfirstBalancer: HandleSubConnStateChange: 0xc00087d1e0, {READY <nil>}
2020-06-29T23:37:27.349610Z info Channel Connectivity change to READY
2020-06-29T23:37:27.438932Z info sds SDS gRPC server for workload UDS starts, listening on "./etc/istio/proxy/SDS"
12 changes: 12 additions & 0 deletions tools/bug-report/pkg/testdata/output/format_json_no_time_filter.log
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,12 @@
{"level":"info","time":"2023-05-10T17:43:55.356626Z","msg":"FLAG: --keepaliveTimeout=\"10s\""}
{"level":"info","time":"2023-05-10T17:43:55.356630Z","msg":"FLAG: --kubeconfig=\"\""}
{"level":"info","time":"2023-05-10T17:43:55.356636Z","msg":"FLAG: --kubernetesApiBurst=\"160\""}
{"level":"info","time":"2023-05-10T17:43:55.356643Z","msg":"FLAG: --kubernetesApiQPS=\"80\""}
{"level":"info","time":"2023-05-10T17:43:55.356647Z","msg":"FLAG: --log_as_json=\"true\""}
{"level":"info","time":"2023-05-10T17:43:55.356669Z","msg":"FLAG: --log_caller=\"\""}
{"level":"info","time":"2023-05-10T17:43:55.356675Z","msg":"FLAG: --log_output_level=\"default:info\""}
{"level":"info","time":"2023-05-10T17:43:55.356681Z","msg":"FLAG: --log_rotate=\"\""}
{"level":"info","time":"2023-05-10T17:43:55.356685Z","msg":"FLAG: --log_rotate_max_age=\"30\""}
{"level":"info","time":"2023-05-10T17:43:55.356691Z","msg":"FLAG: --log_rotate_max_backups=\"1000\""}
{"level":"info","time":"2023-05-10T17:43:55.356696Z","msg":"FLAG: --log_rotate_max_size=\"104857600\""}
{"level":"info","time":"2023-05-10T17:43:55.356701Z","msg":"FLAG: --log_stacktrace_level=\"default:none\""}
6 changes: 6 additions & 0 deletions tools/bug-report/pkg/testdata/output/format_json_with_time_filter.log
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,6 @@
{"level":"info","time":"2023-05-10T17:43:55.356647Z","msg":"FLAG: --log_as_json=\"true\""}
{"level":"info","time":"2023-05-10T17:43:55.356669Z","msg":"FLAG: --log_caller=\"\""}
{"level":"info","time":"2023-05-10T17:43:55.356675Z","msg":"FLAG: --log_output_level=\"default:info\""}
{"level":"info","time":"2023-05-10T17:43:55.356681Z","msg":"FLAG: --log_rotate=\"\""}
{"level":"info","time":"2023-05-10T17:43:55.356685Z","msg":"FLAG: --log_rotate_max_age=\"30\""}
{"level":"info","time":"2023-05-10T17:43:55.356691Z","msg":"FLAG: --log_rotate_max_backups=\"1000\""}
14 changes: 14 additions & 0 deletions tools/bug-report/pkg/testdata/output/format_txt_no_time_filter.log
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,14 @@
2020-06-29T23:37:27.335928Z info parsed scheme: ""
2020-06-29T23:37:27.335940Z info scheme "" not registered, fallback to default scheme
2020-06-29T23:37:27.336128Z info ccResolverWrapper: sending update to cc: {[{istiod.istio-system.svc:15012 <nil> 0 <nil>}] <nil> <nil>}
2020-06-29T23:37:27.336149Z info ClientConn switching balancer to "pick_first"
2020-06-29T23:37:27.336155Z info Channel switches to new LB policy "pick_first"
2020-06-29T23:37:27.336189Z info Subchannel Connectivity change to CONNECTING
2020-06-29T23:37:27.336222Z info Starting gateway SDS
2020-06-29T23:37:27.336491Z info pickfirstBalancer: HandleSubConnStateChange: 0xc00087d1e0, {CONNECTING <nil>}
2020-06-29T23:37:27.336645Z info Channel Connectivity change to CONNECTING
2020-06-29T23:37:27.336838Z info Subchannel picks a new address "istiod.istio-system.svc:15012" to connect
2020-06-29T23:37:27.349559Z info Subchannel Connectivity change to READY
2020-06-29T23:37:27.349600Z info pickfirstBalancer: HandleSubConnStateChange: 0xc00087d1e0, {READY <nil>}
2020-06-29T23:37:27.349610Z info Channel Connectivity change to READY
2020-06-29T23:37:27.438932Z info sds SDS gRPC server for workload UDS starts, listening on "./etc/istio/proxy/SDS"
7 changes: 7 additions & 0 deletions tools/bug-report/pkg/testdata/output/format_txt_with_time_filter.log
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,7 @@
2020-06-29T23:37:27.336155Z info Channel switches to new LB policy "pick_first"
2020-06-29T23:37:27.336189Z info Subchannel Connectivity change to CONNECTING
2020-06-29T23:37:27.336222Z info Starting gateway SDS
2020-06-29T23:37:27.336491Z info pickfirstBalancer: HandleSubConnStateChange: 0xc00087d1e0, {CONNECTING <nil>}
2020-06-29T23:37:27.336645Z info Channel Connectivity change to CONNECTING
2020-06-29T23:37:27.336838Z info Subchannel picks a new address "istiod.istio-system.svc:15012" to connect
2020-06-29T23:37:27.349559Z info Subchannel Connectivity change to READY