Skip to content

Commit

Permalink
Fixes/improvements to buffer flushing
Browse files Browse the repository at this point in the history
  • Loading branch information
trinitytakei committed Jan 6, 2025
1 parent 76a6857 commit 1df0bce
Show file tree
Hide file tree
Showing 7 changed files with 54 additions and 59 deletions.
8 changes: 6 additions & 2 deletions app/models/app_generation/log_entry.rb
Original file line number Diff line number Diff line change
Expand Up @@ -29,9 +29,13 @@ class LogEntry < ApplicationRecord

self.table_name = "app_generation_log_entries"

def rails_output?
entry_type == "rails_output"
end

after_commit -> {
Rails.logger.debug "%%%%% LogEntry Create callback: #{id}"
stream_name = "#{generated_app.to_gid}:app_generation_log_entries"

Turbo::StreamsChannel.broadcast_prepend_to(
stream_name,
target: "app_generation_log_entries",
Expand All @@ -41,8 +45,8 @@ class LogEntry < ApplicationRecord
}, on: :create

after_commit -> {
Rails.logger.debug "%%%%% LogEntry Update callback: #{id}, message length: #{message.length}"
stream_name = "#{generated_app.to_gid}:app_generation_log_entries"

Turbo::StreamsChannel.broadcast_replace_to(
stream_name,
target: "log_entry_#{id}",
Expand Down
2 changes: 2 additions & 0 deletions app/notifiers/app_status_change_notifier.rb
Original file line number Diff line number Diff line change
@@ -1,4 +1,6 @@
class AppStatusChangeNotifier < Noticed::Event
include Rails.application.routes.url_helpers

deliver_by :action_cable do |config|
config.channel = "Noticed::NotificationChannel"
config.stream = -> { recipient }
Expand Down
25 changes: 5 additions & 20 deletions app/services/command_execution_service.rb
Original file line number Diff line number Diff line change
Expand Up @@ -113,10 +113,13 @@ def run_isolated_process

env = {
"BUNDLE_GEMFILE" => nil,
"BUNDLE_PATH" => File.join(@temp_dir, "vendor/bundle"),
"BUNDLE_APP_CONFIG" => File.join(@temp_dir, ".bundle"),
"RAILS_ENV" => "development",
"NODE_ENV" => "development",
"PATH" => ENV["PATH"]
}

log_environment_variables_for_command_execution(env)

buffer = Buffer.new(@generated_app)
Expand All @@ -125,35 +128,17 @@ def run_isolated_process
@pid = wait_thr&.pid
@logger.info("Rails app generation process started", { pid: @pid })

# Auto-accept all prompts
stdin_thread = Thread.new do
loop do
stdin.puts "Y"
sleep 0.1
end
rescue IOError
# Stream closed
end

stdout_thread = Thread.new do
stdout.each_line do |line|
buffer.append(line.strip)
end
end

stderr_thread = Thread.new do
stderr.each_line do |line|
buffer.append(line.strip)
end
end

[stdout_thread, stderr_thread].each(&:join)
stdin_thread.kill # Clean up stdin thread
stdout_thread.join

buffer.complete!

exit_status = wait_thr&.value
output = buffer.join("\n").presence || "No output"
output = buffer.message || "No output"

if exit_status&.success?
@logger.info("Rails app generation process finished successfully", {
Expand Down
42 changes: 25 additions & 17 deletions app/services/command_execution_service/buffer.rb
Original file line number Diff line number Diff line change
Expand Up @@ -9,47 +9,54 @@ def initialize(generated_app)
@log_entry = create_initial_log_entry
@last_flush = Time.current
@completed = false
Rails.logger.debug "%%%%% Buffer initialized with log entry #{@log_entry.id}"
end

def append(message)
should_flush = false

synchronize do
@output << message.gsub("\n", "<br>")
Rails.logger.debug "%%%%% Buffer append: Adding message of length #{message.length}"
@output << message
should_flush = should_flush?
end

flush if should_flush
end

def complete!
Rails.logger.debug "%%%%% Buffer complete! called"
@completed = true
flush
end

def flush
message = nil

synchronize do
message = @output.join("\n")
message = "No output" if message.blank?
end
return if @output.empty?

if @completed
@log_entry.update!(message: message, entry_type: nil)
else
@log_entry.update!(message: message)
end
Rails.logger.debug "%%%%% Buffer flush: Current entry: #{@log_entry&.id}, buffer size: #{@output.length}"

synchronize do
if @log_entry.nil?
@log_entry = create_initial_log_entry
Rails.logger.debug "%%%%% Created new log entry: #{@log_entry.id}"
end

new_content = @output.join("\n")
message = @log_entry.message.present? ? "#{@log_entry.message}\n#{new_content}" : new_content
Rails.logger.debug "%%%%% Updating log entry #{@log_entry.id} with message length: #{message.length}"

@log_entry.update!(
message: message,
phase: @generated_app.status
)

@output.clear
@last_flush = Time.current
end
end

def join(separator = "\n")
synchronize do
@output.join(separator)
end
def message
@log_entry&.message
end

private
Expand All @@ -70,7 +77,8 @@ def synchronize(&block)
end

def should_flush?
Time.current - @last_flush >= FLUSH_INTERVAL
# Flush if enough time has passed OR if buffer is getting large
Time.current - @last_flush >= FLUSH_INTERVAL || @output.length >= 20
end
end
end
4 changes: 2 additions & 2 deletions app/views/app_generation/log_entries/_log_entry.html.erb
Original file line number Diff line number Diff line change
@@ -1,9 +1,9 @@
<%= turbo_frame_tag "log_entry_#{log_entry.id}" do %>
<div class="log-entry <%= log_entry.level %>"
<div id="log_entry_<%= log_entry.id %>" class="log-entry <%= log_entry.level %>"
data-timestamp="<%= log_entry.created_at.to_i %>"
data-entry-type="<%= log_entry.entry_type %>"
data-rails-output="<%= rails_output?(log_entry) %>">
<div class="p-4 <%= rails_output?(log_entry) ? "bg-black text-green-400" : log_level_color(log_entry.level) %>">
<div id="log_entry_content_<%= log_entry.id %>" class="p-4 <%= rails_output?(log_entry) ? "bg-black text-green-400" : log_level_color(log_entry.level) %>">
<div class="flex justify-between items-start">
<div class="flex-1">
<div class="text-sm font-medium message-content">
Expand Down
8 changes: 7 additions & 1 deletion test/services/command_execution_service/buffer_test.rb
Original file line number Diff line number Diff line change
Expand Up @@ -31,7 +31,13 @@ def setup
@buffer.flush

log_entry = AppGeneration::LogEntry.last
assert_equal "First message\nSecond message", log_entry.message
expected_message = [
"Initializing Rails application generation...",
"First message",
"Second message"
].join("\n")

assert_equal expected_message, log_entry.message
assert_equal "rails_output", log_entry.entry_type
end
end
Expand Down
24 changes: 7 additions & 17 deletions test/services/command_execution_service_test.rb
Original file line number Diff line number Diff line change
Expand Up @@ -36,9 +36,7 @@ def teardown
error = "Sample error"

@valid_commands.each do |command|
# Store the current count to only delete new entries
initial_count = @generated_app.log_entries.count

service = CommandExecutionService.new(@generated_app, command)

Open3.stub :popen3, mock_popen3(output, error, success: true) do
Expand All @@ -55,21 +53,17 @@ def teardown
"Preparing to execute command",
"System environment details",
"Environment variables for command execution",
"Sample output"
"Initializing Rails application generation...\nSample output"
]

expected_messages.each_with_index do |message, index|
assert_equal message, log_entries[index].message, "Log entry #{index} doesn't match for command: #{command}"
end

# Verify the final buffer content
buffer_entry = log_entries.find { |entry| entry.metadata["stream"] == "stdout" }
assert_equal "Sample output", buffer_entry.message

# Verify specific log levels
assert_equal "Initializing Rails application generation...\nSample output", buffer_entry.message
assert log_entries.all?(&:info?)

# Clean up only the entries from this iteration
@generated_app.log_entries.where("id > ?", @generated_app.log_entries.limit(initial_count).pluck(:id).last).destroy_all
end
end
Expand Down Expand Up @@ -166,15 +160,14 @@ def teardown

assert_equal "Rails app generation process finished successfully", log_entries[0].message
assert_equal "Rails app generation process started", log_entries[1].message
assert_equal "Sample output", log_entries[2].message
assert_equal "Initializing Rails application generation...\nSample output", log_entries[2].message
assert_equal "Environment variables for command execution", log_entries[3].message
assert_equal "System environment details", log_entries[4].message
assert_equal "Preparing to execute command", log_entries[5].message
assert_equal "Created temporary directory", log_entries[6].message

# Fix: Look for the log entry with stdout stream
buffer_entry = log_entries.find { |entry| entry.metadata["stream"] == "stdout" }
assert_equal "Sample output", buffer_entry.message
assert_equal "Initializing Rails application generation...\nSample output", buffer_entry.message
end
end

Expand All @@ -189,10 +182,9 @@ def teardown

log_entries = @generated_app.log_entries.recent_first

# Verify the sequence of logs
expected_messages = [
"Command failed",
"No output", # From Buffer's default message
"Initializing Rails application generation...",
"Rails app generation process started",
"Environment variables for command execution",
"System environment details",
Expand All @@ -203,14 +195,12 @@ def teardown
]

expected_messages.each do |message|
assert log_entries.any? { |entry| entry.message.include?(message) },
"Expected to find log entry containing '#{message}'"
assert log_entries.any? { |entry| entry.message.include?(message) }
end

# Verify error details
error_log = log_entries.find { |entry| entry.message == "Command failed" }
assert error_log.error?
assert_equal "No output", error_log.metadata["output"]
assert_equal "Initializing Rails application generation...", error_log.metadata["output"]
assert error_log.metadata["status"]
end
end
Expand Down

0 comments on commit 1df0bce

Please sign in to comment.