Add more bootstrap info in debug mode (#17362)

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)
 			}
 		}
 	}

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,

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
+	UserTimeout int              // this value is expected to be in milliseconds
-	Interface   string // this is a VRF device passed via `--interface` flag
+	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

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