Skip to content

Commit

Permalink
Improved logging when child process fails.
Browse files Browse the repository at this point in the history
  • Loading branch information
ioquatix committed Dec 22, 2024
1 parent 9999fe1 commit 5ad7b89
Show file tree
Hide file tree
Showing 9 changed files with 197 additions and 23 deletions.
30 changes: 30 additions & 0 deletions examples/exec-child/jobs
Original file line number Diff line number Diff line change
@@ -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
69 changes: 69 additions & 0 deletions examples/exec-child/readme.md
Original file line number Diff line number Diff line change
@@ -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...
```
24 changes: 24 additions & 0 deletions examples/exec-child/start
Original file line number Diff line number Diff line change
@@ -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
30 changes: 30 additions & 0 deletions examples/exec-child/web
Original file line number Diff line number Diff line change
@@ -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
16 changes: 10 additions & 6 deletions lib/async/container/controller.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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
Expand Down
9 changes: 8 additions & 1 deletion lib/async/container/generic.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
10 changes: 6 additions & 4 deletions lib/async/container/group.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand All @@ -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

Expand All @@ -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
Expand Down Expand Up @@ -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)
Expand Down
4 changes: 2 additions & 2 deletions lib/async/container/notify/console.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
28 changes: 18 additions & 10 deletions lib/async/container/process.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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!
Expand All @@ -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
Expand Down

0 comments on commit 5ad7b89

Please sign in to comment.