DEBUG

Signed-off-by: Stéphane Graber <[email protected]>

client/operations.go

@@ -11,6 +11,7 @@ import (
 	"github.com/gorilla/websocket"
 
 	"github.com/lxc/incus/shared/api"
+	"github.com/lxc/incus/shared/logger"
 )
 
 // The Operation type represents an ongoing Incus operation (asynchronous processing).
@@ -120,28 +121,35 @@ func (op *operation) Wait() error {
 
 // WaitContext lets you wait until the operation reaches a final state with context.Context.
 func (op *operation) WaitContext(ctx context.Context) error {
+	logger.Errorf("stgraber: wait1")
 	if op.skipListener {
+		logger.Errorf("stgraber: wait2")
 		timeout := -1
 		deadline, ok := ctx.Deadline()
 		if ok {
 			timeout = int(time.Until(deadline).Seconds())
 		}
+		logger.Errorf("stgraber: wait3")
 
 		opAPI, _, err := op.r.GetOperationWait(op.ID, timeout)
 		if err != nil {
 			return err
 		}
+		logger.Errorf("stgraber: wait4")
 
 		op.Operation = *opAPI
 
 		if opAPI.Err != "" {
 			return errors.New(opAPI.Err)
 		}
 
+		logger.Errorf("stgraber: wait5")
 		return nil
 	}
 
+	logger.Errorf("stgraber: wait6")
 	op.handlerLock.Lock()
+	logger.Errorf("stgraber: wait7")
 	// Check if not done already
 	if op.StatusCode.IsFinal() {
 		if op.Err != "" {
@@ -150,28 +158,34 @@ func (op *operation) WaitContext(ctx context.Context) error {
 		}
 
 		op.handlerLock.Unlock()
+		logger.Errorf("stgraber: wait8")
 		return nil
 	}
 
+	logger.Errorf("stgraber: wait9")
 	op.handlerLock.Unlock()
+	logger.Errorf("stgraber: wait10")
 
 	// Make sure we have a listener setup
 	err := op.setupListener()
 	if err != nil {
 		return err
 	}
+	logger.Errorf("stgraber: wait11: %s", op.ID)
 
 	select {
 	case <-ctx.Done():
 		return ctx.Err()
 	case <-op.chActive:
 	}
+	logger.Errorf("stgraber: wait12")
 
 	// We're done, parse the result
 	if op.Err != "" {
 		return errors.New(op.Err)
 	}
 
+	logger.Errorf("stgraber: wait13")
 	return nil
 }
 
@@ -200,27 +214,33 @@ func (op *operation) setupListener() error {
 		if err != nil {
 			return err
 		}
+		logger.Errorf("stgraber: op: connected")
 
 		op.listener = listener
 	}
 
 	// Setup the handler
 	chReady := make(chan bool)
 	_, err := op.listener.AddHandler([]string{"operation"}, func(event api.Event) {
+		logger.Errorf("stgraber: op: got event")
 		<-chReady
 
 		// We don't want concurrency while processing events
+		logger.Errorf("stgraber: op: waiting for lock")
 		op.handlerLock.Lock()
+		logger.Errorf("stgraber: op: lock acquired")
 		defer op.handlerLock.Unlock()
 
 		// Check if we're done already (because of another event)
 		if op.listener == nil {
+			logger.Errorf("stgraber: op: listener gone")
 			return
 		}
 
 		// Get an operation struct out of this data
 		newOp := api.Operation{}
 		err := json.Unmarshal(event.Metadata, &newOp)
+		logger.Errorf("stgraber: op: event: %+v", newOp)
 		if err != nil || newOp.ID != op.ID {
 			return
 		}
@@ -277,6 +297,7 @@ func (op *operation) setupListener() error {
 	}()
 
 	// And do a manual refresh to avoid races
+	logger.Errorf("stgraber: op: refresh")
 	err = op.Refresh()
 	if err != nil {
 		op.listener.Disconnect()
@@ -288,6 +309,7 @@ func (op *operation) setupListener() error {
 	}
 
 	// Check if not done already
+	logger.Errorf("stgraber: op: check final")
 	if op.StatusCode.IsFinal() {
 		op.listener.Disconnect()
 		op.listener = nil

cmd/incusd/api_internal.go

@@ -219,6 +219,7 @@ func internalRefreshImage(d *Daemon, r *http.Request) response.Response {
 
 	err := autoUpdateImages(s.ShutdownCtx, s)
 	if err != nil {
+		logger.Errorf("refresh-image: %v", err)
 		return response.SmartError(err)
 	}