diff --git a/.github/actions/env-setup/action.yaml b/.github/actions/env-setup/action.yaml index 74e7658ad..c41a61583 100644 --- a/.github/actions/env-setup/action.yaml +++ b/.github/actions/env-setup/action.yaml @@ -70,10 +70,3 @@ runs: run: | echo "Installing Ginkgo testing framework..." go install github.com/onsi/ginkgo/v2/ginkgo@v2.14.0 - - - name: Cache Go Dependencies - uses: actions/cache@v4 - with: - path: .work/pkg - key: ${{ runner.os }}-pkg-${{ hashFiles('**/go.sum') }} - restore-keys: ${{ runner.os }}-pkg- \ No newline at end of file diff --git a/charts/vela-core/README.md b/charts/vela-core/README.md index 2c89d0688..8b078362d 100644 --- a/charts/vela-core/README.md +++ b/charts/vela-core/README.md @@ -148,6 +148,7 @@ helm install --create-namespace -n vela-system kubevela kubevela/vela-core --wai | `affinity` | Affinity | `{}` | | `rbac.create` | Specifies whether a RBAC role should be created | `true` | | `logDebug` | Enable debug logs for development purpose | `false` | +| `devLogs` | Enable formatted logging support for development purpose | `false` | | `logFilePath` | If non-empty, write log files in this path | `""` | | `logFileMaxSize` | Defines the maximum size a log file can grow to. Unit is megabytes. If the value is 0, the maximum file size is unlimited. | `1024` | | `kubeClient.qps` | The qps for reconcile clients | `400` | diff --git a/charts/vela-core/templates/kubevela-controller.yaml b/charts/vela-core/templates/kubevela-controller.yaml index bda74980f..746ba1425 100644 --- a/charts/vela-core/templates/kubevela-controller.yaml +++ b/charts/vela-core/templates/kubevela-controller.yaml @@ -328,6 +328,7 @@ spec: - "--feature-gates=ValidateComponentWhenSharding={{- .Values.featureGates.validateComponentWhenSharding | toString -}}" - "--feature-gates=DisableWebhookAutoSchedule={{- .Values.featureGates.disableWebhookAutoSchedule | toString -}}" {{ end }} + - "--dev-logs={{ .Values.devLogs }}" image: {{ .Values.imageRegistry }}{{ .Values.image.repository }}:{{ .Values.image.tag }} imagePullPolicy: {{ quote .Values.image.pullPolicy }} resources: diff --git a/charts/vela-core/values.yaml b/charts/vela-core/values.yaml index 77ee3d38c..8b2d5fdb9 100644 --- a/charts/vela-core/values.yaml +++ b/charts/vela-core/values.yaml @@ -258,6 +258,9 @@ rbac: ## @param logDebug Enable debug logs for development purpose logDebug: false +## @param devLogs Enable formatted logging support for development purpose +devLogs: false + ## @param logFilePath If non-empty, write log files in this path logFilePath: "" diff --git a/cmd/core/app/color_writer.go b/cmd/core/app/color_writer.go new file mode 100644 index 000000000..dd1fc51a4 --- /dev/null +++ b/cmd/core/app/color_writer.go @@ -0,0 +1,580 @@ +/* +Copyright 2022 The KubeVela 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 app + +import ( + "bytes" + "fmt" + "go/ast" + "go/parser" + "go/token" + "io" + "io/fs" + "os" + "path/filepath" + "regexp" + "strconv" + "strings" + "sync" + "unicode" +) + +const ( + ansiReset = "\x1b[0m" + ansiDate = "\x1b[36m" + ansiInfo = "\x1b[32m" + ansiWarn = "\x1b[33m" + ansiError = "\x1b[31m" + ansiFatal = "\x1b[35m" + ansiDebug = "\x1b[34m" + ansiThread = "\x1b[34m" + ansiLocation = "\x1b[93m" + ansiMessage = "\x1b[97m" + ansiKey = "\x1b[96m" + ansiValue = "\x1b[37m" +) + +var methodPatterns = []*regexp.Regexp{ + regexp.MustCompile(`(?i)\b(?:caller|func|function|method)\s*[:=]\s*"?([a-zA-Z0-9_./()*-]+)`), +} + +var srcIdx = newSourceIndex() + +type colorWriter struct { + dst io.Writer + mu sync.Mutex + buf bytes.Buffer +} + +func newColorWriter(dst io.Writer) io.Writer { + return &colorWriter{dst: dst} +} + +func (w *colorWriter) Write(p []byte) (int, error) { + w.mu.Lock() + defer w.mu.Unlock() + + written := 0 + for len(p) > 0 { + idx := bytes.IndexByte(p, '\n') + if idx == -1 { + _, _ = w.buf.Write(p) + written += len(p) + break + } + _, _ = w.buf.Write(p[:idx]) + if err := w.flushLineLocked(); err != nil { + written += idx + return written, err + } + if _, err := w.dst.Write([]byte{'\n'}); err != nil { + written += idx + 1 + return written, err + } + p = p[idx+1:] + written += idx + 1 + } + return written, nil +} + +func (w *colorWriter) flushLineLocked() error { + if w.buf.Len() == 0 { + return nil + } + line := w.buf.String() + w.buf.Reset() + _, err := io.WriteString(w.dst, formatColoredLine(line)) + return err +} + +func formatColoredLine(line string) string { + if len(line) == 0 { + return line + } + severity := line[0] + rest := line[1:] + headerEnd := strings.IndexByte(rest, ']') + if headerEnd == -1 { + return line + } + header := rest[:headerEnd] + remainder := strings.TrimSpace(rest[headerEnd+1:]) + fields := strings.Fields(header) + if len(fields) < 4 { + return line + } + + date := fields[0] + ts := fields[1] + pid := strings.TrimSpace(fields[2]) + rawLocation := strings.Join(fields[3:], " ") + level, levelColor := mapSeverity(severity) + location := buildLocation(rawLocation, remainder) + + sb := strings.Builder{} + sb.Grow(len(line) + 32) + + sb.WriteString(ansiDate) + sb.WriteString("[") + sb.WriteString(formatTimestamp(date, ts)) + sb.WriteString("]") + sb.WriteString(ansiReset) + sb.WriteString(" ") + + sb.WriteString(levelColor) + sb.WriteString("[") + sb.WriteString(fmt.Sprintf("%-5s", level)) + sb.WriteString("]") + sb.WriteString(ansiReset) + sb.WriteString(" ") + + sb.WriteString(ansiThread) + sb.WriteString("[") + sb.WriteString(pid) + sb.WriteString("]") + sb.WriteString(ansiReset) + sb.WriteString(" ") + + sb.WriteString(ansiLocation) + sb.WriteString("[") + sb.WriteString(location) + sb.WriteString("]") + sb.WriteString(ansiReset) + + if remainder != "" { + msg, fields := splitMessageAndFields(remainder) + if msg != "" { + sb.WriteString(" ") + sb.WriteString(ansiMessage) + sb.WriteString(msg) + sb.WriteString(ansiReset) + } + for _, field := range fields { + sb.WriteString(" ") + sb.WriteString(ansiKey) + sb.WriteString(field.key) + sb.WriteString(ansiReset) + sb.WriteString("=") + sb.WriteString(ansiValue) + sb.WriteString(field.renderValue()) + sb.WriteString(ansiReset) + } + } + + return sb.String() +} + +func mapSeverity(s byte) (string, string) { + switch s { + case 'I': + return "INFO", ansiInfo + case 'W': + return "WARN", ansiWarn + case 'E': + return "ERROR", ansiError + case 'F': + return "FATAL", ansiFatal + case 'D': + return "DEBUG", ansiDebug + default: + return string(s), ansiDebug + } +} + +func formatTimestamp(date, ts string) string { + if len(date) == 4 { + return fmt.Sprintf("%s-%s %s", date[:2], date[2:], trimMicros(ts)) + } + return strings.TrimSpace(date + " " + trimMicros(ts)) +} + +func trimMicros(ts string) string { + if dot := strings.IndexByte(ts, '.'); dot != -1 && len(ts) > dot+4 { + return ts[:dot+4] + } + return ts +} + +func buildLocation(rawLocation, remainder string) string { + file, line := splitFileAndLine(rawLocation) + method := lookupMethod(file, line) + if method == "" { + method = extractMethodName(remainder) + } + if file == "" { + return rawLocation + } + if method == "" { + if line != "" { + return fmt.Sprintf("%s:%s", file, line) + } + return file + } + if line == "" { + return fmt.Sprintf("%s:%s", file, method) + } + return fmt.Sprintf("%s:%s:%s", file, method, line) +} + +func splitFileAndLine(raw string) (string, string) { + trimmed := strings.TrimSpace(raw) + if trimmed == "" { + return "", "" + } + lastColon := strings.LastIndex(trimmed, ":") + if lastColon == -1 { + return trimmed, "" + } + return strings.TrimSpace(trimmed[:lastColon]), strings.TrimSpace(trimmed[lastColon+1:]) +} + +type kvField struct { + key string + value string + quoted bool +} + +func (f kvField) renderValue() string { + if f.quoted { + return fmt.Sprintf("\"%s\"", f.value) + } + return f.value +} + +func splitMessageAndFields(s string) (string, []kvField) { + s = strings.TrimSpace(s) + if s == "" { + return "", nil + } + idx := findFirstKVIndex(s) + if idx == -1 { + return s, nil + } + msg := strings.TrimSpace(s[:idx]) + fields := parseKeyValues(s[idx:]) + return msg, fields +} + +func findFirstKVIndex(s string) int { + inQuotes := false + for i := 0; i < len(s); i++ { + ch := s[i] + if ch == '"' { + if i == 0 || s[i-1] != '\\' { + inQuotes = !inQuotes + } + continue + } + if inQuotes { + continue + } + if ch == '=' { + keyEnd := i + keyStart := keyEnd - 1 + for keyStart >= 0 && !unicode.IsSpace(rune(s[keyStart])) { + keyStart-- + } + key := strings.TrimSpace(s[keyStart+1 : keyEnd]) + if isValidKey(key) { + return keyStart + 1 + } + } + } + return -1 +} + +func parseKeyValues(s string) []kvField { + fields := make([]kvField, 0) + i := 0 + for i < len(s) { + for i < len(s) && unicode.IsSpace(rune(s[i])) { + i++ + } + if i >= len(s) { + break + } + keyStart := i + for i < len(s) && s[i] != '=' && !unicode.IsSpace(rune(s[i])) { + i++ + } + keyEnd := i + for keyEnd > keyStart && unicode.IsSpace(rune(s[keyEnd-1])) { + keyEnd-- + } + if i >= len(s) || s[i] != '=' { + for i < len(s) && !unicode.IsSpace(rune(s[i])) { + i++ + } + continue + } + key := s[keyStart:keyEnd] + if !isValidKey(key) { + i++ + continue + } + i++ + for i < len(s) && unicode.IsSpace(rune(s[i])) { + i++ + } + if i >= len(s) { + fields = append(fields, kvField{key: key, value: "", quoted: false}) + break + } + quoted := false + var value string + if s[i] == '"' { + quoted = true + i++ + start := i + for i < len(s) { + if s[i] == '"' && (i == start || s[i-1] != '\\') { + break + } + i++ + } + value = s[start:i] + if i < len(s) && s[i] == '"' { + i++ + } + } else { + start := i + for i < len(s) && !unicode.IsSpace(rune(s[i])) { + i++ + } + value = s[start:i] + } + fields = append(fields, kvField{key: key, value: value, quoted: quoted}) + } + return fields +} + +func isValidKey(key string) bool { + if key == "" { + return false + } + for _, r := range key { + if unicode.IsLetter(r) || unicode.IsDigit(r) || r == '_' || r == '-' || r == '.' { + continue + } + return false + } + return true +} + +func extractMethodName(remainder string) string { + if remainder == "" { + return "" + } + for _, pattern := range methodPatterns { + if matches := pattern.FindStringSubmatch(remainder); len(matches) > 1 { + return simplifyMethodName(matches[1]) + } + } + return "" +} + +func simplifyMethodName(name string) string { + if name == "" { + return "" + } + name = strings.Trim(name, "\"' ") + if idx := strings.LastIndex(name, "/"); idx != -1 { + name = name[idx+1:] + } + return name +} + +func lookupMethod(file, line string) string { + if file == "" || line == "" { + return "" + } + ln, err := strconv.Atoi(line) + if err != nil || ln <= 0 { + return "" + } + return srcIdx.functionAt(file, ln) +} + +type funcInfo struct { + name string + startLine int + endLine int +} + +type fileCache struct { + once sync.Once + funcs []funcInfo +} + +type sourceIndex struct { + mu sync.Mutex + files map[string]*fileCache +} + +func newSourceIndex() *sourceIndex { + return &sourceIndex{files: make(map[string]*fileCache)} +} + +func (s *sourceIndex) functionAt(base string, line int) string { + s.mu.Lock() + cache, ok := s.files[base] + if !ok { + cache = &fileCache{} + s.files[base] = cache + } + s.mu.Unlock() + + cache.once.Do(func() { + cache.funcs = loadFunctionsFor(base) + }) + for _, fn := range cache.funcs { + if line >= fn.startLine && line <= fn.endLine { + return fn.name + } + } + return "" +} + +func loadFunctionsFor(base string) []funcInfo { + paths := findSourceFiles(base) + if len(paths) == 0 { + return nil + } + infos := make([]funcInfo, 0, len(paths)*4) + for _, path := range paths { + fset := token.NewFileSet() + fileAst, err := parser.ParseFile(fset, path, nil, 0) + if err != nil { + continue + } + for _, decl := range fileAst.Decls { + fn, ok := decl.(*ast.FuncDecl) + if !ok || fn.Name == nil { + continue + } + start := fset.Position(fn.Pos()).Line + end := fset.Position(fn.End()).Line + name := fn.Name.Name + if recv := receiverType(fn); recv != "" { + name = fmt.Sprintf("%s.%s", recv, name) + } + infos = append(infos, funcInfo{name: name, startLine: start, endLine: end}) + } + } + return infos +} + +func receiverType(fn *ast.FuncDecl) string { + if fn.Recv == nil || len(fn.Recv.List) == 0 { + return "" + } + return typeString(fn.Recv.List[0].Type) +} + +func typeString(expr ast.Expr) string { + switch v := expr.(type) { + case *ast.Ident: + return v.Name + case *ast.StarExpr: + return typeString(v.X) + case *ast.SelectorExpr: + return v.Sel.Name + case *ast.IndexExpr: + return typeString(v.X) + case *ast.IndexListExpr: + return typeString(v.X) + case *ast.ParenExpr: + return typeString(v.X) + default: + return "" + } +} + +var ( + searchRootsOnce sync.Once + cachedRoots []string +) + +func findSourceFiles(base string) []string { + matches := make([]string, 0) + seen := make(map[string]struct{}) + for _, root := range sourceRoots() { + if root == "" { + continue + } + lookupFilesInRoot(root, base, seen, &matches) + } + return matches +} + +func sourceRoots() []string { + searchRootsOnce.Do(func() { + roots := make([]string, 0, 4) + if env := os.Getenv("VELA_SOURCE_ROOT"); env != "" { + for _, item := range strings.Split(env, string(os.PathListSeparator)) { + if trimmed := strings.TrimSpace(item); trimmed != "" { + roots = append(roots, trimmed) + } + } + } + if cwd, err := os.Getwd(); err == nil { + roots = append(roots, cwd) + } + cachedRoots = dedupeStrings(roots) + }) + return cachedRoots +} + +func lookupFilesInRoot(root, base string, seen map[string]struct{}, matches *[]string) { + _ = filepath.WalkDir(root, func(path string, d fs.DirEntry, err error) error { + if err != nil { + // Continue scanning on error. + //nolint:nilerr + return nil + } + if d.IsDir() { + name := d.Name() + if name == "vendor" || name == "node_modules" || strings.HasPrefix(name, ".") { + if root == path { + return nil + } + return filepath.SkipDir + } + return nil + } + if d.Name() == base { + if _, ok := seen[path]; !ok { + seen[path] = struct{}{} + *matches = append(*matches, path) + } + } + return nil + }) +} + +func dedupeStrings(in []string) []string { + seen := make(map[string]struct{}, len(in)) + out := make([]string, 0, len(in)) + for _, v := range in { + if _, ok := seen[v]; ok { + continue + } + seen[v] = struct{}{} + out = append(out, v) + } + return out +} diff --git a/cmd/core/app/options/options.go b/cmd/core/app/options/options.go index be3096d31..7959c0f80 100644 --- a/cmd/core/app/options/options.go +++ b/cmd/core/app/options/options.go @@ -50,6 +50,7 @@ type CoreOptions struct { LogFilePath string LogFileMaxSize uint64 LogDebug bool + DevLogs bool ControllerArgs *oamcontroller.Args HealthAddr string StorageDriver string @@ -76,6 +77,7 @@ func NewCoreOptions() *CoreOptions { LogFilePath: "", LogFileMaxSize: 1024, LogDebug: false, + DevLogs: false, ControllerArgs: &oamcontroller.Args{ RevisionLimit: 50, AppRevisionLimit: 10, @@ -116,6 +118,7 @@ func (s *CoreOptions) Flags() cliflag.NamedFlagSets { gfs.StringVar(&s.LogFilePath, "log-file-path", s.LogFilePath, "The file to write logs to.") gfs.Uint64Var(&s.LogFileMaxSize, "log-file-max-size", s.LogFileMaxSize, "Defines the maximum size a log file can grow to, Unit is megabytes.") gfs.BoolVar(&s.LogDebug, "log-debug", s.LogDebug, "Enable debug logs for development purpose") + gfs.BoolVar(&s.DevLogs, "dev-logs", s.DevLogs, "Enable ANSI color formatting for console logs (ignored when log-file-path is set)") gfs.StringVar(&s.HealthAddr, "health-addr", s.HealthAddr, "The address the health endpoint binds to.") gfs.DurationVar(&s.InformerSyncPeriod, "informer-sync-period", s.InformerSyncPeriod, "The re-sync period for informer in controller-runtime. This is a system-level configuration.") diff --git a/cmd/core/app/server.go b/cmd/core/app/server.go index 064821917..36eef859b 100644 --- a/cmd/core/app/server.go +++ b/cmd/core/app/server.go @@ -103,6 +103,17 @@ func run(ctx context.Context, s *options.CoreOptions) error { restConfig.QPS = float32(s.QPS) restConfig.Burst = s.Burst restConfig.Wrap(auth.NewImpersonatingRoundTripper) + + // Set logger (use --dev-logs=true for local development) + if s.DevLogs { + logOutput := newColorWriter(os.Stdout) + klog.LogToStderr(false) + klog.SetOutput(logOutput) + ctrl.SetLogger(textlogger.NewLogger(textlogger.NewConfig(textlogger.Output(logOutput)))) + } else { + ctrl.SetLogger(textlogger.NewLogger(textlogger.NewConfig())) + } + klog.InfoS("Kubernetes Config Loaded", "UserAgent", restConfig.UserAgent, "QPS", restConfig.QPS, @@ -127,8 +138,6 @@ func run(ctx context.Context, s *options.CoreOptions) error { } } - ctrl.SetLogger(textlogger.NewLogger(textlogger.NewConfig())) - if utilfeature.DefaultMutableFeatureGate.Enabled(features.ApplyOnce) { commonconfig.ApplicationReSyncPeriod = s.InformerSyncPeriod }