dymk/redux-scraper
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Enhance logging with more informative and consistent tags

Browse Source
This commit is contained in:
Dylan Knutson
2025-02-14 08:39:35 +00:00
parent fc0fbfc46e
commit 97f7e50d61
9 changed files with 133 additions and 70 deletions
Download Patch File Download Diff File Expand all files Collapse all files

13
app/jobs/domain/e621/job/static_file_job.rb
View File

@@ -13,15 +13,18 @@ class Domain::E621::Job::StaticFileJob < Domain::E621::Job::Base
elsif (post = args[:post]) && post.is_a?(Domain::E621::Post)
post =
Domain::Post::E621Post.find_by(e621_id: post.e621_id) ||
raise("post with e621_id #{post.e621_id} not found")
fatal_error(
format_tags(
"post with not found",
make_tag("e621_id", post.e621_id),
),
)
T.must(post.file)
else
fatal_error(":file or :post is required")
end
logger.tagged(
make_tag("post_id", file.post&.id),
make_tag("state", file.state),
) { download_post_file(file) }
logger.push_tags(make_arg_tag(file), make_arg_tag(file.post))
download_post_file(file)
end
end

45
app/jobs/domain/fa/job/base.rb
View File

@@ -193,7 +193,11 @@ class Domain::Fa::Job::Base < Scraper::JobBase
when :file_error
logger.info "(todo) file_error'd post seen in listing page for fa_id #{post.fa_id}"
else
logger.info "unknown post state `#{post.state}` for fa_id #{post.fa_id}"
logger.info format_tags(
"unknown post state",
make_tag("post.state", post.state),
make_tag("post.fa_id", post.fa_id),
)
end
end
@@ -261,7 +265,9 @@ class Domain::Fa::Job::Base < Scraper::JobBase
{ user: user }
else
unless user.url_name
logger.warn "user does not have a url name and is not persisted, skipping (#{user.name})"
logger.warn format_tags(
"no user url_name and is new record, skipping",
)
return
end
@@ -271,8 +277,10 @@ class Domain::Fa::Job::Base < Scraper::JobBase
if enqueue_page_scan && users_enqueued_for_page_scan.add?(user.url_name)
if user.due_for_page_scan?
logger.info(
"enqueue user page job for #{T.must(user.url_name).bold}, " +
"last scanned #{time_ago_in_words(user.scanned_page_at)}",
format_tags(
"enqueue user page job",
make_tag("last scanned", time_ago_in_words(user.scanned_page_at)),
),
)
defer_job(Domain::Fa::Job::UserPageJob, args)
end
@@ -282,8 +290,13 @@ class Domain::Fa::Job::Base < Scraper::JobBase
users_enqueued_for_gallery_scan.add?(user.url_name)
if user.due_for_gallery_scan?
logger.info(
"enqueue user gallery job for #{T.must(user.url_name).bold}, " +
"last scanned #{time_ago_in_words(user.scanned_gallery_at)}",
format_tags(
"enqueue user gallery job",
make_tag(
"last scanned",
time_ago_in_words(user.scanned_gallery_at),
),
),
)
defer_job(Domain::Fa::Job::UserGalleryJob, args)
end
@@ -292,8 +305,10 @@ class Domain::Fa::Job::Base < Scraper::JobBase
if enqueue_favs_scan && users_enqueued_for_favs_scan.add?(user.url_name)
if user.due_for_favs_scan?
logger.info(
"enqueue user favs job for #{T.must(user.url_name).bold}, " +
"last scanned #{time_ago_in_words(user.scanned_favs_at)}",
format_tags(
"enqueue user favs job",
make_tag("last scanned", time_ago_in_words(user.scanned_favs_at)),
),
)
defer_job(Domain::Fa::Job::FavsJob, args)
end
@@ -317,7 +332,8 @@ class Domain::Fa::Job::Base < Scraper::JobBase
enqueue_pri = self.class.normalize_enqueue_pri(enqueue_pri)
if @posts_enqueued_for_scan.add?(fa_id)
logger.info "enqueue post scan for fa_id #{fa_id}"
logger.info format_tags("enqueue post scan", make_tag("fa_id", fa_id))
defer_job(
Domain::Fa::Job::ScanPostJob,
{ fa_id: fa_id },
@@ -335,7 +351,10 @@ class Domain::Fa::Job::Base < Scraper::JobBase
if @posts_enqueued_for_scan.add?(T.must(post.fa_id))
fa_id_str = (post.fa_id || "(nil)").to_s.bold
if !post.scanned_at.present?
logger.info "enqueue post scan for fa_id #{fa_id_str}"
logger.info format_tags(
"enqueue post scan",
make_tag("fa_id", fa_id_str),
)
defer_job(
Domain::Fa::Job::ScanPostJob,
{ post: post },
@@ -343,7 +362,11 @@ class Domain::Fa::Job::Base < Scraper::JobBase
)
elsif (post_file = post.file) && post_file.url_str.present? &&
post_file.log_entry.nil?
logger.info "enqueue file scan for fa_id #{fa_id_str}"
logger.info format_tags(
"enqueue file scan",
make_tag("fa_id", fa_id_str),
make_tag("post_file.id", post_file.id),
)
defer_job(
Domain::Fa::Job::ScanFileJob,
{ post_file: },

17
app/jobs/domain/fa/job/scan_post_job.rb
View File

@@ -5,18 +5,20 @@ class Domain::Fa::Job::ScanPostJob < Domain::Fa::Job::Base
sig { override.params(args: T::Hash[Symbol, T.untyped]).returns(T.untyped) }
def perform(args)
post = post_from_args!(build_post: true)
logger.prefix =
proc { "[fa_id #{post.fa_id.to_s.bold} / #{post.state&.bold}]" }
logger.push_tags(make_arg_tag(post))
if (post.state == "ok" && !post.scanned_at.present?) || force_scan?
ReduxApplicationRecord.transaction { scan_post(post) }
end
file = post.file
logger.push_tags(make_arg_tag(file)) if file.present?
if (file.present? && file.state == "pending" && file.url_str.present?) ||
force_scan?
logger.info("enqueue file job (#{self.priority})")
logger.info(
format_tags("enqueue file job", make_tag("priority", self.priority)),
)
defer_job(
Domain::Fa::Job::ScanFileJob,
{ post_file: post.file },
@@ -25,6 +27,7 @@ class Domain::Fa::Job::ScanPostJob < Domain::Fa::Job::Base
end
if creator = post.creator
logger.push_tags(make_arg_tag(creator))
enqueue_user_scan(creator)
end
@@ -34,7 +37,7 @@ class Domain::Fa::Job::ScanPostJob < Domain::Fa::Job::Base
suppress_jobs: [{ job: self.class, fa_id: post.fa_id }],
)
end
logger.info "finished post scan"
logger.info format_tags("finished post scan")
ensure
post.save! if post
end
@@ -58,7 +61,7 @@ class Domain::Fa::Job::ScanPostJob < Domain::Fa::Job::Base
page = Domain::Fa::Parser::Page.new(response.body, require_logged_in: false)
if page.submission_not_found?
logger.error("post was removed")
logger.error(format_tags("post was removed"))
post.state = "removed"
return
end
@@ -68,7 +71,7 @@ class Domain::Fa::Job::ScanPostJob < Domain::Fa::Job::Base
unless page.probably_submission?
if response.body =~
/The page you are trying to reach is currently pending deletion/
logger.error("post is pending deletion")
logger.error(format_tags("post is pending deletion"))
post.state = "removed"
return
else

13
app/jobs/domain/fa/job/user_avatar_job.rb
View File

@@ -8,10 +8,7 @@ class Domain::Fa::Job::UserAvatarJob < Domain::Fa::Job::Base
avatar = avatar_from_args!
user = T.cast(avatar.user, Domain::User::FaUser)
logger.prefix =
proc do
"[avatar #{avatar.id.to_s.bold} / user #{user.url_name.to_s.bold}]"
end
logger.push_tags(make_arg_tag(avatar), make_arg_tag(user))
if avatar.state == "ok" && avatar.log_entry.present? && !force_scan?
logger.info("already have avatar downloaded, skipping")
@@ -20,6 +17,7 @@ class Domain::Fa::Job::UserAvatarJob < Domain::Fa::Job::Base
response =
http_client.get("https://a.furaffinity.net/0/#{user.url_name}.gif")
logger.push_tags(make_arg_tag(response.log_entry))
avatar.last_log_entry = response.log_entry
avatar.downloaded_at = response.log_entry.created_at
@@ -28,15 +26,18 @@ class Domain::Fa::Job::UserAvatarJob < Domain::Fa::Job::Base
when 200
avatar.state = "ok"
avatar.log_entry = response.log_entry
logger.info("downloaded avatar")
logger.info(format_tags("downloaded avatar"))
when 404
avatar.state = "file_404"
avatar.error_message = "http status #{response.status_code}"
logger.warn(format_tags("404, terminal error state"))
else
avatar.state = "http_error"
avatar.error_message = "http status #{response.status_code}"
fatal_error(
"http #{response.status_code}, log entry #{response.log_entry.id}",
format_tags(
"http #{response.status_code}, log entry #{response.log_entry.id}",
),
)
end
ensure

30
app/jobs/domain/fa/job/user_incremental_job.rb
View File

@@ -6,11 +6,10 @@ module Domain::Fa::Job
sig { override.params(args: T::Hash[Symbol, T.untyped]).returns(T.untyped) }
def perform(args)
user = user_from_args!
logger.push_tags(make_arg_tag(user))
# buggy user
return if user.id == 117_552 && user.url_name == "click here"
logger.prefix =
proc { "[ #{user.id.to_s.bold} / #{user.url_name&.bold} ]" }
# this is similar to a user page job, and will update the user page
# however, it will incrementally update user favs & follows / following:
@@ -22,13 +21,20 @@ module Domain::Fa::Job
if !user.due_for_incremental_scan? && !force_scan?
logger.warn(
"scanned #{time_ago_in_words(user.scanned_incremental_at).bold}, skipping",
format_tags(
make_tag(
"incremental scanned",
time_ago_in_words(user.scanned_incremental_at),
),
"scanned recently, skipping",
),
)
return
end
response =
http_client.get("https://www.furaffinity.net/user/#{user.url_name}/")
logger.push_tags(make_arg_tag(response.log_entry))
ret =
Domain::Fa::Job::ScanUserUtils.check_disabled_or_not_found(
@@ -39,11 +45,12 @@ module Domain::Fa::Job
case ret
when ScanUserUtils::DisabledOrNotFoundResult::Ok
page = ret.page
logger.info(format_tags("user page is ok"))
when ScanUserUtils::DisabledOrNotFoundResult::Stop
logger.error(ret.message)
logger.error(format_tags(ret.message))
return
when ScanUserUtils::DisabledOrNotFoundResult::Fatal
fatal_error(ret.message)
fatal_error(format_tags(ret.message))
end
update_user_fields_from_page(user, page, response)
@@ -53,10 +60,11 @@ module Domain::Fa::Job
check_watching(user, page.user_page.recent_watching)
user.scanned_incremental_at = Time.current
user.save!
logger.info "completed page scan"
logger.info(format_tags("completed page scan"))
ensure
if response && response.status_code == 200
user.save! if user
if response && response.status_code == 200 && user.present?
enqueue_jobs_from_found_links(
response.log_entry,
suppress_jobs: [{ job: self.class, url_name: user.url_name }],
@@ -86,7 +94,7 @@ module Domain::Fa::Job
if missing_fav_post_ids.any?
logger.info(
"add #{missing_fav_post_ids.size.to_s.bold} new favs for user",
format_tags(make_tag("add favs", missing_fav_post_ids.size)),
)
Domain::UserPostFav.insert_all!(
missing_fav_post_ids.map do |post_id|
@@ -96,9 +104,7 @@ module Domain::Fa::Job
end
if missing_fav_post_ids.include? recent_fav_post_ids.last
logger.info(
"last fav is new (#{missing_fav_post_ids.size.to_s.bold} missing), enqueue full favs scan",
)
logger.info(format_tags("last fav is new, enqueue full favs scan"))
defer_job(Domain::Fa::Job::FavsJob, { user: user })
else
user.scanned_favs_at = Time.current

10
app/jobs/domain/inkbunny/job/base.rb
View File

@@ -19,4 +19,14 @@ class Domain::Inkbunny::Job::Base < Scraper::JobBase
def user_from_args!
user_from_args || raise("user must exist")
end
sig { returns(Domain::Post::InkbunnyPost) }
def post_from_args!
T.cast(arguments[0][:post], Domain::Post::InkbunnyPost)
end
sig { returns(Domain::PostFile::InkbunnyPostFile) }
def post_file_from_args!
T.cast(arguments[0][:file], Domain::PostFile::InkbunnyPostFile)
end
end

11
app/jobs/domain/inkbunny/job/static_file_job.rb
View File

@@ -6,14 +6,9 @@ module Domain::Inkbunny::Job
sig { override.params(args: T::Hash[Symbol, T.untyped]).returns(T.untyped) }
def perform(args)
file = T.cast(args[:file], Domain::PostFile::InkbunnyPostFile)
logger.tagged(
make_tag("file_class", file.class.name),
make_tag("id", file.id),
make_tag("ib_file_id", file.ib_id),
make_tag("state", file.state),
) { download_post_file(file) }
file = post_file_from_args!
logger.push_tags(make_arg_tag(file), make_arg_tag(file.post))
download_post_file(file)
end
end
end

47
app/jobs/domain/static_file_job_helper.rb
View File

@@ -11,42 +11,51 @@ module Domain::StaticFileJobHelper
sig { params(post_file: Domain::PostFile).void }
def download_post_file(post_file)
if post_file.state_terminal_error?
logger.error("post file is in a terminal error state, skipping")
logger.error(format_tags("terminal error state, skipping"))
return
end
if post_file.state_ok? && post_file.log_entry_id.present?
logger.warn("post file has already been downloaded, skipping")
logger.warn(format_tags("already downloaded, skipping"))
return
end
file_url_str = post_file.url_str
if file_url_str.blank?
logger.warn("post file has no url, skipping")
logger.warn(format_tags("no url, skipping"))
return
end
response = http_client.get(file_url_str)
post_file.log_entry = response.log_entry
post_file.last_status_code = response.status_code
if response.status_code == 200
post_file.state_ok!
logger.info("downloaded file")
elsif response.status_code == 404
post_file.state_terminal_error!
post_file.retry_count += 1
logger.error("#{response.status_code}, not retrying download")
else
post_file.retry_count += 1
if post_file.retry_count > MAX_RETRIES
logger.tagged(make_arg_tag(response.log_entry)) do
if response.status_code == 200
post_file.state_ok!
logger.info(format_tags("downloaded file"))
elsif response.status_code == 404
post_file.state_terminal_error!
logger.error(
"file has been retried #{post_file.retry_count} times, giving up",
)
post_file.retry_count += 1
logger.error(format_tags("404, terminal error state"))
else
post_file.state_retryable_error!
fatal_error("#{response.status_code}, will retry later")
post_file.retry_count += 1
if post_file.retry_count > MAX_RETRIES
post_file.state_terminal_error!
logger.error(
format_tags(
make_tag("retry_count", post_file.retry_count),
"retried too many times, giving up",
),
)
else
post_file.state_retryable_error!
fatal_error(
format_tags(
make_tag("retry_count", post_file.retry_count),
"will retry later",
),
)
end
end
end
ensure

17
app/lib/has_color_logger.rb
View File

@@ -35,9 +35,11 @@ module HasColorLogger
sig { params(arg: T.untyped).returns(T::Array[String]) }
def make_arg_tag(arg)
tags = []
return tags if arg.nil?
if arg.is_a?(Domain::User)
prefix_and_attr = arg.class.param_prefix_and_attribute
tags << make_tag("user.kind", arg.class.view_prefix)
tags << make_tag("user.id", arg.id)
tags << make_tag(
"user.#{prefix_and_attr[0]}",
@@ -47,6 +49,7 @@ module HasColorLogger
if arg.is_a?(Domain::Post)
prefix_and_attr = arg.class.param_prefix_and_attribute
tags << make_tag("post.kind", arg.class.view_prefix)
tags << make_tag("post.id", arg.id)
tags << make_tag(
"post.#{prefix_and_attr[0]}",
@@ -55,8 +58,18 @@ module HasColorLogger
end
if arg.is_a?(Domain::PostFile)
tags << make_tag("post_file.id", arg.id)
tags << make_tag("post_file.post_id", arg.post_id)
tags << make_tag("file.id", arg.id)
tags << make_tag("file.state", arg.state)
end
if arg.is_a?(Domain::UserAvatar)
tags << make_tag("avatar.id", arg.id)
tags << make_tag("avatar.state", arg.state)
end
if arg.is_a?(HttpLogEntry)
tags << make_tag("hle.id", arg.id)
tags << make_tag("hle.code", arg.status_code)
end
tags