diff --git a/cmd/bootstrap-peer-server.go b/cmd/bootstrap-peer-server.go index 5d4249da1..97af95569 100644 --- a/cmd/bootstrap-peer-server.go +++ b/cmd/bootstrap-peer-server.go @@ -24,6 +24,7 @@ import ( "io" "net/http" "net/url" + "os" "reflect" "time" @@ -216,6 +217,7 @@ func verifyServerSystemConfig(ctx context.Context, endpointServerPools EndpointS for onlineServers < len(clnts)/2 { for _, clnt := range clnts { if err := clnt.Verify(ctx, srcCfg); err != nil { + bootstrapTrace(fmt.Sprintf("clnt.Verify: %v, endpoint: %v", err, clnt.endpoint)) if !isNetworkError(err) { logger.LogOnceIf(ctx, fmt.Errorf("%s has incorrect configuration: %w", clnt.String(), err), clnt.String()) incorrectConfigs = append(incorrectConfigs, fmt.Errorf("%s has incorrect configuration: %w", clnt.String(), err)) @@ -264,7 +266,11 @@ func newBootstrapRESTClients(endpointServerPools EndpointServerPools) []*bootstr // Only proceed for remote endpoints. if !endpoint.IsLocal { - clnts = append(clnts, newBootstrapRESTClient(endpoint)) + cl := newBootstrapRESTClient(endpoint) + if serverDebugLog { + cl.restClient.TraceOutput = os.Stdout + } + clnts = append(clnts, cl) } } } diff --git a/cmd/server-main.go b/cmd/server-main.go index 86ebfccfe..270c5c65f 100644 --- a/cmd/server-main.go +++ b/cmd/server-main.go @@ -396,6 +396,9 @@ func configRetriableErrors(err error) bool { func bootstrapTrace(msg string) { globalBootstrapTracer.Record(msg, 2) + if serverDebugLog { + logger.Info(fmt.Sprint(time.Now().Round(time.Millisecond).Format(time.RFC3339), " bootstrap: ", msg)) + } if globalTrace.NumSubscribers(madmin.TraceBootstrap) == 0 { return @@ -516,30 +519,38 @@ func serverMain(ctx *cli.Context) { setDefaultProfilerRates() // Initialize globalConsoleSys system + bootstrapTrace("newConsoleLogger") globalConsoleSys = NewConsoleLogger(GlobalContext) logger.AddSystemTarget(GlobalContext, globalConsoleSys) // Perform any self-tests + bootstrapTrace("selftests") bitrotSelfTest() erasureSelfTest() compressSelfTest() // Handle all server environment vars. + bootstrapTrace("serverHandleEnvVars") serverHandleEnvVars() // Handle all server command args. + bootstrapTrace("serverHandleCmdArgs") serverHandleCmdArgs(ctx) // Initialize KMS configuration + bootstrapTrace("handleKMSConfig") handleKMSConfig() // Set node name, only set for distributed setup. + bootstrapTrace("setNodeName") globalConsoleSys.SetNodeName(globalLocalNodeName) // Initialize all help + bootstrapTrace("initHelp") initHelp() // Initialize all sub-systems + bootstrapTrace("initAllSubsystems") initAllSubsystems(GlobalContext) // Is distributed setup, error out if no certificates are found for HTTPS endpoints. @@ -556,11 +567,13 @@ func serverMain(ctx *cli.Context) { go func() { if !globalCLIContext.Quiet && !globalInplaceUpdateDisabled { // Check for new updates from dl.min.io. + bootstrapTrace("checkUpdate") checkUpdate(getMinioMode()) } }() // Set system resources to maximum. + bootstrapTrace("setMaxResources") setMaxResources() // Verify kernel release and version. @@ -575,6 +588,7 @@ func serverMain(ctx *cli.Context) { } // Configure server. + bootstrapTrace("configureServerHandler") handler, err := configureServerHandler(globalEndpoints) if err != nil { logger.Fatal(config.ErrUnexpectedError(err), "Unable to configure one of server's RPC services") @@ -585,6 +599,7 @@ func serverMain(ctx *cli.Context) { getCert = globalTLSCerts.GetCertificate } + bootstrapTrace("xhttp.NewServer") httpServer := xhttp.NewServer(getServerListenAddrs()). UseHandler(setCriticalErrorHandler(corsHandler(handler))). UseTLSConfig(newTLSConfig(getCert)). @@ -595,10 +610,12 @@ func serverMain(ctx *cli.Context) { UseCustomLogger(log.New(io.Discard, "", 0)). // Turn-off random logging by Go stdlib UseTCPOptions(globalTCPOptions) + httpServer.TCPOptions.Trace = bootstrapTrace go func() { globalHTTPServerErrorCh <- httpServer.Start(GlobalContext) }() + bootstrapTrace("setHTTPServer") setHTTPServer(httpServer) if globalIsDistErasure { @@ -609,6 +626,7 @@ func serverMain(ctx *cli.Context) { } } + bootstrapTrace("newObjectLayer") newObject, err := newObjectLayer(GlobalContext, globalEndpoints) if err != nil { logFatalErrs(err, Endpoint{}, true) @@ -617,11 +635,15 @@ func serverMain(ctx *cli.Context) { xhttp.SetDeploymentID(globalDeploymentID) xhttp.SetMinIOVersion(Version) + bootstrapTrace("newSharedLock") globalLeaderLock = newSharedLock(GlobalContext, newObject, "leader.lock") // Enable background operations for erasure coding + bootstrapTrace("initAutoHeal") initAutoHeal(GlobalContext, newObject) + bootstrapTrace("initHealMRF") initHealMRF(GlobalContext, newObject) + bootstrapTrace("initBackgroundExpiry") initBackgroundExpiry(GlobalContext, newObject) if !globalCLIContext.StrictS3Compat { @@ -658,15 +680,18 @@ func serverMain(ctx *cli.Context) { // Initialize users credentials and policies in background right after config has initialized. go func() { + bootstrapTrace("globalIAMSys.Init") globalIAMSys.Init(GlobalContext, newObject, globalEtcdClient, globalRefreshIAMInterval) // Initialize if globalBrowserEnabled { + bootstrapTrace("initConsoleServer") srv, err := initConsoleServer() if err != nil { logger.FatalIf(err, "Unable to initialize console service") } + bootstrapTrace("setConsoleSrv") setConsoleSrv(srv) go func() { @@ -676,18 +701,22 @@ func serverMain(ctx *cli.Context) { // if we see FTP args, start FTP if possible if len(ctx.StringSlice("ftp")) > 0 { + bootstrapTrace("startFTPServer") go startFTPServer(ctx) } // If we see SFTP args, start SFTP if possible if len(ctx.StringSlice("sftp")) > 0 { + bootstrapTrace("startFTPServer") go startSFTPServer(ctx) } }() go func() { if !globalDisableFreezeOnBoot { + bootstrapTrace("freezeServices") defer unfreezeServices() + defer bootstrapTrace("unfreezeServices") t := time.AfterFunc(5*time.Minute, func() { logger.Info(color.Yellow("WARNING: Taking more time to initialize the config subsystem. Please set '_MINIO_DISABLE_API_FREEZE_ON_BOOT=true' to not freeze the APIs")) }) @@ -695,21 +724,27 @@ func serverMain(ctx *cli.Context) { } // Initialize data scanner. + bootstrapTrace("initDataScanner") initDataScanner(GlobalContext, newObject) // Initialize background replication + bootstrapTrace("initBackgroundReplication") initBackgroundReplication(GlobalContext, newObject) + bootstrapTrace("globalTransitionState.Init") globalTransitionState.Init(newObject) // Initialize batch job pool. + bootstrapTrace("newBatchJobPool") globalBatchJobPool = newBatchJobPool(GlobalContext, newObject, 100) // Initialize the license update job + bootstrapTrace("initLicenseUpdateJob") initLicenseUpdateJob(GlobalContext, newObject) go func() { // Initialize transition tier configuration manager + bootstrapTrace("globalTierConfigMgr.Init") err := globalTierConfigMgr.Init(GlobalContext, newObject) if err != nil { logger.LogIf(GlobalContext, err) @@ -732,29 +767,36 @@ func serverMain(ctx *cli.Context) { } // Initialize bucket notification system. + bootstrapTrace("initBucketTargets") logger.LogIf(GlobalContext, globalEventNotifier.InitBucketTargets(GlobalContext, newObject)) // List buckets to initialize bucket metadata sub-sys. + bootstrapTrace("listBuckets") buckets, err := newObject.ListBuckets(GlobalContext, BucketOptions{}) if err != nil { logger.LogIf(GlobalContext, fmt.Errorf("Unable to list buckets to initialize bucket metadata sub-system: %w", err)) } // Initialize bucket metadata sub-system. + bootstrapTrace("globalBucketMetadataSys.Init") globalBucketMetadataSys.Init(GlobalContext, buckets, newObject) // initialize replication resync state. + bootstrapTrace("go initResync") go globalReplicationPool.initResync(GlobalContext, buckets, newObject) // Initialize site replication manager after bucket metadata + bootstrapTrace("globalSiteReplicationSys.Init") globalSiteReplicationSys.Init(GlobalContext, newObject) // Initialize quota manager. + bootstrapTrace("globalBucketQuotaSys.Init") globalBucketQuotaSys.Init(newObject) // Populate existing buckets to the etcd backend if globalDNSConfig != nil { // Background this operation. + bootstrapTrace("initFederatorBackend") go initFederatorBackend(buckets, newObject) } @@ -771,6 +813,7 @@ func serverMain(ctx *cli.Context) { if region == "" { region = "us-east-1" } + bootstrapTrace("globalMinioClient") globalMinioClient, err = minio.New(globalLocalNodeName, &minio.Options{ Creds: credentials.NewStaticV4(globalActiveCred.AccessKey, globalActiveCred.SecretKey, ""), Secure: globalIsTLS, diff --git a/internal/http/listener.go b/internal/http/listener.go index 63490333b..49bd6a316 100644 --- a/internal/http/listener.go +++ b/internal/http/listener.go @@ -120,8 +120,9 @@ func (listener *httpListener) Addrs() (addrs []net.Addr) { // TCPOptions specify customizable TCP optimizations on raw socket type TCPOptions struct { - UserTimeout int // this value is expected to be in milliseconds - Interface string // this is a VRF device passed via `--interface` flag + UserTimeout int // this value is expected to be in milliseconds + Interface string // this is a VRF device passed via `--interface` flag + Trace func(msg string) // Trace when starting. } // newHTTPListener - creates new httpListener object which is interface compatible to net.Listener. @@ -162,6 +163,10 @@ func newHTTPListener(ctx context.Context, serverAddrs []string, opts TCPOptions) for _, serverAddr := range serverAddrs { var l net.Listener if l, err = listenCfg.Listen(ctx, "tcp", serverAddr); err != nil { + if opts.Trace != nil { + opts.Trace(fmt.Sprint("listenCfg.Listen: ", err.Error())) + } + if isLocalhost && strings.HasPrefix(serverAddr, "[::1") { continue } @@ -171,12 +176,18 @@ func newHTTPListener(ctx context.Context, serverAddrs []string, opts TCPOptions) tcpListener, ok := l.(*net.TCPListener) if !ok { err = fmt.Errorf("unexpected listener type found %v, expected net.TCPListener", l) + if opts.Trace != nil { + opts.Trace(fmt.Sprint("net.TCPListener: ", err.Error())) + } + if isLocalhost && strings.HasPrefix(serverAddr, "[::1") { continue } return nil, err } - + if opts.Trace != nil { + opts.Trace(fmt.Sprint("adding listener to ", tcpListener.Addr())) + } tcpListeners = append(tcpListeners, tcpListener) } @@ -196,6 +207,9 @@ func newHTTPListener(ctx context.Context, serverAddrs []string, opts TCPOptions) acceptCh: make(chan acceptResult, len(tcpListeners)), } listener.ctx, listener.ctxCanceler = context.WithCancel(ctx) + if opts.Trace != nil { + opts.Trace(fmt.Sprint("opening ", len(listener.tcpListeners), " listeners")) + } listener.start() return listener, nil diff --git a/internal/rest/client.go b/internal/rest/client.go index 77288d06a..4cbc7a8bb 100644 --- a/internal/rest/client.go +++ b/internal/rest/client.go @@ -25,6 +25,7 @@ import ( "io" "math/rand" "net/http" + "net/http/httputil" "net/url" "path" "strings" @@ -89,6 +90,9 @@ type Client struct { // Avoid metrics update if set to true NoMetrics bool + // TraceOutput will print debug information on non-200 calls if set. + TraceOutput io.Writer // Debug trace output + httpClient *http.Client url *url.URL newAuthToken func(audience string) string @@ -222,6 +226,66 @@ func (r *respBodyMonitor) errorStatus(err error) { } } +// dumpHTTP - dump HTTP request and response. +func (c *Client) dumpHTTP(req *http.Request, resp *http.Response) { + // Starts http dump. + _, err := fmt.Fprintln(c.TraceOutput, "---------START-HTTP---------") + if err != nil { + return + } + + // Filter out Signature field from Authorization header. + origAuth := req.Header.Get("Authorization") + if origAuth != "" { + req.Header.Set("Authorization", "**REDACTED**") + } + + // Only display request header. + reqTrace, err := httputil.DumpRequestOut(req, false) + if err != nil { + return + } + + // Write request to trace output. + _, err = fmt.Fprint(c.TraceOutput, string(reqTrace)) + if err != nil { + return + } + + // Only display response header. + var respTrace []byte + + // For errors we make sure to dump response body as well. + if resp.StatusCode != http.StatusOK && + resp.StatusCode != http.StatusPartialContent && + resp.StatusCode != http.StatusNoContent { + respTrace, err = httputil.DumpResponse(resp, true) + if err != nil { + return + } + } else { + respTrace, err = httputil.DumpResponse(resp, false) + if err != nil { + return + } + } + + // Write response to trace output. + _, err = fmt.Fprint(c.TraceOutput, strings.TrimSuffix(string(respTrace), "\r\n")) + if err != nil { + return + } + + // Ends the http dump. + _, err = fmt.Fprintln(c.TraceOutput, "---------END-HTTP---------") + if err != nil { + return + } + + // Returns success. + return +} + // Call - make a REST call with context. func (c *Client) Call(ctx context.Context, method string, values url.Values, body io.Reader, length int64) (reply io.ReadCloser, err error) { urlStr := c.url.String() @@ -263,6 +327,12 @@ func (c *Client) Call(ctx context.Context, method string, values url.Values, bod return nil, &NetworkError{err} } + // If trace is enabled, dump http request and response, + // except when the traceErrorsOnly enabled and the response's status code is ok + if c.TraceOutput != nil && resp.StatusCode != http.StatusOK { + c.dumpHTTP(req, resp) + } + if resp.StatusCode != http.StatusOK { // If server returns 412 pre-condition failed, it would // mean that authentication succeeded, but another