I have enabled all debugging I could find in /etc/foreman/settings.yaml (except :sql:), particularly telemetry.logger.
This is what I am getting without :sql: logging:
2023-02-20T20:08:02 [D|dyn|] Executor heartbeat
2023-02-20T20:08:17 [D|dyn|] Executor heartbeat
2023-02-20T20:08:22 [I|app|9709ac29] Started GET "/apidoc/apipie_checksum" for 10.212.2.31 at 2023-02-20 20:08:22 +0100
2023-02-20T20:08:22 [D|tel|9709ac29] Incrementing counter fm_rails_activerecord_instances by 1.00 {:class=>"User"}
2023-02-20T20:08:22 [D|tel|9709ac29] Incrementing counter fm_rails_activerecord_instances by 1.00 {:class=>"AuthSource"}
2023-02-20T20:08:22 [D|per|9709ac29] Current user set to foreman_admin (admin)
2023-02-20T20:08:22 [I|app|9709ac29] Processing by Apipie::ApipiesController#apipie_checksum as JSON
2023-02-20T20:08:22 [I|app|9709ac29] Parameters: {"apipy"=>{}}
2023-02-20T20:08:22 [D|app|9709ac29] Rendering /usr/share/gems/gems/apipie-rails-0.8.2/app/views/apipie/apipies/apipie_checksum.json.erb
2023-02-20T20:08:24 [I|app|9709ac29] Rendered /usr/share/gems/gems/apipie-rails-0.8.2/app/views/apipie/apipies/apipie_checksum.json.erb (Duration: 1323.4ms | Allocations: 1772899)
2023-02-20T20:08:24 [I|app|9709ac29] Completed 200 OK in 1333ms (Views: 1328.3ms | ActiveRecord: 0.6ms | Allocations: 1776079)
2023-02-20T20:08:24 [D|tel|9709ac29] Incrementing counter fm_rails_http_requests by 1.00 {:controller=>"other", :action=>"other", :status=>200}
2023-02-20T20:08:24 [D|tel|9709ac29] Observing histogram fm_rails_http_request_total_duration value 1332.70 {:controller=>"other", :action=>"other"}
2023-02-20T20:08:24 [D|tel|9709ac29] Observing histogram fm_rails_http_request_db_duration value 0.60 {:controller=>"other", :action=>"other"}
2023-02-20T20:08:24 [D|tel|9709ac29] Observing histogram fm_rails_http_request_view_duration value 1328.33 {:controller=>"other", :action=>"other"}
2023-02-20T20:08:24 [D|tel|9709ac29] Incrementing counter fm_rails_ruby_gc_count by 5.00 {:controller=>"other", :action=>"other"}
2023-02-20T20:08:24 [D|tel|9709ac29] Incrementing counter fm_rails_ruby_gc_minor_count by 5.00 {:controller=>"other", :action=>"other"}
2023-02-20T20:08:24 [D|tel|9709ac29] Incrementing counter fm_rails_ruby_gc_allocated_objects by 1789097.00 {:controller=>"other", :action=>"other"}
2023-02-20T20:08:24 [D|tel|9709ac29] Incrementing counter fm_rails_ruby_gc_freed_objects by 1789440.00 {:controller=>"other", :action=>"other"}
2023-02-20T20:08:24 [I|app|f529536b] Started POST "/api/users" for 10.212.2.31 at 2023-02-20 20:08:24 +0100
2023-02-20T20:08:24 [I|app|f529536b] Processing by Api::V2::UsersController#create as JSON
2023-02-20T20:08:24 [I|app|f529536b] Parameters: {"user"=>{"login"=>"testuser", "mail"=>"testuser1@my.org", "password"=>"[FILTERED]", "auth_source_id"=>1}, "apiv"=>"v2"}
2023-02-20T20:08:24 [D|tel|f529536b] Incrementing counter fm_rails_activerecord_instances by 1.00 {:class=>"User"}
2023-02-20T20:08:25 [D|tel|f529536b] Observing histogram fm_rails_login_pwhash_duration value 366.03 {:algorithm=>:pbkdf2sha1}
2023-02-20T20:08:32 [D|dyn|] Executor heartbeat
2023-02-20T20:08:47 [D|dyn|] Executor heartbeat
And the following even includes :sql: logging (everything set to “debug”):
2023-02-20T20:13:05 [D|sql|01396098] Katello::Event Load (0.2ms) SELECT "katello_events".* FROM "katello_events" WHERE ("katello_events"."process_after" IS NULL OR "katello_events"."process_after" BETWEEN $1 AND $2) AND "katello_events"."in_progress" = $3 ORDER BY "katello_events"."created_at" ASC LIMIT $4 [["process_after", "4713-01-01 BC"], ["process_after", "2023-02-20 19:13:05.924455"], ["in_progress", false], ["LIMIT", 1]]
2023-02-20T20:13:08 [D|sql|01396098] Katello::Event Load (0.2ms) SELECT "katello_events".* FROM "katello_events" WHERE ("katello_events"."process_after" IS NULL OR "katello_events"."process_after" BETWEEN $1 AND $2) AND "katello_events"."in_progress" = $3 ORDER BY "katello_events"."created_at" ASC LIMIT $4 [["process_after", "4713-01-01 BC"], ["process_after", "2023-02-20 19:13:08.926681"], ["in_progress", false], ["LIMIT", 1]]
2023-02-20T20:13:11 [D|sql|01396098] Katello::Event Load (0.3ms) SELECT "katello_events".* FROM "katello_events" WHERE ("katello_events"."process_after" IS NULL OR "katello_events"."process_after" BETWEEN $1 AND $2) AND "katello_events"."in_progress" = $3 ORDER BY "katello_events"."created_at" ASC LIMIT $4 [["process_after", "4713-01-01 BC"], ["process_after", "2023-02-20 19:13:11.929095"], ["in_progress", false], ["LIMIT", 1]]
2023-02-20T20:13:13 [D|dyn|] Executor heartbeat
2023-02-20T20:13:14 [D|sql|01396098] Katello::Event Load (0.2ms) SELECT "katello_events".* FROM "katello_events" WHERE ("katello_events"."process_after" IS NULL OR "katello_events"."process_after" BETWEEN $1 AND $2) AND "katello_events"."in_progress" = $3 ORDER BY "katello_events"."created_at" ASC LIMIT $4 [["process_after", "4713-01-01 BC"], ["process_after", "2023-02-20 19:13:14.932780"], ["in_progress", false], ["LIMIT", 1]]
2023-02-20T20:13:15 [I|app|31b21abd] Started GET "/apidoc/apipie_checksum" for 10.212.2.31 at 2023-02-20 20:13:15 +0100
2023-02-20T20:13:15 [I|app|31b21abd] Processing by Apipie::ApipiesController#apipie_checksum as JSON
2023-02-20T20:13:15 [I|app|31b21abd] Parameters: {"apipy"=>{}}
2023-02-20T20:13:15 [D|app|31b21abd] Rendering /usr/share/gems/gems/apipie-rails-0.8.2/app/views/apipie/apipies/apipie_checksum.json.erb
2023-02-20T20:13:16 [I|app|31b21abd] Rendered /usr/share/gems/gems/apipie-rails-0.8.2/app/views/apipie/apipies/apipie_checksum.json.erb (Duration: 1524.1ms | Allocations: 1772575)
2023-02-20T20:13:16 [I|app|31b21abd] Completed 200 OK in 1530ms (Views: 1527.7ms | ActiveRecord: 0.0ms | Allocations: 1775713)
2023-02-20T20:13:16 [D|tel|31b21abd] Incrementing counter fm_rails_http_requests by 1.00 {:controller=>"other", :action=>"other", :status=>200}
2023-02-20T20:13:16 [D|tel|31b21abd] Observing histogram fm_rails_http_request_total_duration value 1530.35 {:controller=>"other", :action=>"other"}
2023-02-20T20:13:16 [D|tel|31b21abd] Observing histogram fm_rails_http_request_db_duration value 0.00 {:controller=>"other", :action=>"other"}
2023-02-20T20:13:16 [D|tel|31b21abd] Observing histogram fm_rails_http_request_view_duration value 1527.74 {:controller=>"other", :action=>"other"}
2023-02-20T20:13:16 [D|tel|31b21abd] Incrementing counter fm_rails_ruby_gc_count by 6.00 {:controller=>"other", :action=>"other"}
2023-02-20T20:13:16 [D|tel|31b21abd] Incrementing counter fm_rails_ruby_gc_major_count by 1.00 {:controller=>"other", :action=>"other"}
2023-02-20T20:13:16 [D|tel|31b21abd] Incrementing counter fm_rails_ruby_gc_minor_count by 5.00 {:controller=>"other", :action=>"other"}
2023-02-20T20:13:16 [D|tel|31b21abd] Incrementing counter fm_rails_ruby_gc_allocated_objects by 1777601.00 {:controller=>"other", :action=>"other"}
2023-02-20T20:13:16 [D|tel|31b21abd] Incrementing counter fm_rails_ruby_gc_freed_objects by 1777086.00 {:controller=>"other", :action=>"other"}
2023-02-20T20:13:17 [I|app|c1c12435] Started POST "/api/users" for 10.212.2.31 at 2023-02-20 20:13:17 +0100
2023-02-20T20:13:17 [I|app|c1c12435] Processing by Api::V2::UsersController#create as JSON
2023-02-20T20:13:17 [I|app|c1c12435] Parameters: {"user"=>{"login"=>"testuser", "mail"=>"testuser1@my.org", "password"=>"[FILTERED]", "auth_source_id"=>1}, "apiv"=>"v2"}
2023-02-20T20:13:17 [D|sql|c1c12435] Setting Load (0.3ms) SELECT "settings".* FROM "settings" WHERE "settings"."category" = $1 AND "settings"."value" IS NOT NULL AND (updated_at >= '2023-02-20 19:12:06.554863') [["category", "Setting"]]
2023-02-20T20:13:17 [D|sql|c1c12435] User Load (0.2ms) SELECT "users".* FROM "users" WHERE "users"."lower_login" = $1 LIMIT $2 [["lower_login", "admin_01"], ["LIMIT", 1]]
2023-02-20T20:13:17 [D|tel|c1c12435] Incrementing counter fm_rails_activerecord_instances by 1.00 {:class=>"User"}
2023-02-20T20:13:17 [D|tel|c1c12435] Observing histogram fm_rails_login_pwhash_duration value 378.72 {:algorithm=>:pbkdf2sha1}
2023-02-20T20:13:17 [D|sql|c1c12435] PersonalAccessToken Load (0.6ms) SELECT "personal_access_tokens".* FROM "personal_access_tokens" WHERE "personal_access_tokens"."revoked" = $1 AND (expires_at >= '2023-02-20 19:13:17.081692' OR expires_at IS NULL) AND "personal_access_tokens"."user_id" = $2 AND "personal_access_tokens"."token" = $3 LIMIT $4 [["revoked", false], ["user_id", 6], ["token", "$pbkdf2sha1$600000$9054fbe0b622c638224d50d20824d2ff6782e308$67SUVb8SU8BCneMq+0wP3Gu1x2tsy/ab2649b7e58f7e32b0c75b"], ["LIMIT", 1]]
2023-02-20T20:13:17 [D|sql|01396098] Katello::Event Load (0.6ms) SELECT "katello_events".* FROM "katello_events" WHERE ("katello_events"."process_after" IS NULL OR "katello_events"."process_after" BETWEEN $1 AND $2) AND "katello_events"."in_progress" = $3 ORDER BY "katello_events"."created_at" ASC LIMIT $4 [["process_after", "4713-01-01 BC"], ["process_after", "2023-02-20 19:13:17.935555"], ["in_progress", false], ["LIMIT", 1]]
2023-02-20T20:13:20 [D|sql|01396098] Katello::Event Load (0.2ms) SELECT "katello_events".* FROM "katello_events" WHERE ("katello_events"."process_after" IS NULL OR "katello_events"."process_after" BETWEEN $1 AND $2) AND "katello_events"."in_progress" = $3 ORDER BY "katello_events"."created_at" ASC LIMIT $4 [["process_after", "4713-01-01 BC"], ["process_after", "2023-02-20 19:13:20.940814"], ["in_progress", false], ["LIMIT", 1]]
It’s frustrating that full debug logging doesn’t provide more details.
Is there a way to further increase the verbosity of logging?
