State var "disappears" and some error with StateVarHash

[vmedvedev]

Hello all,

I’ve got a transiend problem while deploying VM using rhc-miq-quickstart. Sometimes while deploying a VM I see WARN message “Failed to load BinaryBlob with ID [xxxxx] for MiqAeEngine::StateVarHash”. After that State Machine generally fails with " [State var :vm_prov_request_ids is blank!]". Seems like vm_prov_request_ids state variable turns out to be empty, while it surely had the value earlier (I see it in earlier log messages).

Have anybody seen this and where to investigate further?

WBR,
Viacheslav Medvedev

[vmedvedev]

automation log fragment:
[----] W, [2020-12-15T11:37:46.941925 #510589:2aac912a796c] WARN – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) Failed to load BinaryBlob with ID [1000000007953] for MiqAeEngine::StateVarHash
[----] I, [2020-12-15T11:37:46.957163 #510589:2aac912a796c] INFO – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) Updated namespace [/Service/Provisioning/StateMachines/ServiceProvision_Template/build_vm_provision_request?MiqServer%3A%3Amiq_server=1000000000001&Service%3A%3AService=1000000000151&ServiceTemplateProvisionTask%3A%3Aservice_template_provision_task=1000000000361&User%3A%3Auser=1000000000008&ae_state=post1&ae_state_data=—%20%21ruby%2Fobject%3AMiqAeEngine%3A%3AStateVarHash%0Abinary_blob_id%3A%201000000007953%0A&ae_state_previous=—%0A%22%2Frhc-miq-quickstart%2FService%2FProvisioning%2FStateMachines%2FServiceProvision_Template%2Fbuild_vm_provision_request%22%3A%0A%20%20ae_state%3A%20post1%0A%20%20ae_state_retries%3A%206%0A%20%20ae_state_started%3A%202020-12-15%2008%3A31%3A22%20UTC%0A%20%20ae_state_max_retries%3A%20100%0A&ae_state_retries=6&ae_state_started=2020-12-15%2008%3A31%3A22%20UTC&dialog_option_1_flavor=small&dialog_option_1_number_of_vms=1&dialog_option_1_os=centos_linux_7_7&dialog_tag_0_environment=prod&dialog_tag_0_location=b7&dialog_tag_0_machine_type=web&dialog_tag_0_network_location=internal&object_name=build_vm_provision_request&request=clone_to_service&service_action=Provision&vmdb_object_type=service_template_provision_task#create rhc-miq-quickstart/Service/Provisioning/StateMachines]
[----] I, [2020-12-15T11:37:46.984697 #510589:2aac912a796c] INFO – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) In State=[post1], invoking [on_entry] method=[update_serviceprovision_status(status => ‘Processing Post1 Customizations’)]
[----] I, [2020-12-15T11:37:46.991537 #510589:2aac912a796c] INFO – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) Updated namespace [Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status RedHatConsulting_Utilities/Service/Provisioning/StateMachines]
[----] I, [2020-12-15T11:37:46.999378 #510589:2aac912a796c] INFO – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) Invoking [inline] method [/RedHatConsulting_Utilities/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status] with inputs [{“status”=>“Processing Post1 Customizations”, “email_only_on_error”=>true}]
[----] I, [2020-12-15T11:37:47.000828 #510589:2aac912a796c] INFO – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) <AEMethod [/RedHatConsulting_Utilities/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status]> Starting
[----] I, [2020-12-15T11:37:47.487278 #510589:2aac9b745500] INFO – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) Save Telemetry as State Var: { service_provisioning_telemetry_on_entry_post1 => 2020-12-15 11:37:47 +0300, :miq_request_id => 1000000000360 }
[----] I, [2020-12-15T11:37:47.498866 #510589:2aac912a796c] INFO – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) <AEMethod [/RedHatConsulting_Utilities/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status]> Ending
[----] I, [2020-12-15T11:37:47.499026 #510589:2aac912a796c] INFO – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) Method exited with rc=MIQ_OK
[----] I, [2020-12-15T11:37:47.499475 #510589:2aac912a796c] INFO – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) Processing State=[post1]
[----] I, [2020-12-15T11:37:47.499727 #510589:2aac912a796c] INFO – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) Following Relationship [miqaedb:/Service/Provisioning/StateMachines/Methods/check_vm_provision_requests#create]
[----] I, [2020-12-15T11:37:47.510315 #510589:2aac912a796c] INFO – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) Updated namespace [miqaedb:/Service/Provisioning/StateMachines/Methods/check_vm_provision_requests#create rhc-miq-quickstart/Service/Provisioning/StateMachines]
[----] I, [2020-12-15T11:37:47.548287 #510589:2aac912a796c] INFO – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) Updated namespace [Service/Provisioning/StateMachines/Methods/check_vm_provision_requests rhc-miq-quickstart/Service/Provisioning/StateMachines]
[----] I, [2020-12-15T11:37:47.551329 #510589:2aac912a796c] INFO – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) Invoking [inline] method [/rhc-miq-quickstart/Service/Provisioning/StateMachines/Methods/check_vm_provision_requests] with inputs [{}]
[----] I, [2020-12-15T11:37:47.558043 #510589:2aac912a796c] INFO – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) Updated namespace [StdLib/Core/Core RedHatConsulting_Utilities/StdLib]
[----] I, [2020-12-15T11:37:47.570296 #510589:2aac912a796c] INFO – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) Loading embedded method /RedHatConsulting_Utilities/StdLib/Core/Core
[----] I, [2020-12-15T11:37:47.606126 #510589:2aac912a796c] INFO – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) <AEMethod [/rhc-miq-quickstart/Service/Provisioning/StateMachines/Methods/check_vm_provision_requests]> Starting
[----] E, [2020-12-15T11:37:48.048508 #510589:2aac9f471668] ERROR – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) [State var :vm_prov_request_ids is blank!]
/rhc-miq-quickstart/Service/Provisioning/StateMachines/Methods/check_vm_provision_requests:37:in main' /rhc-miq-quickstart/Service/Provisioning/StateMachines/Methods/check_vm_provision_requests:84:in ’

[pemcg]

State vars should only be “simple” data types (rather than for example a Rails object). What sort of variable are you storing (i.e. string, int etc)?

pemcg

[vmedvedev]

vm_prov_request_ids it’s an array of strings. But in fact “check_vm_provision_requests” method which fails - is RedHat (rhc-miq-quickstart) code, not mine. They use this variable to save provision request ids between state machine stages. And what I’ve noticed is that this variable looses it’s value from time to time.

[pemcg]

It would be interesting to see if any of your generic workers are being killed, try the following on all of your appliances:

grep 'MiqServer#validate_worker' evm.log | grep "WARN\|ERROR"

pemcg

[vmedvedev]

no such entries

[vmedvedev]

@vmedvedev

Failed to load BinaryBlob with ID [1000000007953] for MiqAeEngine::StateVarHash

But here’s what it contains about this BinaryBlob #7953

[----] I, [2020-12-15T11:36:45.833622 #510589:2aac912a796c] INFO – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) MIQ(MiqAeEngine.deliver) Requeuing {:object_type=>“ServiceTemplateProvisionTask”, :object_id=>1000000000361, :namespace=>“Service/Provisioning/StateMachines”, :class_name=>“ServiceProvision_Template”, :instance_name=>“build_vm_provision_request”, :automate_message=>“create”, :attrs=>{“dialog_tag_0_location”=>“b7”, “dialog_tag_0_environment”=>“prod”, “dialog_tag_0_network_location”=>“internal”, “dialog_option_1_os”=>“centos_linux_7_7”, “dialog_option_1_flavor”=>“small”, “dialog_tag_0_machine_type”=>“web”, “dialog_tag_0_gts_backup”=>nil, “dialog_tag_0_gts_replication”=>nil, “dialog_option_1_number_of_vms”=>“1”, “request”=>“clone_to_service”, :service_action=>“Provision”, “Service::Service”=>1000000000151}, :user_id=>1000000000008, :miq_group_id=>1000000000021, :tenant_id=>1000000000001, :miq_task_id=>nil, :state=>“post1”, :ae_fsm_started=>nil, :ae_state_started=>“2020-12-15 08:31:22 UTC”, :ae_state_retries=>6, :ae_state_data=>"— !ruby/object:MiqAeEngine::StateVarHash\nbinary_blob_id: 1000000007953\n", :ae_state_previous=>"—\n"/rhc-miq-quickstart/Service/Provisioning/StateMachines/ServiceProvision_Template/build_vm_provision_request":\n ae_state: post1\n ae_state_retries: 6\n ae_state_started: 2020-12-15 08:31:22 UTC\n ae_state_max_retries: 100\n"} for object [ServiceTemplateProvisionTask.1000000000361] with state [post1] to Automate for delivery in [60] seconds
[----] I, [2020-12-15T11:36:45.843769 #510589:2aac912a796c] INFO – : Q-task_id([r1000000000360_service_template_provision_task_1000000000361]) MIQ(MiqQueue.put) Message id: [1000001219176], id: , Zone: [default], Role: [automate], Server: , MiqTask id: , Ident: [generic], Target id: , Instance id: , Task id: , Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [100], State: [ready], Deliver On: [2020-12-15 08:37:45 UTC], Data: , Args: [{:object_type=>“ServiceTemplateProvisionTask”, :object_id=>1000000000361, :namespace=>“Service/Provisioning/StateMachines”, :class_name=>“ServiceProvision_Template”, :instance_name=>“build_vm_provision_request”, :automate_message=>“create”, :attrs=>{“dialog_tag_0_location”=>“b7”, “dialog_tag_0_environment”=>“prod”, “dialog_tag_0_network_location”=>“internal”, “dialog_option_1_os”=>“centos_linux_7_7”, “dialog_option_1_flavor”=>“small”, “dialog_tag_0_machine_type”=>“web”, “dialog_tag_0_gts_backup”=>nil, “dialog_tag_0_gts_replication”=>nil, “dialog_option_1_number_of_vms”=>“1”, “request”=>“clone_to_service”, :service_action=>“Provision”, “Service::Service”=>1000000000151}, :user_id=>1000000000008, :miq_group_id=>1000000000021, :tenant_id=>1000000000001, :miq_task_id=>nil, :state=>“post1”, :ae_fsm_started=>nil, :ae_state_started=>“2020-12-15 08:31:22 UTC”, :ae_state_retries=>6, :ae_state_data=>"— !ruby/object:MiqAeEngine::StateVarHash\nbinary_blob_id: 1000000007953\n", :ae_state_previous=>"—\n"/rhc-miq-quickstart/Service/Provisioning/StateMachines/ServiceProvision_Template/build_vm_provision_request":\n ae_state: post1\n ae_state_retries: 6\n ae_state_started: 2020-12-15 08:31:22 UTC\n ae_state_max_retries: 100\n"}]
[----] I, [2020-12-15T11:37:46.886426 #510589:2aac912a796c] INFO – : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [1000001219176], MiqWorker id: [1000000000359], Zone: [default], Role: [automate], Server: , MiqTask id: , Ident: [generic], Target id: , Instance id: , Task id: , Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [100], State: [dequeue], Deliver On: [2020-12-15 08:37:45 UTC], Data: , Args: [{:object_type=>“ServiceTemplateProvisionTask”, :object_id=>1000000000361, :namespace=>“Service/Provisioning/StateMachines”, :class_name=>“ServiceProvision_Template”, :instance_name=>“build_vm_provision_request”, :automate_message=>“create”, :attrs=>{“dialog_tag_0_location”=>“b7”, “dialog_tag_0_environment”=>“prod”, “dialog_tag_0_network_location”=>“internal”, “dialog_option_1_os”=>“centos_linux_7_7”, “dialog_option_1_flavor”=>“small”, “dialog_tag_0_machine_type”=>“web”, “dialog_tag_0_gts_backup”=>nil, “dialog_tag_0_gts_replication”=>nil, “dialog_option_1_number_of_vms”=>“1”, “request”=>“clone_to_service”, :service_action=>“Provision”, “Service::Service”=>1000000000151}, :user_id=>1000000000008, :miq_group_id=>1000000000021, :tenant_id=>1000000000001, :miq_task_id=>nil, :state=>“post1”, :ae_fsm_started=>nil, :ae_state_started=>“2020-12-15 08:31:22 UTC”, :ae_state_retries=>6, :ae_state_data=>"— !ruby/object:MiqAeEngine::StateVarHash\nbinary_blob_id: 1000000007953\n", :ae_state_previous=>"—\n"/rhc-miq-quickstart/Service/Provisioning/StateMachines/ServiceProvision_Template/build_vm_provision_request":\n ae_state: post1\n ae_state_retries: 6\n ae_state_started: 2020-12-15 08:31:22 UTC\n ae_state_max_retries: 100\n"}], Dequeued in: [61.049291244] seconds

[pemcg]

Let’s look at the older log files, try this:

zgrep ‘MiqServer#validate_worker’ /var/www/miq/vmdb/log/evm.log* | grep “WARN|ERROR”

[vmedvedev]

Your command returned no results. But here is all the worker related errors:
zgrep 'worker' /var/www/miq/vmdb/log/evm.log* | grep -E "WARN|ERROR"

/var/www/miq/vmdb/log/evm.log:[----] W, [2020-12-16T10:23:54.875856 #510573:2b1f9dc62bd0] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log:[----] W, [2020-12-16T10:23:55.227037 #510573:2b1f9dc62bd0] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:43.973513 #510604:2b0ce474d968] ERROR – : MIQ(ManageIQ::Providers::AnsibleTower::AutomationManager::RefreshWorker::Runner) ID [1000000000364] PID [510604] GUID [cb14f850-8867-42c0-bb3e-fa24cbcf7272] Error in update_worker_record_at_exit: PG::UnableToSend: no connection to the server
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:44.065443 #640961:2ad5f0c21974] ERROR – : MIQ(MiqGenericWorker::Runner) ID [1000000000365] PID [640961] GUID [1878da0c-579b-4780-8a4e-93967a113bf1] Error in update_worker_record_at_exit: PG::UnableToSend: no connection to the server
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:44.068516 #510587:2ab2757c9960] ERROR – : MIQ(MiqGenericWorker::Runner) ID [1000000000358] PID [510587] GUID [68fcb67e-b4e4-46d0-a133-94c7e3a3c289] Error in update_worker_record_at_exit: PG::UnableToSend: no connection to the server
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:48.199631 #510591:2aaf6ce9195c] ERROR – : MIQ(MiqReportingWorker::Runner) ID [1000000000360] PID [510591] GUID [122b62a3-46f8-4b8d-a615-2c5be88fb213] Error in update_worker_record_at_exit: PG::UnableToSend: server closed the connection unexpectedly
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:48.706385 #510583:2b162884196c] ERROR – : MIQ(MiqPriorityWorker::Runner) ID [1000000000356] PID [510583] GUID [ae3443e4-f796-4ac1-ace6-374e4ec1d7de] Error in update_worker_record_at_exit: PG::UnableToSend: server closed the connection unexpectedly
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:48.706734 #510583:2b162884196c] ERROR – : MIQ(MiqPriorityWorker::Runner) ID [1000000000356] PID [510583] GUID [ae3443e4-f796-4ac1-ace6-374e4ec1d7de] Failed to register worker with worker monitor: DRb::DRbConnError: drbunix:///tmp/worker_monitor20201211-510275-1gw7cp - #<Errno::ENOENT: No such file or directory - connect(2) for ///tmp/worker_monitor20201211-510275-1gw7cp> Worker exiting.
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:48.758895 #510581:2b11e346196c] ERROR – : MIQ(MiqPriorityWorker::Runner) ID [1000000000355] PID [510581] GUID [5398ca9b-674a-4d01-af7e-0434fcc91b85] Error in update_worker_record_at_exit: PG::UnableToSend: server closed the connection unexpectedly
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:48.759268 #510581:2b11e346196c] ERROR – : MIQ(MiqPriorityWorker::Runner) ID [1000000000355] PID [510581] GUID [5398ca9b-674a-4d01-af7e-0434fcc91b85] Failed to register worker with worker monitor: DRb::DRbConnError: drbunix:///tmp/worker_monitor20201211-510275-1gw7cp - #<Errno::ENOENT: No such file or directory - connect(2) for ///tmp/worker_monitor20201211-510275-1gw7cp> Worker exiting.
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:49.451292 #510585:2b1335a1b954] ERROR – : MIQ(MiqEventHandler::Runner) ID [1000000000357] PID [510585] GUID [ac635306-d8f1-40c3-b314-598b0969b333] Error in update_worker_record_at_exit: PG::UnableToSend: server closed the connection unexpectedly
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:49.452302 #510585:2b1335a1b954] ERROR – : MIQ(MiqEventHandler::Runner) ID [1000000000357] PID [510585] GUID [ac635306-d8f1-40c3-b314-598b0969b333] Failed to register worker with worker monitor: DRb::DRbConnError: drbunix:///tmp/worker_monitor20201211-510275-1gw7cp - #<Errno::ENOENT: No such file or directory - connect(2) for ///tmp/worker_monitor20201211-510275-1gw7cp> Worker exiting.
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:49.545255 #510579:2b2026927964] ERROR – : EMS [rsbt-istmosvc01.trosbank.trus.tsocgen] as [trbs-miqvcuser@trosbank.trus.tsocgen] ID [1000000000354] PID [510579] GUID [7bf7b689-d43b-4999-bf13-1158b8f88a5a] Error in update_worker_record_at_exit: PG::UnableToSend: server closed the connection unexpectedly
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:49.956079 #510596:2abcc3fb5964] ERROR – : MIQ(ManageIQ::Providers::Vmware::InfraManager::OperationsWorker::Runner) ID [1000000000362] PID [510596] GUID [ef248695-d905-4059-a0c0-18a5d90b3cca] Error in update_worker_record_at_exit: PG::UnableToSend: server closed the connection unexpectedly
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:49.956482 #510596:2abcc3fb5964] ERROR – : MIQ(ManageIQ::Providers::Vmware::InfraManager::OperationsWorker::Runner) ID [1000000000362] PID [510596] GUID [ef248695-d905-4059-a0c0-18a5d90b3cca] Failed to register worker with worker monitor: DRb::DRbConnError: drbunix:///tmp/worker_monitor20201211-510275-1gw7cp - #<Errno::ENOENT: No such file or directory - connect(2) for ///tmp/worker_monitor20201211-510275-1gw7cp> Worker exiting.
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:50.188059 #510593:2aeb423d595c] ERROR – : MIQ(MiqReportingWorker::Runner) ID [1000000000361] PID [510593] GUID [b32310fa-5f51-49db-8ce0-a9bf26ec69ca] Error in update_worker_record_at_exit: PG::UnableToSend: server closed the connection unexpectedly
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:50.189228 #510593:2aeb423d595c] ERROR – : MIQ(MiqReportingWorker::Runner) ID [1000000000361] PID [510593] GUID [b32310fa-5f51-49db-8ce0-a9bf26ec69ca] Failed to register worker with worker monitor: DRb::DRbConnError: drbunix:///tmp/worker_monitor20201211-510275-1gw7cp - #<Errno::ENOENT: No such file or directory - connect(2) for ///tmp/worker_monitor20201211-510275-1gw7cp> Worker exiting.
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:51.624013 #510575:2b05a7c0d3c0] ERROR – : MIQ(MiqWebServiceWorker::Runner) ID [1000000000352] PID [510575] GUID [82176e6c-c0f4-4cb7-903d-fc2406c30756] Error in update_worker_record_at_exit: could not connect to server: Connection refused
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:52.110466 #510601:2b0367453964] ERROR – : MIQ(ManageIQ::Providers::Vmware::InfraManager::RefreshWorker::Runner) ID [1000000000363] PID [510601] GUID [53b43fd7-2979-4b29-a52f-539b2fd97817] Error in update_worker_record_at_exit: PG::UnableToSend: no connection to the server
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:55.461879 #510577:2b16b432396c] ERROR – : EMS as [trbsmiqawx] ID [1000000000353] PID [510577] GUID [8fb38869-66a6-4816-8fd5-1f5d94730952] Error in update_worker_record_at_exit: PG::UnableToSend: server closed the connection unexpectedly
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:55.538342 #510571:2abf27c81958] ERROR – : MIQ(MiqScheduleWorker::Runner) ID [1000000000350] PID [510571] GUID [e9c6798c-1e19-498c-ab34-72973e40d798] Error in update_worker_record_at_exit: PG::UnableToSend: server closed the connection unexpectedly
/var/www/miq/vmdb/log/evm.log:[----] E, [2020-12-16T11:19:59.617126 #510570:2ae36d161b58] ERROR – : MIQ(MiqRemoteConsoleWorker::Runner) ID [1000000000349] PID [510570] GUID [4d444223-026b-4f1f-8489-f4244f479803] Error in update_worker_record_at_exit: could not connect to server: Cannot assign requested address
/var/www/miq/vmdb/log/evm.log:[----] W, [2020-12-16T11:41:59.519371 #2511:2ae589be8b80] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log:[----] W, [2020-12-16T11:41:59.534675 #2511:2ae589be8b80] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log:[----] W, [2020-12-16T11:42:19.074286 #2511:2ae589be6e0c] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log:[----] W, [2020-12-16T11:42:19.085692 #2511:2ae589be6e0c] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log:[----] W, [2020-12-16T11:42:23.375473 #2511:2ae589be8b80] WARN – : MIQ(ops_controller-tree_select): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log:[----] W, [2020-12-16T11:42:23.386922 #2511:2ae589be8b80] WARN – : MIQ(ops_controller-tree_select): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log:[----] W, [2020-12-16T11:43:45.534787 #2511:2ae589be6808] WARN – : MIQ(ops_controller-change_tab): workers Size 7825 Elements 1
/var/www/miq/vmdb/log/evm.log:[----] W, [2020-12-16T11:43:45.546028 #2511:2ae589be6808] WARN – : MIQ(ops_controller-change_tab): workers Size 7825 Elements 1
/var/www/miq/vmdb/log/evm.log:[----] W, [2020-12-16T11:43:51.155332 #2511:2ae589be9350] WARN – : MIQ(ops_controller-change_tab): workers Size 7825 Elements 1
/var/www/miq/vmdb/log/evm.log:[----] W, [2020-12-16T11:43:51.166413 #2511:2ae589be9350] WARN – : MIQ(ops_controller-change_tab): workers Size 7825 Elements 1
/var/www/miq/vmdb/log/evm.log:[----] W, [2020-12-16T11:43:57.918084 #2511:2ae589be8748] WARN – : MIQ(ops_controller-accordion_select): workers Size 7825 Elements 1
/var/www/miq/vmdb/log/evm.log:[----] W, [2020-12-16T11:43:57.929002 #2511:2ae589be8748] WARN – : MIQ(ops_controller-accordion_select): workers Size 7825 Elements 1
/var/www/miq/vmdb/log/evm.log:[----] W, [2020-12-16T11:44:58.287586 #2511:2ae589be8748] WARN – : MIQ(ops_controller-accordion_select): workers Size 7825 Elements 1
/var/www/miq/vmdb/log/evm.log:[----] W, [2020-12-16T11:44:58.298960 #2511:2ae589be8748] WARN – : MIQ(ops_controller-accordion_select): workers Size 7825 Elements 1
/var/www/miq/vmdb/log/evm.log-20201203.gz:[----] W, [2020-12-02T12:05:36.165539 #189891:2aae949ea184] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201203.gz:[----] W, [2020-12-02T12:05:36.211045 #189891:2aae949ea184] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201203.gz:[----] W, [2020-12-02T17:02:27.191980 #189596:2acb2cea596c] WARN – : MIQ(MiqServer#exceeded_memory_threshold?) Worker [MiqGenericWorker] with ID: [1000000000324], PID: [189908], GUID: [662a221d-5f2d-46c1-80f2-42711f449472] process memory usage [631736000] exceeded limit [629145600], requesting worker to exit
/var/www/miq/vmdb/log/evm.log-20201205.gz:[----] W, [2020-12-04T13:49:21.562775 #189891:2aae949edd84] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201205.gz:[----] W, [2020-12-04T13:49:21.591181 #189891:2aae949edd84] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201205.gz:[----] W, [2020-12-04T13:49:32.867900 #189891:2aae949ed80c] WARN – : MIQ(ops_controller-tree_select): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201205.gz:[----] W, [2020-12-04T13:49:32.962432 #189891:2aae949ed80c] WARN – : MIQ(ops_controller-tree_select): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201207.gz:[----] W, [2020-12-06T15:34:17.002348 #189891:2aae949ea8b4] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201207.gz:[----] W, [2020-12-06T15:34:17.034474 #189891:2aae949ea8b4] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201207.gz:[----] W, [2020-12-06T15:45:26.805782 #189891:2aae949ed80c] WARN – : MIQ(ops_controller-accordion_select): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201207.gz:[----] W, [2020-12-06T15:45:26.827306 #189891:2aae949ed80c] WARN – : MIQ(ops_controller-accordion_select): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201207.gz:[----] W, [2020-12-06T15:45:29.423130 #189891:2aae949edb54] WARN – : MIQ(ops_controller-change_tab): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201207.gz:[----] W, [2020-12-06T15:45:29.478372 #189891:2aae949edb54] WARN – : MIQ(ops_controller-change_tab): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201211.gz:[----] W, [2020-12-10T17:09:42.690718 #374083:2b128a3e5900] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201211.gz:[----] W, [2020-12-10T17:09:42.715200 #374083:2b128a3e5900] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201212.gz:[----] W, [2020-12-11T19:30:23.680291 #374083:2b128a3e4fb4] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201212.gz:[----] W, [2020-12-11T19:30:23.692219 #374083:2b128a3e4fb4] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201215.gz:[----] W, [2020-12-14T16:10:48.800120 #510573:2b1f9dc62bd0] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201215.gz:[----] W, [2020-12-14T16:10:48.812705 #510573:2b1f9dc62bd0] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201215.gz:[----] W, [2020-12-14T19:48:34.174779 #510573:2b1f9dc60c68] WARN – : MIQ(ops_controller-accordion_select): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201215.gz:[----] W, [2020-12-14T19:48:34.187048 #510573:2b1f9dc60c68] WARN – : MIQ(ops_controller-accordion_select): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201216.gz:[----] W, [2020-12-15T13:15:51.548447 #510573:2b1f9dc62bd0] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201216.gz:[----] W, [2020-12-15T13:15:51.562076 #510573:2b1f9dc62bd0] WARN – : MIQ(ops_controller-explorer): workers Size 7803 Elements 1
/var/www/miq/vmdb/log/evm.log-20201216.gz:[----] W, [2020-12-15T15:36:22.375648 #510275:2b1620a2d968] WARN – : MIQ(MiqServer#exceeded_memory_threshold?) Worker [MiqGenericWorker] with ID: [1000000000359], PID: [510589], GUID: [67789c91-7c57-4fb1-9aef-4656f9a60843] process memory usage [630108000] exceeded limit [629145600], requesting worker to exit

[pemcg]

@vmedvedev

[MiqGenericWorker] with ID: [1000000000359], PID: [510589], GUID: [67789c91-7c57-4fb1-9aef-4656f9a60843] process memory usage [630108000] exceeded limit [629145600], requesting worker to exit

Interesting, the search string has changed - my bad. This is exactly what I was hoping to see. Try increasing the thresholds for your generic workers, probably up to 1GB (generic workers process Automate tasks).

Hope this helps,
pemcg

[vmedvedev]

@pemcg thank you for your suggestions. I’ve increased memory threshold for workers. “memory usage” messages dissapeared but the problem with “Failed to load BinaryBlob” is still there.

This time I’ve got “WARN message “Failed to load BinaryBlob with ID [xxxxx] for MiqAeEngine::StateVarHash” and Ansible Tower Job run from state machine have failed because pshost variable have failed to pass (in fact all the ansible_* state vars were lost and the job template run with default variables).

I checked that the pshost var was set correctly on preretirement state:

[----] I, [2020-12-24T17:53:20.117637 #256659:2b1e0116c5e8] INFO – : Q-task_id([r1000000000501_vm_retire_task_1000000000513]) Processing get_pshost…
[----] I, [2020-12-24T17:53:20.120186 #256659:2b1e0116c5e8] INFO – : Q-task_id([r1000000000501_vm_retire_task_1000000000513]) DEBUG m: pshost_lookup_strategy_manualbytag
[----] I, [2020-12-24T17:53:20.120576 #256659:2b1e0116c5e8] INFO – : Q-task_id([r1000000000501_vm_retire_task_1000000000513]) Processing pshost_lookup_strategy_manualbytag…
[----] I, [2020-12-24T17:53:20.125034 #256659:2b1e0116c5e8] INFO – : Q-task_id([r1000000000501_vm_retire_task_1000000000513]) Searching for pshost name with key [pshost_lookup_manualbytags_lookup_internal_test]
[----] I, [2020-12-24T17:53:20.127372 #256659:2b1e0116c5e8] INFO – : Q-task_id([r1000000000501_vm_retire_task_1000000000513]) DEBUG pshost from settings: XXXXXXXXXXXXXXXXXXXX

[vmedvedev]

@pemcg I’ve updated to jansa-2 from jansa-1 and found such messages in evm.log. Could they relate to this issue, what do you think? Changed limits :log_threshold to 250 kbytes, :element_threshold to 20 kbytes. Let’s see…

[----] W, [2020-12-28T13:19:22.147016 #359336:2aee3abc7ebc]  WARN -- : MIQ(ops_controller-explorer): Session object size of 103.3 KB exceeds threshold of 100 KB
[----] W, [2020-12-28T17:27:56.420485 #359336:2aee3abc7318]  WARN -- : MIQ(ops_controller-accordion_select): Session object size of 154 KB exceeds threshold of 100 KB
[----] W, [2020-12-28T17:28:14.176421 #359336:2aee3abc7a70]  WARN -- : MIQ(ops_controller-change_tab): Session object size of 188.5 KB exceeds threshold of 100 KB
[----] W, [2020-12-28T17:28:20.133489 #359336:2aee3abc2174]  WARN -- : MIQ(ops_controller-tree_select): Session object size of 154.5 KB exceeds threshold of 100 KB

[vmedvedev]

No more errors related to woker or session object size, but the problem still there. I’ve found this error which seems to be related with this issue. Investigating further.

[----] I, [2021-01-22T12:05:20.504423 #1132708:2af4e273d974]  INFO -- : Q-task_id([r1000000000624_service_template_provision_task_1000000000641]) MIQ(MiqQueue#deliver) Message id: [1000001912924], Delivering...
[----] I, [2021-01-22T12:05:20.508976 #1132708:2af4e273d974]  INFO -- : Q-task_id([r1000000000624_service_template_provision_task_1000000000641]) MIQ(MiqAeEngine.deliver) Delivering {:event_type=>:service_provisioned, "Miq
Event::miq_event"=>1000000015905, :miq_event_id=>1000000015905, "EventStream::event_stream"=>1000000015905, :event_stream_id=>1000000015905} for object [Service.1000000000233] with state [] to Automate
[----] E, [2021-01-22T12:05:20.512625 #1132708:2af4e273d974] ERROR -- : Q-task_id([r1000000000624_service_template_provision_task_1000000000641]) MIQ(MiqQueue#deliver) Message id: [1000001912924], Error: [Couldn't find Ser
vice]
[----] E, [2021-01-22T12:05:20.512809 #1132708:2af4e273d974] ERROR -- : Q-task_id([r1000000000624_service_template_provision_task_1000000000641]) [ActiveRecord::RecordNotFound]: Couldn't find Service  Method:[block (2 leve
ls) in <class:LogProxy>]
[----] E, [2021-01-22T12:05:20.512919 #1132708:2af4e273d974] ERROR -- : Q-task_id([r1000000000624_service_template_provision_task_1000000000641]) /opt/manageiq/manageiq-gemset/gems/activerecord-5.2.4.4/lib/active_record/core.rb:217:in `find_by!'
/opt/manageiq/manageiq-gemset/bundler/gems/manageiq-automation_engine-f0185addb172/lib/miq_automation_engine/engine/miq_ae_engine.rb:85:in `deliver'
/var/www/miq/vmdb/app/models/miq_queue.rb:484:in `block in dispatch_method'
/usr/share/ruby/timeout.rb:93:in `block in timeout'
/usr/share/ruby/timeout.rb:33:in `block in catch'
/usr/share/ruby/timeout.rb:33:in `catch'
/usr/share/ruby/timeout.rb:33:in `catch'
/usr/share/ruby/timeout.rb:108:in `timeout'
/var/www/miq/vmdb/app/models/miq_queue.rb:482:in `dispatch_method'
/var/www/miq/vmdb/app/models/miq_queue.rb:459:in `block in deliver'
/var/www/miq/vmdb/app/models/user.rb:317:in `with_user'
/var/www/miq/vmdb/app/models/user.rb:332:in `with_user_group'
/var/www/miq/vmdb/app/models/miq_queue.rb:459:in `deliver'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:80:in `deliver_queue_message'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:104:in `deliver_message'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:122:in `block in do_work'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:118:in `loop'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:118:in `do_work'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:256:in `block in do_work_loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:253:in `loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:253:in `do_work_loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:113:in `run'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:95:in `start'
/var/www/miq/vmdb/lib/workers/bin/run_single_worker.rb:113:in `<main>'
[----] I, [2021-01-22T12:05:20.513043 #1132708:2af4e273d974]  INFO -- : Q-task_id([r1000000000624_service_template_provision_task_1000000000641]) MIQ(MiqQueue#delivered) Message id: [1000001912924], State: [error], Delivered in [0.008648454] seconds

[vmedvedev]

It seems that the problem is related to binary blob purging mechanism. 3 blobs purged and 3 tasks finally failed.

@pemcg could you please help how this purging mechanism can be tuned? Now the binary_blob_purge_interval is set to default 1.hour. All the tasks inbetween purging are ok. All three tasks running during purging - failed.

evm.log
[----] I, [2021-01-22T16:34:06.232508 #1172161:2b0472885954] INFO – : MIQ(BinaryBlob.purge_by_scope) Purging Binary blobs…
[----] I, [2021-01-22T16:34:06.233984 #1172161:2b0472885954] INFO – : MIQ(BinaryBlob.purge_in_batches) Purging 3 Binary blobs.
[----] I, [2021-01-22T16:34:06.236919 #1172161:2b0472885954] INFO – : MIQ(BinaryBlob.purge_by_scope) Purging Binary blobs…Complete - Deleted 3 records

automation.log
[----] W, [2021-01-22T16:34:46.175922 #1172161:2b0472885954] WARN – : Q-task_id([r1000000000655_service_template_provision_task_1000000000679]) Failed to load BinaryBlob with ID [1000000012727] for MiqAeEngine::StateVarHash
[----] W, [2021-01-22T16:35:03.448877 #1172159:2aef14ab394c] WARN – : Q-task_id([r1000000000657_service_template_provision_task_1000000000681]) Failed to load BinaryBlob with ID [1000000012728] for MiqAeEngine::StateVarHash
[----] W, [2021-01-22T16:35:03.698953 #1172161:2b0472885954] WARN – : Q-task_id([r1000000000652_vm_retire_task_1000000000676]) Failed to load BinaryBlob with ID [1000000012729] for MiqAeEngine::StateVarHash