Bug #25923
closedPuppet fact processing failed for hosts with large number of LUNs attached
Description
After an upgrade from Katello 3.8 to 3.10 - I see Postgres errors in production.log for hosts with lots of LUNs and array paths.
2019-01-25T12:51:37 [I|app|ad329] Processing by Api::V2::HostsController#facts as JSON
2019-01-25T12:51:37 [I|app|ad329] Parameters: {"facts"=>"[FILTERED]", "name"=>"rich-orcl-14-pp.snaponglobal.com", "certname"=>"rich-orcl-14-pp.snaponglobal.com", "apiv"=>"v2", "host"=>{"certname"=>"rich-orcl-14-pp.snaponglobal.com", "name"=>"rich-orcl-14-pp.snaponglobal.com"}}
2019-01-25T12:51:46 [W|app|ad329] Action failed
2019-01-25T12:51:46 [W|app|ad329] Action failed
ActiveRecord::StatementInvalid: PG::ProtocolViolation: ERROR: invalid message format
: SELECT "fact_names".* FROM "fact_names" WHERE "fact_names"."type" IN ('PuppetFactName') AND "fact_names"."name" IN ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15, $16, $17, $18, $19, $20, $21, $22, $23, $24, $25, $26, $27, $28, $29, $30, $31, $32, $33,$34, $35, $36, $37, $38, $39, $40, $41, $42, $43, $44, 45, $46, $47, $48, $49, $50, $51, $52, $53, $54, $55, $56, $57, $58, $59, $60, $61, $62, $63, $64, $65, $66, $67, $68, $69, $70, $71, $72, $73, $74, $75, $76, $77, $78, $79, $80, $81, $82, $83, $84, $85, $86, $87, $88, $89, $90, $91, $92, $93, $94, $95, $96, $97, $98, $99, $100, $101, $102, $103, $104, $105, $106, $107, $108, $109, $110, $111, $112, $113, $114, $115, $116, $117, $118,
<snipped for brevity but tens of thousands of parameters in numeric order here>
, $66347, $66348, $66349, $66350, $66351, $66352, $66353, $66354, $66355, $66356, $66357, $66358, $66359, $66360, $66361, $66362, $66363, $66364, $66365, $66366, $66367, $66368, $66369, $66370, $66371, $66372, $66373, $66374, $66375, $66376, $66377, $66378, $66379, $66380, $66381, $66382, $66383, $66384, $66385, $66386, $66387, $66388, $66389, $66390, $66391, $66392, $66393, $66394, $66395, $66396, $66397, $66398, $66399, $66400, $66401, $66402, $66403, $66404, $66405, $66406, $66407, $66408, $66409, $66410, $66411, $66412, $66413, $66414, $66415, $66416, $66417, $66418, $66419, $66420, $66421, $66422, $66423, $66424, $66425, $66426, $66427, $66428, $66429, $66430, $66431, $66432, $66433, $66434, $66435, $66436, $66437) AND "fact_names"."type" = $66438
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:603:in `async_exec'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:603:in `block (2 levels) in exec_no_cache'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:602:in `block in exec_no_cache'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract_adapter.rb:579:in `block (2 levels) in log'
/opt/rh/rh-ruby25/root/usr/share/ruby/monitor.rb:226:in `mon_synchronize'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract_adapter.rb:578:in `block in log'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract_adapter.rb:569:in `log'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:601:in `exec_no_cache'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:590:in `execute_and_clear'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:81:in `exec_query'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:465:in `select'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:57:in `select_all'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/query_cache.rb:99:in `block in select_all'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/query_cache.rb:122:in `block in cache_sql'
/opt/rh/rh-ruby25/root/usr/share/ruby/monitor.rb:226:in `mon_synchronize'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/query_cache.rb:108:in `cache_sql'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/query_cache.rb:99:in `select_all'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/querying.rb:41:in `find_by_sql'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/relation.rb:554:in `block in exec_queries'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/relation.rb:578:in `skip_query_cache_if_necessary'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/relation.rb:541:in `exec_queries'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/relation.rb:414:in `load'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/relation.rb:200:in `records'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/relation/delegation.rb:41:in `each'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/core_ext/enumerable.rb:67:in `index_by'
/usr/share/foreman/app/services/fact_importer.rb:128:in `initialize_fact_names'
/usr/share/foreman/app/services/fact_importer.rb:94:in `ensure_fact_names'
/usr/share/foreman/app/services/structured_fact_importer.rb:51:in `ensure_fact_names'
/usr/share/foreman/app/services/fact_importer.rb:56:in `import!'
/usr/share/foreman/app/models/host/base.rb:144:in `block in import_facts'
/usr/share/foreman/app/services/foreman/telemetry_helper.rb:27:in `telemetry_duration_histogram'
/usr/share/foreman/app/models/host/base.rb:143:in `import_facts'
/usr/share/foreman/app/models/host/managed.rb:324:in `import_facts'
/usr/share/foreman/app/controllers/api/v2/hosts_controller.rb:288:in `facts'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/abstract_controller/base.rb:194:in `process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/rendering.rb:30:in `process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/usr/share/foreman/app/controllers/api/v2/base_controller.rb:163:in `disable_json_root'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/application_shared.rb:15:in `set_timezone'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in `clear_thread'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/foreman/controller/topbar_sweeper.rb:12:in `set_topbar_sweeper_controller'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/theforeman/tfm/root/usr/share/gems/gems/audited-4.7.1/lib/audited/sweeper.rb:14:in `around'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/theforeman/tfm/root/usr/share/gems/gems/audited-4.7.1/lib/audited/sweeper.rb:14:in `around'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:136:in `run_callbacks'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/abstract_controller/callbacks.rb:41:in `process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/rescue.rb:22:in `process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/notifications.rb:168:in `block in instrument'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/notifications.rb:168:in `instrument'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/abstract_controller/base.rb:134:in `process'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionview-5.2.1/lib/action_view/rendering.rb:32:in `process'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal.rb:191:in `dispatch'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal.rb:252:in `dispatch'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/routing/route_set.rb:34:in `serve'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/routing/mapper.rb:18:in `block in <class:Constraints>'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/routing/mapper.rb:48:in `serve'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/journey/router.rb:52:in `block in serve'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/journey/router.rb:35:in `each'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/journey/router.rb:35:in `serve'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/routing/route_set.rb:840:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.14/lib/apipie/static_dispatcher.rb:65:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.14/lib/apipie/extractor/recorder.rb:137:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
/usr/share/foreman/lib/middleware/telemetry.rb:9:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.14/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
/usr/share/foreman/lib/middleware/catch_json_parse_errors.rb:8:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/tempfile_reaper.rb:15:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/etag.rb:25:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/conditional_get.rb:38:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/head.rb:12:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/usr/share/foreman/lib/middleware/logging_context.rb:23:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/session/abstract/id.rb:232:in `context'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/session/abstract/id.rb:226:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/cookies.rb:670:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:98:in `run_callbacks'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/railties-5.2.1/lib/rails/rack/logger.rb:38:in `call_app'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/railties-5.2.1/lib/rails/rack/logger.rb:28:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb:13:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.10.0/lib/katello/prevent_json_parsing.rb:12:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/method_override.rb:22:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/runtime.rb:22:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_dispatch/middleware/static.rb:127:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/sendfile.rb:111:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/secure_headers-6.0.0/lib/secure_headers/middleware.rb:13:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/railties-5.2.1/lib/rails/engine.rb:524:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/railties-5.2.1/lib/rails/railtie.rb:190:in `public_send'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/railties-5.2.1/lib/rails/railtie.rb:190:in `method_missing'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/urlmap.rb:68:in `block in call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/urlmap.rb:53:in `each'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/rack-2.0.5/lib/rack/urlmap.rb:53:in `call'
/usr/share/passenger/phusion_passenger/rack/thread_handler_extension.rb:74:in `process_request'
/usr/share/passenger/phusion_passenger/request_handler/thread_handler.rb:141:in `accept_and_process_next_request'
/usr/share/passenger/phusion_passenger/request_handler/thread_handler.rb:109:in `main_loop'
/usr/share/passenger/phusion_passenger/request_handler.rb:455:in `block (3 levels) in start_threads'
/opt/theforeman/tfm/root/usr/share/gems/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2019-01-25T12:51:46 [I|app|ad329] Rendering api/v2/errors/standard_error.json.rabl within api/v2/layouts/error_layout
2019-01-25T12:51:46 [I|app|ad329] Rendered api/v2/errors/standard_error.json.rabl within api/v2/layouts/error_layout (4.8ms)
2019-01-25T12:51:46 [I|app|ad329] Completed 500 Internal Server Error in 9203ms (Views: 6.4ms | ActiveRecord: 31.3ms)
Updated by Tomer Brisker over 5 years ago
- Related to Refactor #25053: Run expensive db_facts query just once and unordered added
Updated by Tomer Brisker over 5 years ago
- Project changed from Katello to Foreman
- Category set to Facts
This seems to be related to an optimization attempt in the fact importer in foreman 1.20, moving to foreman project
Updated by Lukas Zapletal over 5 years ago
Tomer, what makes you think this is related? I mean, before and after the patch the code still contains: query.where(:fact_name => fact_names.values)
so we are including quite a bunch of SQL parameters which is obviously not great but I haven't touched this.
Let me try to workaround this via regular expression.
Updated by The Foreman Bot over 5 years ago
- Status changed from New to Ready For Testing
- Assignee set to Lukas Zapletal
- Pull request https://github.com/theforeman/foreman/pull/6438 added
Updated by The Foreman Bot over 5 years ago
- Pull request https://github.com/theforeman/foreman/pull/6480 added
Updated by Tomer Brisker over 5 years ago
- Pull request deleted (
https://github.com/theforeman/foreman/pull/6438)
Updated by Lukas Zapletal over 5 years ago
- Status changed from Ready For Testing to Closed
Applied in changeset 678fd49ef2490485dea76ba6b8f289e9388519d9.
Updated by Anonymous over 5 years ago
- Related to Refactor #26882: Update fact importer for Foreman 1.23 added