Improved logging when child process fails.

Author: ioquatix

examples/exec-child/jobs

@@ -0,0 +1,30 @@
+#!/usr/bin/env ruby
+# frozen_string_literal: true
+
+require "console"
+require "async/container/notify"
+
+# Console.logger.debug!
+
+class Jobs
+	def self.start = self.new.start
+		
+	def start
+		Console.info(self, "Starting jobs...")
+		
+		if notify = Async::Container::Notify.open!
+			Console.info(self, "Notifying container ready...")
+			notify.ready!
+		end
+		
+		loop do
+			Console.info(self, "Jobs running...")
+			
+			sleep 10
+		end
+	rescue Interrupt
+		Console.info(self, "Exiting jobs...")
+	end
+end
+
+Jobs.start

examples/exec-child/readme.md

@@ -0,0 +1,69 @@
+# Exec Child Example
+
+This example demonstrates how to execute a child process using the `exec` function in a container.
+
+## Usage
+
+Start the main controller:
+
+```
+> bundle exec ./start
+  0.0s     info: AppController [oid=0x938] [ec=0x94c] [pid=96758] [2024-12-12 14:33:45 +1300]
+               | Controller starting...
+ 0.65s     info: Jobs [oid=0x8e8] [ec=0x8fc] [pid=96763] [2024-12-12 14:33:45 +1300]
+               | Starting jobs...
+ 0.65s     info: Jobs [oid=0x8e8] [ec=0x8fc] [pid=96763] [2024-12-12 14:33:45 +1300]
+               | Notifying container ready...
+ 0.65s     info: Jobs [oid=0x8e8] [ec=0x8fc] [pid=96763] [2024-12-12 14:33:45 +1300]
+               | Jobs running...
+ 0.65s     info: Web [oid=0x8e8] [ec=0x8fc] [pid=96760] [2024-12-12 14:33:45 +1300]
+               | Starting web...
+ 0.65s     info: Web [oid=0x8e8] [ec=0x8fc] [pid=96760] [2024-12-12 14:33:45 +1300]
+               | Notifying container ready...
+ 0.65s     info: Web [oid=0x8e8] [ec=0x8fc] [pid=96760] [2024-12-12 14:33:45 +1300]
+               | Web running...
+ 0.09s     info: AppController [oid=0x938] [ec=0x94c] [pid=96758] [2024-12-12 14:33:45 +1300]
+               | Controller started...
+```
+
+In another terminal: `kill -HUP 96758` to cause a blue-green restart, which causes a new container to be started with new jobs and web processes:
+
+```
+ 9.57s     info: Jobs [oid=0x8e8] [ec=0x8fc] [pid=96836] [2024-12-12 14:33:54 +1300]
+               | Starting jobs...
+ 9.57s     info: Web [oid=0x8e8] [ec=0x8fc] [pid=96833] [2024-12-12 14:33:54 +1300]
+               | Starting web...
+ 9.57s     info: Jobs [oid=0x8e8] [ec=0x8fc] [pid=96836] [2024-12-12 14:33:54 +1300]
+               | Notifying container ready...
+ 9.57s     info: Web [oid=0x8e8] [ec=0x8fc] [pid=96833] [2024-12-12 14:33:54 +1300]
+               | Notifying container ready...
+ 9.57s     info: Jobs [oid=0x8e8] [ec=0x8fc] [pid=96836] [2024-12-12 14:33:54 +1300]
+               | Jobs running...
+ 9.57s     info: Web [oid=0x8e8] [ec=0x8fc] [pid=96833] [2024-12-12 14:33:54 +1300]
+               | Web running...
+```
+
+Once the new container is running and the child processes have notified they are ready, the controller will stop the old container:
+
+```
+ 9.01s     info: Async::Container::Group [oid=0xa00] [ec=0x94c] [pid=96758] [2024-12-12 14:33:54 +1300]
+               | Stopping all processes...
+               | {
+               |   "timeout": true
+               | }
+ 9.01s     info: Async::Container::Group [oid=0xa00] [ec=0x94c] [pid=96758] [2024-12-12 14:33:54 +1300]
+               | Sending interrupt to 2 running processes...
+ 9.57s     info: Web [oid=0x8e8] [ec=0x8fc] [pid=96760] [2024-12-12 14:33:54 +1300]
+               | Exiting web...
+ 9.57s     info: Jobs [oid=0x8e8] [ec=0x8fc] [pid=96763] [2024-12-12 14:33:54 +1300]
+               | Exiting jobs...
+```
+
+The new container continues to run as expected:
+
+```
+19.57s     info: Web [oid=0x8e8] [ec=0x8fc] [pid=96833] [2024-12-12 14:34:04 +1300]
+               | Web running...
+19.57s     info: Jobs [oid=0x8e8] [ec=0x8fc] [pid=96836] [2024-12-12 14:34:04 +1300]
+               | Jobs running...
+```

examples/exec-child/start

@@ -0,0 +1,24 @@
+#!/usr/bin/env ruby
+# frozen_string_literal: true
+
+require "async/container"
+require "console"
+
+# Console.logger.debug!
+
+class AppController < Async::Container::Controller
+	def setup(container)
+		container.spawn(name: "Web") do |instance|
+			# Specify ready: false here as the child process is expected to take care of the readiness notification:
+			instance.exec("bundle", "exec", "web", ready: false)
+		end
+		
+		container.spawn(name: "Jobs") do |instance|
+			instance.exec("bundle", "exec", "jobs", ready: false)
+		end
+	end
+end
+
+controller = AppController.new
+
+controller.run

examples/exec-child/web

@@ -0,0 +1,30 @@
+#!/usr/bin/env ruby
+# frozen_string_literal: true
+
+require "console"
+require "async/container/notify"
+
+# Console.logger.debug!
+
+class Web
+	def self.start = self.new.start
+	
+	def start
+		Console.info(self, "Starting web...")
+		
+		if notify = Async::Container::Notify.open!
+			Console.info(self, "Notifying container ready...")
+			notify.ready!
+		end
+		
+		loop do
+			Console.info(self, "Web running...")
+			
+			sleep 10
+		end
+	rescue Interrupt
+		Console.info(self, "Exiting web...")
+	end
+end
+
+Web.start

lib/async/container/controller.rb

@@ -26,13 +26,10 @@ def initialize(notify: Notify.open!, container_class: Container, graceful_stop:
 				@container = nil
 				@container_class = container_class
 
-				if @notify = notify
-					@notify.status!("Initializing...")
-				end
-				
+				@notify = notify
 				@signals = {}
 
-				trap(SIGHUP) do
+				self.trap(SIGHUP) do
 					self.restart
 				end
 
@@ -93,7 +90,12 @@ def setup(container)
 
 			# Start the container unless it's already running.
 			def start
-				self.restart unless @container
+				unless @container
+					Console.info(self) {"Controller starting..."}
+					self.restart
+				end
+				
+				Console.info(self) {"Controller started..."}
 			end
 
 			# Stop the container if it's running.
@@ -183,6 +185,8 @@ def reload
 
 			# Enter the controller run loop, trapping `SIGINT` and `SIGTERM`.
 			def run
+				@notify&.status!("Initializing...")
+				
 				# I thought this was the default... but it doesn't always raise an exception unless you do this explicitly.
 				# We use `Thread.current.raise(...)` so that exceptions are filtered through `Thread.handle_interrupt` correctly.
 				interrupt_action = Signal.trap(:INT) do

lib/async/container/generic.rb

@@ -107,13 +107,20 @@ def wait_until_ready
 					Console.debug(self) do |buffer|
 						buffer.puts "Waiting for ready:"
 						@state.each do |child, state|
-							buffer.puts "\t#{child.class}: #{state.inspect}"
+							buffer.puts "\t#{child.inspect}: #{state}"
 						end
 					end
 
 					self.sleep
 
 					if self.status?(:ready)
+						Console.logger.debug(self) do |buffer|
+							buffer.puts "All ready:"
+							@state.each do |child, state|
+								buffer.puts "\t#{child.inspect}: #{state}"
+							end
+						end
+						
 						return true
 					end
 				end

lib/async/container/group.rb

@@ -65,7 +65,7 @@ def wait
 			# Interrupt all running processes.
 			# This resumes the controlling fiber with an instance of {Interrupt}.
 			def interrupt
-				Console.debug(self, "Sending interrupt to #{@running.size} running processes...")
+				Console.info(self, "Sending interrupt to #{@running.size} running processes...")
 				@running.each_value do |fiber|
 					fiber.resume(Interrupt)
 				end
@@ -74,7 +74,7 @@ def interrupt
 			# Terminate all running processes.
 			# This resumes the controlling fiber with an instance of {Terminate}.
 			def terminate
-				Console.debug(self, "Sending terminate to #{@running.size} running processes...")
+				Console.info(self, "Sending terminate to #{@running.size} running processes...")
 				@running.each_value do |fiber|
 					fiber.resume(Terminate)
 				end
@@ -83,6 +83,7 @@ def terminate
 			# Stop all child processes using {#terminate}.
 			# @parameter timeout [Boolean | Numeric | Nil] If specified, invoke a graceful shutdown using {#interrupt} first.
 			def stop(timeout = 1)
+				Console.info(self, "Stopping all processes...", timeout: timeout)
 				# Use a default timeout if not specified:
 				timeout = 1 if timeout == true
 
@@ -105,7 +106,7 @@ def stop(timeout = 1)
 				end
 
 				# Terminate all children:
-				self.terminate
+				self.terminate if any?
 
 				# Wait for all children to exit:
 				self.wait
@@ -137,7 +138,8 @@ def wait_for(channel)
 			protected
 
 			def wait_for_children(duration = nil)
-				Console.debug(self, "Waiting for children...", duration: duration)
+				Console.debug(self, "Waiting for children...", duration: duration, running: @running)
+				
 				if !@running.empty?
 					# Maybe consider using a proper event loop here:
 					readable, _, _ = ::IO.select(@running.keys, nil, nil, duration)

lib/async/container/notify/console.rb

@@ -24,8 +24,8 @@ def initialize(logger)
 				end
 
 				# Send a message to the console.
-				def send(level: :debug, **message)
-					@logger.send(level, self) {message}
+				def send(level: :info, **message)
+					@logger.public_send(level, self) {message}
 				end
 
 				# Send an error message to the console.

lib/async/container/process.rb

@@ -122,10 +122,12 @@ def name= value
 
 			# A human readable representation of the process.
 			# @returns [String]
-			def to_s
-				"\#<#{self.class} #{@name}>"
+			def inspect
+				"\#<#{self.class} name=#{@name.inspect} status=#{@status.inspect} pid=#{@pid.inspect}>"
 			end
 
+			alias to_s inspect
+			
 			# Invoke {#terminate!} and then {#wait} for the child process to exit.
 			def close
 				self.terminate!
@@ -149,22 +151,28 @@ def terminate!
 			end
 
 			# Wait for the child process to exit.
+			# @asynchronous This method may block.
+			#
 			# @returns [::Process::Status] The process exit status.
 			def wait
 				if @pid && @status.nil?
-					_, @status = ::Process.wait2(@pid, ::Process::WNOHANG)
+					Console.debug(self, "Waiting for process to exit...", pid: @pid)
 
-					if @status.nil?
-						sleep(0.01)
+					_, @status = ::Process.wait2(@pid, ::Process::WNOHANG)
+
+					while @status.nil?
+						sleep(0.1)
+						
 						_, @status = ::Process.wait2(@pid, ::Process::WNOHANG)
-					end
-					
-					if @status.nil?
-						Console.warn(self) {"Process #{@pid} is blocking, has it exited?"}
-						_, @status = ::Process.wait2(@pid)
+						
+						if @status.nil?
+							Console.warn(self) {"Process #{@pid} is blocking, has it exited?"}
+						end
 					end
 				end
 
+				Console.debug(self, "Process exited.", pid: @pid, status: @status)
+				
 				return @status
 			end
 		end

releases.md

@@ -0,0 +1,5 @@
+# Releases
+
+## Unreleased
+
+  - Improved logging when child process fails and container startup.