chore: add debug log (#709)

Author: fatelei

internal/core/local_runtime/instance.go

@@ -12,6 +12,7 @@ import (
 	"github.com/google/uuid"
 	"github.com/langgenius/dify-plugin-daemon/internal/types/app"
 	"github.com/langgenius/dify-plugin-daemon/pkg/entities/plugin_entities"
+	"github.com/langgenius/dify-plugin-daemon/pkg/utils/log"
 )
 
 const (
@@ -124,6 +125,15 @@ func (s *PluginInstance) Stop() {
 // Once the subprocess exists itself, STDOUT always close, which results in `CLOSE STDOUT`
 func (s *PluginInstance) StartStdout() {
 	defer func() {
+		log.Info(
+			"plugin stdout reader exiting",
+			"plugin", s.pluginUniqueIdentifier,
+			"instance", s.ID()[:8],
+			"started", s.started,
+			"shutdown", s.shutdown,
+			"last_active_at", s.lastActiveAt,
+			"instance_error", s.Error(),
+		)
 		// notify shutdown signal
 		s.WalkNotifiers(func(notifier PluginInstanceNotifier) {
 			notifier.OnInstanceShutdown(s)
@@ -167,6 +177,15 @@ func (s *PluginInstance) StartStdout() {
 				),
 			)
 		})
+	} else {
+		log.Warn(
+			"plugin stdout reader reached eof",
+			"plugin", s.pluginUniqueIdentifier,
+			"instance", s.ID()[:8],
+			"started", s.started,
+			"shutdown", s.shutdown,
+			"last_active_at", s.lastActiveAt,
+		)
 	}
 
 	// once reader of stdout is closed, kill subprocess
@@ -176,13 +195,37 @@ func (s *PluginInstance) StartStdout() {
 		s.WalkNotifiers(func(notifier PluginInstanceNotifier) {
 			notifier.OnInstanceErrorLog(s, fmt.Errorf("failed to kill subprocess: %s", err.Error()))
 		})
+		log.Warn(
+			"plugin subprocess kill returned",
+			"plugin", s.pluginUniqueIdentifier,
+			"instance", s.ID()[:8],
+			"error", err,
+		)
+	} else {
+		log.Warn(
+			"plugin subprocess killed after stdout closed",
+			"plugin", s.pluginUniqueIdentifier,
+			"instance", s.ID()[:8],
+		)
 	}
 
 	// collect subprocess, avoid zombie processes
 	if _, err := s.cmd.Process.Wait(); err != nil {
 		s.WalkNotifiers(func(notifier PluginInstanceNotifier) {
 			notifier.OnInstanceErrorLog(s, fmt.Errorf("failed to reap subprocess: %s", err.Error()))
 		})
+		log.Warn(
+			"plugin subprocess wait returned error",
+			"plugin", s.pluginUniqueIdentifier,
+			"instance", s.ID()[:8],
+			"error", err,
+		)
+	} else {
+		log.Info(
+			"plugin subprocess reaped",
+			"plugin", s.pluginUniqueIdentifier,
+			"instance", s.ID()[:8],
+		)
 	}
 }
 
@@ -282,6 +325,13 @@ func (s *PluginInstance) Monitor() error {
 
 		// check heartbeat
 		if time.Since(s.lastActiveAt) > MAX_HEARTBEAT_INTERVAL {
+			log.Warn(
+				"plugin instance marked inactive",
+				"plugin", s.pluginUniqueIdentifier,
+				"instance", s.ID()[:8],
+				"inactive_seconds", time.Since(s.lastActiveAt).Seconds(),
+				"instance_error", s.Error(),
+			)
 			s.WalkNotifiers(func(notifier PluginInstanceNotifier) {
 				// notify handlers
 				notifier.OnInstanceLaunchFailed(

internal/core/local_runtime/subprocess.go

@@ -12,6 +12,7 @@ import (
 	"github.com/langgenius/dify-plugin-daemon/pkg/entities/constants"
 	"github.com/langgenius/dify-plugin-daemon/pkg/entities/plugin_entities"
 	routinepkg "github.com/langgenius/dify-plugin-daemon/pkg/routine"
+	"github.com/langgenius/dify-plugin-daemon/pkg/utils/log"
 	"github.com/langgenius/dify-plugin-daemon/pkg/utils/routine"
 )
 
@@ -124,26 +125,49 @@ func (r *LocalPluginRuntime) startNewInstance() error {
 	instance.AddNotifier(&PluginInstanceNotifierTemplate{
 		// the first heartbeat will trigger this
 		OnInstanceReadyImpl: func(pi *PluginInstance) {
-			// notify plugin started
-			r.WalkNotifiers(func(notifier PluginRuntimeNotifier) {
-				notifier.OnInstanceReady(instance)
-			})
 			// mark the instance as started
 			instance.started = true
 			// setup instance
 			r.instanceLocker.Lock()
+			before := len(r.instances)
 			r.instances = append(r.instances, instance)
+			after := len(r.instances)
 			r.instanceLocker.Unlock()
+			log.Info(
+				"local runtime instance ready",
+				"plugin", r.Config.Identity(),
+				"instance", instance.ID()[:8],
+				"pid", e.Process.Pid,
+				"instances_before", before,
+				"instances_after", after,
+			)
+			// notify plugin started
+			r.WalkNotifiers(func(notifier PluginRuntimeNotifier) {
+				notifier.OnInstanceReady(instance)
+			})
 
 			close(launchChannel)
 		},
 		OnInstanceShutdownImpl: func(pi *PluginInstance) {
 			// remove the instance from the list
 			r.instanceLocker.Lock()
+			before := len(r.instances)
 			r.instances = slices.DeleteFunc(r.instances, func(instance *PluginInstance) bool {
 				return instance.instanceId == pi.instanceId
 			})
+			after := len(r.instances)
 			r.instanceLocker.Unlock()
+			log.Warn(
+				"local runtime instance shutdown",
+				"plugin", r.Config.Identity(),
+				"instance", pi.ID()[:8],
+				"pid", e.Process.Pid,
+				"started", pi.started,
+				"shutdown", pi.shutdown,
+				"instances_before", before,
+				"instances_after", after,
+				"instance_error", pi.Error(),
+			)
 
 			if !instance.started {
 				// if the instance is not started, it means the plugin is not ready