Skip to content

[CI] add more logs about reserved job info #77

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
lihao-figma wants to merge 1 commit into from
Closed

[CI] add more logs about reserved job info #77

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
104 changes: 94 additions & 10 deletions ruby/lib/ci/queue/redis/worker.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -73,6 +73,12 @@ def idle?

def poll
wait_for_master
if master?
warn "Worker #{worker_id} is the master"
else
master_id = master_worker_id
warn "Worker #{worker_id} saw master worker: #{master_id}" if master_id
end
idle_since = nil
idle_state_printed = false
until shutdown_required? || config.circuit_breakers.any?(&:open?) || exhausted? || max_test_failed?
Expand Down Expand Up @@ -233,7 +239,8 @@ def reserve
end

def try_to_reserve_test
eval_script(
current_time = CI::Queue.time_now.to_f
test_id = eval_script(
:reserve,
keys: [
key('queue'),
Expand All @@ -243,11 +250,42 @@ def try_to_reserve_test
key('owners'),
key('test-group-timeout')
],
argv: [CI::Queue.time_now.to_f, 'true', config.timeout]
argv: [current_time, 'true', config.timeout]
)

if test_id
# Check what timeout was used (dynamic or default)
dynamic_timeout = redis.hget(key('test-group-timeout'), test_id)
timeout_used = dynamic_timeout ? dynamic_timeout.to_f : config.timeout
deadline = current_time + timeout_used
gap_seconds = timeout_used
gap_hours = (gap_seconds / 3600).to_i
gap_mins = ((gap_seconds % 3600) / 60).to_i
gap_secs = (gap_seconds % 60)

current_time_readable = Time.at(current_time).strftime('%Y-%m-%d %H:%M:%S')
deadline_readable = Time.at(deadline).strftime('%Y-%m-%d %H:%M:%S')

# Format gap_seconds to 2 decimal places, and gap_secs for the formatted version
gap_seconds_formatted = format('%.2f', gap_seconds)
gap_secs_formatted = gap_secs < 60 ? format('%.2f', gap_secs) : gap_secs.to_i.to_s

# Add details about how timeout was computed
timeout_details = if dynamic_timeout
test_count = (dynamic_timeout.to_f / config.timeout).round
"dynamic_timeout=#{dynamic_timeout.to_f}s (config.timeout=#{config.timeout}s * chunk.test_count=#{test_count})"
else
"default_timeout=#{config.timeout}s"
end

warn "[reserve] test=#{test_id} current_time=#{current_time_readable} (#{current_time}) deadline=#{deadline_readable} (#{deadline}) gap=#{gap_seconds_formatted}s (#{gap_hours}h#{gap_mins}m#{gap_secs_formatted}s) [#{timeout_details}]"
end

test_id
end

def try_to_reserve_lost_test
current_time = CI::Queue.time_now.to_f
lost_test = eval_script(
:reserve_lost,
keys: [
Expand All @@ -257,13 +295,41 @@ def try_to_reserve_lost_test
key('owners'),
key('test-group-timeout')
],
argv: [CI::Queue.time_now.to_f, timeout, 'true', config.timeout]
argv: [current_time, timeout, 'true', config.timeout]
)

if lost_test
# Check what timeout was used (dynamic or default)
dynamic_timeout = redis.hget(key('test-group-timeout'), lost_test)
timeout_used = dynamic_timeout ? dynamic_timeout.to_f : config.timeout
deadline = current_time + timeout_used
gap_seconds = timeout_used
gap_hours = (gap_seconds / 3600).to_i
gap_mins = ((gap_seconds % 3600) / 60).to_i
gap_secs = (gap_seconds % 60)

current_time_readable = Time.at(current_time).strftime('%Y-%m-%d %H:%M:%S')
deadline_readable = Time.at(deadline).strftime('%Y-%m-%d %H:%M:%S')

# Format gap_seconds to 2 decimal places, and gap_secs for the formatted version
gap_seconds_formatted = format('%.2f', gap_seconds)
gap_secs_formatted = gap_secs < 60 ? format('%.2f', gap_secs) : gap_secs.to_i.to_s

# Add details about how timeout was computed
timeout_details = if dynamic_timeout
test_count = (dynamic_timeout.to_f / config.timeout).round
"dynamic_timeout=#{dynamic_timeout.to_f}s (config.timeout=#{config.timeout}s * chunk.test_count=#{test_count})"
else
"default_timeout=#{config.timeout}s"
end

warn "[reserve_lost] test=#{lost_test} current_time=#{current_time_readable} (#{current_time}) deadline=#{deadline_readable} (#{deadline}) gap=#{gap_seconds_formatted}s (#{gap_hours}h#{gap_mins}m#{gap_secs_formatted}s) [#{timeout_details}]"
end

if lost_test.nil? && idle?
puts "Worker #{worker_id} could not reserve a lost test while idle"
puts 'Printing running tests:'
puts "#{redis.zrange(key('running'), 0, -1, withscores: true)}"
warn "Worker #{worker_id} could not reserve a lost test while idle"
warn 'Printing running tests:'
warn "#{redis.zrange(key('running'), 0, -1, withscores: true)}"
end

build.record_warning(Warnings::RESERVED_LOST_TEST, test: lost_test, timeout: timeout) if lost_test
Expand Down Expand Up @@ -296,10 +362,24 @@ def register
def acquire_master_role?
return true if @master

@master = redis.setnx(key('master-status'), 'setup')
rescue *CONNECTION_ERRORS
@master = nil
false
begin
@master = redis.setnx(key('master-status'), 'setup')
if @master
begin
redis.set(key('master-worker-id'), worker_id)
redis.expire(key('master-worker-id'), config.redis_ttl)
warn "Worker #{worker_id} elected as master"
rescue *CONNECTION_ERRORS
# If setting master-worker-id fails, we still have master status
# Log but don't lose master role
warn("Failed to set master-worker-id: #{$!.message}")
end
end
@master
rescue *CONNECTION_ERRORS
@master = nil
false
end
end

def register_worker_presence
Expand Down Expand Up @@ -336,6 +416,10 @@ def store_chunk_metadata(chunks)
transaction.expire(key('test-group-timeout'), config.redis_ttl)
end
end
rescue *CONNECTION_ERRORS => e
raise if master?

warn("Failed to store chunk metadata: #{e.message}")
end

def chunk_id?(id)
Expand Down