Extension loading/timeout enhancments (#6122)

Author: wbreza

cli/azd/cmd/middleware/extensions.go

@@ -18,6 +18,7 @@ import (
 	"github.com/azure/azure-dev/cli/azd/pkg/extensions"
 	"github.com/azure/azure-dev/cli/azd/pkg/input"
 	"github.com/azure/azure-dev/cli/azd/pkg/ioc"
+	"github.com/azure/azure-dev/cli/azd/pkg/output"
 	"github.com/fatih/color"
 )
 
@@ -100,6 +101,8 @@ func (m *ExtensionsMiddleware) Run(ctx context.Context, next NextFn) (*actions.A
 
 	forceColor := !color.NoColor
 	var wg sync.WaitGroup
+	var mu sync.Mutex
+	var failedExtensions []*extensions.Extension
 
 	// Track total time for all extensions to become ready
 	allExtensionsStartTime := time.Now()
@@ -145,13 +148,19 @@ func (m *ExtensionsMiddleware) Run(ctx context.Context, next NextFn) (*actions.A
 
 			// Wait for the extension to signal readiness or failure.
 			// If AZD_EXT_DEBUG is set to a truthy value, wait indefinitely for debugger attachment
+			// If AZD_EXT_TIMEOUT is set to a number (seconds), use that as the timeout (default: 5 seconds)
 			readyCtx, cancel := getReadyContext(ctx)
 			defer cancel()
 
 			startTime := time.Now()
 			if err := ext.WaitUntilReady(readyCtx); err != nil {
 				elapsed := time.Since(startTime)
 				log.Printf("'%s' extension failed to become ready after %v: %v\n", ext.Id, elapsed, err)
+
+				// Track failed extensions for warning display
+				mu.Lock()
+				failedExtensions = append(failedExtensions, ext)
+				mu.Unlock()
 			} else {
 				elapsed := time.Since(startTime)
 				log.Printf("'%s' extension became ready in %v\n", ext.Id, elapsed)
@@ -162,6 +171,22 @@ func (m *ExtensionsMiddleware) Run(ctx context.Context, next NextFn) (*actions.A
 	// Wait for all extensions to reach a terminal state (ready or failed)
 	wg.Wait()
 
+	// Check for failed extensions and display warnings
+
+	if len(failedExtensions) > 0 {
+		m.console.Message(ctx, output.WithWarningFormat("WARNING: Extension startup failures detected"))
+		m.console.Message(ctx, "The following extensions failed to initialize within the timeout period:")
+		for _, ext := range failedExtensions {
+			m.console.Message(ctx, fmt.Sprintf("  - %s (%s)", ext.DisplayName, ext.Id))
+		}
+		m.console.Message(ctx, "")
+		m.console.Message(
+			ctx,
+			"Some features may be unavailable. Increase timeout with AZD_EXT_TIMEOUT=<seconds> if needed.",
+		)
+		m.console.Message(ctx, "")
+	}
+
 	// Log total time for all extensions to complete startup
 	totalElapsed := time.Since(allExtensionsStartTime)
 	log.Printf("All %d extensions completed startup in %v\n", len(extensionList), totalElapsed)
@@ -185,5 +210,14 @@ func getReadyContext(ctx context.Context) (context.Context, context.CancelFunc)
 	if isDebug() {
 		return context.WithCancel(ctx)
 	}
-	return context.WithTimeout(ctx, 5*time.Second)
+
+	// Use custom timeout from environment variable or default to 5 seconds
+	timeout := 5 * time.Second
+	if timeoutValue := os.Getenv("AZD_EXT_TIMEOUT"); timeoutValue != "" {
+		if seconds, err := strconv.Atoi(timeoutValue); err == nil && seconds > 0 {
+			timeout = time.Duration(seconds) * time.Second
+		}
+	}
+
+	return context.WithTimeout(ctx, timeout)
 }

cli/azd/go.work.sum

@@ -1,4 +1,5 @@
 cel.dev/expr v0.24.0/go.mod h1:hLPLo1W4QUmuYdA72RBX06QTs6MXw941piREPl3Yfiw=
+github.com/Azure/azure-sdk-for-go/sdk/azidentity v1.13.1/go.mod h1:IYus9qsFobWIc2YVwe/WPjcnyCkPKtnHAqUYeebc8z0=
 github.com/Azure/go-ansiterm v0.0.0-20230124172434-306776ec8161/go.mod h1:xomTg63KZ2rFqZQzSB4Vz2SUXa1BpHTVz9L5PTmPC4E=
 github.com/Code-Hex/go-generics-cache v1.3.1/go.mod h1:qxcC9kRVrct9rHeiYpFWSoW1vxyillCVzX13KZG8dl4=
 github.com/GoogleCloudPlatform/opentelemetry-operations-go/detectors/gcp v1.29.0/go.mod h1:Cz6ft6Dkn3Et6l2v2a9/RpN7epQ1GtDlO6lj8bEcOvw=

cli/azd/internal/grpcserver/event_service.go

@@ -7,7 +7,6 @@ import (
 	"context"
 	"errors"
 	"fmt"
-	"log"
 
 	"github.com/azure/azure-dev/cli/azd/internal/mapper"
 	"github.com/azure/azure-dev/cli/azd/pkg/azdext"
@@ -79,7 +78,7 @@ func (s *eventService) EventStream(stream grpc.BidiStreamingServer[azdext.EventM
 
 	// Create message broker with EventMessageEnvelope
 	envelope := azdext.NewEventMessageEnvelope()
-	broker := grpcbroker.NewMessageBroker(stream, envelope)
+	broker := grpcbroker.NewMessageBroker(stream, envelope, extension.Id)
 
 	// Register handlers for incoming subscription requests (no response needed)
 	broker.On(func(ctx context.Context, msg *azdext.SubscribeProjectEvent) (*azdext.EventMessage, error) {
@@ -92,11 +91,9 @@ func (s *eventService) EventStream(stream grpc.BidiStreamingServer[azdext.EventM
 
 	// Run the broker's dispatcher (blocking)
 	if err := broker.Run(ctx); err != nil && !errors.Is(err, context.Canceled) {
-		log.Printf("Broker error in EventStream: %v", err)
 		return fmt.Errorf("broker error: %w", err)
 	}
 
-	log.Println("EventStream completed")
 	return nil
 }
 

cli/azd/internal/grpcserver/framework_service.go

@@ -66,7 +66,7 @@ func (s *FrameworkService) Stream(stream azdext.FrameworkService_StreamServer) e
 
 	// Create message broker for this stream
 	ops := azdext.NewFrameworkServiceEnvelope()
-	broker := grpcbroker.NewMessageBroker(stream, ops)
+	broker := grpcbroker.NewMessageBroker(stream, ops, extension.Id)
 
 	// Track the language for cleanup when stream closes
 	var registeredLanguage string
@@ -86,12 +86,9 @@ func (s *FrameworkService) Stream(stream azdext.FrameworkService_StreamServer) e
 	// Run the broker dispatcher (blocking)
 	// This will return when the stream closes or encounters an error
 	if err := broker.Run(ctx); err != nil && !errors.Is(err, context.Canceled) {
-		log.Printf("Broker error for framework service %s: %v", registeredLanguage, err)
 		return fmt.Errorf("broker error: %w", err)
 	}
 
-	log.Printf("Stream closed for framework service: %s", registeredLanguage)
-
 	s.providerMapMu.Lock()
 	delete(s.providerMap, registeredLanguage)
 	s.providerMapMu.Unlock()

cli/azd/internal/grpcserver/server.go

@@ -119,7 +119,7 @@ func (s *Server) Start() (*ServerInfo, error) {
 		}
 	}()
 
-	log.Printf("AZD Server listening on port %d", randomPort)
+	log.Printf("AZD gRPC Server listening on port %d", randomPort)
 
 	return &ServerInfo{
 		Address:    fmt.Sprintf("localhost:%d", randomPort),
@@ -134,7 +134,7 @@ func (s *Server) Stop() error {
 	}
 
 	s.grpcServer.Stop()
-	log.Println("AZD Server stopped")
+	log.Println("AZD gRPC Server stopped")
 
 	return nil
 }

cli/azd/internal/grpcserver/service_target_service.go

@@ -70,7 +70,7 @@ func (s *ServiceTargetService) Stream(stream azdext.ServiceTargetService_StreamS
 
 	// Create message broker for this stream
 	ops := azdext.NewServiceTargetEnvelope()
-	broker := grpcbroker.NewMessageBroker(stream, ops)
+	broker := grpcbroker.NewMessageBroker(stream, ops, extension.Id)
 
 	// Track the hostType for cleanup when stream closes
 	var registeredHostType string
@@ -94,8 +94,6 @@ func (s *ServiceTargetService) Stream(stream azdext.ServiceTargetService_StreamS
 		return fmt.Errorf("broker error: %w", err)
 	}
 
-	log.Printf("Stream closed for provider: %s", registeredHostType)
-
 	s.providerMapMu.Lock()
 	delete(s.providerMap, registeredHostType)
 	s.providerMapMu.Unlock()

cli/azd/main.go

@@ -46,12 +46,14 @@ func main() {
 
 	log.SetFlags(log.LstdFlags | log.Lshortfile)
 
-	if isDebugEnabled() {
+	debugEnabled := isDebugEnabled()
+	logFileCleanup := setupLogging(debugEnabled)
+	defer logFileCleanup()
+
+	if debugEnabled {
 		azcorelog.SetListener(func(event azcorelog.Event, msg string) {
 			log.Printf("%s: %s\n", event, msg)
 		})
-	} else {
-		log.SetOutput(io.Discard)
 	}
 
 	log.Printf("azd version: %s", internal.Version)
@@ -366,6 +368,69 @@ func readToEndAndClose(r io.ReadCloser) (string, error) {
 	return buf.String(), err
 }
 
+// setupLogging configures log output based on AZD_DEBUG_LOG environment variable
+// Returns a cleanup function that should be called when the program exits
+func setupLogging(debugEnabled bool) func() {
+	debugLogValue := os.Getenv("AZD_DEBUG_LOG")
+
+	var logOutput io.Writer = io.Discard
+	var cleanupFunc func() = func() {}
+
+	// Check if debug logging is enabled and valid
+	if debugLogValue != "" {
+		if isDebugLogEnabled, err := strconv.ParseBool(debugLogValue); err == nil && isDebugLogEnabled {
+			// Create daily log files adjacent to azd binary
+			if logFile, err := createDailyLogFile(); err == nil {
+				if debugEnabled {
+					// When --debug is used, write to both stderr and log file
+					logOutput = io.MultiWriter(os.Stderr, logFile)
+				} else {
+					// When only AZD_DEBUG_LOG is set, write only to log file
+					logOutput = logFile
+				}
+
+				// Set cleanup function to close the log file
+				cleanupFunc = func() {
+					logFile.Close()
+				}
+			}
+		}
+	}
+
+	// If debug is enabled but no log file was created, use stderr
+	if debugEnabled && logOutput == io.Discard {
+		logOutput = os.Stderr
+	}
+
+	log.SetOutput(logOutput)
+	return cleanupFunc
+}
+
+// createDailyLogFile creates a daily log file adjacent to the azd binary
+func createDailyLogFile() (*os.File, error) {
+	// Get the path to the current executable
+	execPath, err := os.Executable()
+	if err != nil {
+		return nil, fmt.Errorf("failed to get current executable path: %w", err)
+	}
+
+	// Get the directory containing the executable
+	execDir := filepath.Dir(execPath)
+
+	// Create log filename with current date
+	currentDate := time.Now().Format("2006-01-02")
+	logFileName := fmt.Sprintf("azd-%s.log", currentDate)
+	logFilePath := filepath.Join(execDir, logFileName)
+
+	// Open or create the log file (append mode)
+	logFile, err := os.OpenFile(logFilePath, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0644)
+	if err != nil {
+		return nil, fmt.Errorf("failed to create/open log file %s: %w", logFilePath, err)
+	}
+
+	return logFile, nil
+}
+
 func startBackgroundUploadProcess() error {
 	// The background upload process executable is ourself
 	execPath, err := os.Executable()

cli/azd/pkg/azdext/debugger.go

@@ -17,7 +17,7 @@ import (
 
 // waitForDebugger checks if AZD_EXT_DEBUG environment variable is set to a truthy value.
 // If set, prompts the user to attach a debugger to the current process.
-func waitForDebugger(ctx context.Context, azdClient *AzdClient) {
+func waitForDebugger(ctx context.Context, extensionId string, azdClient *AzdClient) {
 	debugValue := os.Getenv("AZD_EXT_DEBUG")
 	if debugValue == "" {
 		return
@@ -28,7 +28,6 @@ func waitForDebugger(ctx context.Context, azdClient *AzdClient) {
 		return
 	}
 
-	extensionId := getExtensionId(ctx)
 	message := fmt.Sprintf("Extension '%s' ready to debug (pid: %d).", extensionId, os.Getpid())
 
 	_, err = azdClient.Prompt().Confirm(ctx, &ConfirmRequest{