Update logging in scanHost and apply timeout to each step of the scan…

…ning progress (#1101)

Closes #1088

Updates `scanHost` to be a bit more generous with the timeout and apply
it to each step of the scanning process. That way, if resolving the IP
address took 3 seconds and fetching the settings takes 4 we won't fail
the scan if fetching the price table takes another 4 seconds.

We also log both errors now when a scan fails twice.

worker/worker.go

@@ -1436,64 +1436,81 @@ func (w *worker) scanHost(ctx context.Context, timeout time.Duration, hostKey ty
 	logger := w.logger.With("host", hostKey).With("hostIP", hostIP).With("timeout", timeout)
 	// prepare a helper for scanning
 	scan := func() (rhpv2.HostSettings, rhpv3.HostPriceTable, time.Duration, error) {
-		// apply timeout
-		scanCtx := ctx
-		var cancel context.CancelFunc
-		if timeout > 0 {
-			scanCtx, cancel = context.WithTimeout(scanCtx, timeout)
-			defer cancel()
-		}
-		// resolve hostIP. We don't want to scan hosts on private networks.
-		if !w.allowPrivateIPs {
-			host, _, err := net.SplitHostPort(hostIP)
-			if err != nil {
-				return rhpv2.HostSettings{}, rhpv3.HostPriceTable{}, 0, err
+		// helper to prepare a context for scanning
+		withTimeoutCtx := func() (context.Context, context.CancelFunc) {
+			if timeout > 0 {
+				return context.WithTimeout(ctx, timeout)
 			}
-			addrs, err := (&net.Resolver{}).LookupIPAddr(scanCtx, host)
-			if err != nil {
-				return rhpv2.HostSettings{}, rhpv3.HostPriceTable{}, 0, err
-			}
-			for _, addr := range addrs {
-				if isPrivateIP(addr.IP) {
-					return rhpv2.HostSettings{}, rhpv3.HostPriceTable{}, 0, api.ErrHostOnPrivateNetwork
+			return ctx, func() {}
+		}
+		// resolve the address
+		{
+			scanCtx, cancel := withTimeoutCtx()
+			defer cancel()
+			// resolve hostIP. We don't want to scan hosts on private networks.
+			if !w.allowPrivateIPs {
+				host, _, err := net.SplitHostPort(hostIP)
+				if err != nil {
+					return rhpv2.HostSettings{}, rhpv3.HostPriceTable{}, 0, err
+				}
+				addrs, err := (&net.Resolver{}).LookupIPAddr(scanCtx, host)
+				if err != nil {
+					return rhpv2.HostSettings{}, rhpv3.HostPriceTable{}, 0, err
+				}
+				for _, addr := range addrs {
+					if isPrivateIP(addr.IP) {
+						return rhpv2.HostSettings{}, rhpv3.HostPriceTable{}, 0, api.ErrHostOnPrivateNetwork
+					}
 				}
 			}
 		}
 
 		// fetch the host settings
 		start := time.Now()
 		var settings rhpv2.HostSettings
-		err := w.withTransportV2(scanCtx, hostKey, hostIP, func(t *rhpv2.Transport) error {
-			var err error
-			if settings, err = RPCSettings(scanCtx, t); err != nil {
-				return fmt.Errorf("failed to fetch host settings: %w", err)
+		{
+			scanCtx, cancel := withTimeoutCtx()
+			defer cancel()
+			err := w.withTransportV2(scanCtx, hostKey, hostIP, func(t *rhpv2.Transport) error {
+				var err error
+				if settings, err = RPCSettings(scanCtx, t); err != nil {
+					return fmt.Errorf("failed to fetch host settings: %w", err)
+				}
+				// NOTE: we overwrite the NetAddress with the host address here
+				// since we just used it to dial the host we know it's valid
+				settings.NetAddress = hostIP
+				return nil
+			})
+			if err != nil {
+				return settings, rhpv3.HostPriceTable{}, time.Since(start), err
 			}
-			// NOTE: we overwrite the NetAddress with the host address here
-			// since we just used it to dial the host we know it's valid
-			settings.NetAddress = hostIP
-			return nil
-		})
-		elapsed := time.Since(start)
-		if err != nil {
-			return settings, rhpv3.HostPriceTable{}, elapsed, err
 		}
 
 		// fetch the host pricetable
 		var pt rhpv3.HostPriceTable
-		err = w.transportPoolV3.withTransportV3(scanCtx, hostKey, settings.SiamuxAddr(), func(ctx context.Context, t *transportV3) error {
-			if hpt, err := RPCPriceTable(ctx, t, func(pt rhpv3.HostPriceTable) (rhpv3.PaymentMethod, error) { return nil, nil }); err != nil {
-				return fmt.Errorf("failed to fetch host price table: %w", err)
-			} else {
-				pt = hpt.HostPriceTable
-				return nil
+		{
+			scanCtx, cancel := withTimeoutCtx()
+			defer cancel()
+			err := w.transportPoolV3.withTransportV3(scanCtx, hostKey, settings.SiamuxAddr(), func(ctx context.Context, t *transportV3) error {
+				if hpt, err := RPCPriceTable(ctx, t, func(pt rhpv3.HostPriceTable) (rhpv3.PaymentMethod, error) { return nil, nil }); err != nil {
+					return fmt.Errorf("failed to fetch host price table: %w", err)
+				} else {
+					pt = hpt.HostPriceTable
+					return nil
+				}
+			})
+			if err != nil {
+				return settings, rhpv3.HostPriceTable{}, time.Since(start), err
 			}
-		})
-		return settings, pt, elapsed, err
+		}
+		return settings, pt, time.Since(start), nil
 	}
 
 	// scan: first try
 	settings, pt, duration, err := scan()
 	if err != nil {
+		logger = logger.With(zap.Error(err))
+
 		// scan: second try
 		select {
 		case <-ctx.Done():
@@ -1502,11 +1519,11 @@ func (w *worker) scanHost(ctx context.Context, timeout time.Duration, hostKey ty
 		}
 		settings, pt, duration, err = scan()
 
-		logger = logger.With("elapsed", duration)
+		logger = logger.With("elapsed", duration).With(zap.Error(err))
 		if err == nil {
 			logger.Info("successfully scanned host on second try")
 		} else if !isErrHostUnreachable(err) {
-			logger.Infow("failed to scan host", zap.Error(err))
+			logger.Infow("failed to scan host")
 		}
 	}