search

ManageIQ / manageiq

ManageIQ Open-Source Management Platform
https://manageiq.org
Apache License 2.0
1.34k stars 897 forks source link

Looping TypeError in logs after upgrade from Morphy to Petrosian #23081

Open pint2oo opened 2 months ago

pint2oo commented 2 months ago

1. Describe the issue you are having and what you expected to happen

Hi, After upgrading from Morphy to Petrosian, the evmserverd service never fully starts due to it looping on the following error: 

Jul 07 12:32:11 dbappliance.domain.tld evm[3980]:  INFO -- evm: MIQ(MiqReport#remove_associated_schedules) Schedule id: 1000000000083, targets: [1000000000255]
Jul 07 12:32:11 dbappliance.domain.tld evm[3980]: ERROR -- evm: [TypeError]: no implicit conversion of nil into Array  Method:[block (2 levels) in <class:LogProxy>]
Jul 07 12:32:11 dbappliance.domain.tld evm[3980]: ERROR -- evm: /var/www/miq/vmdb/lib/miq_expression/target.rb:173:in `+'
...(see archive below for more details including stack trace and DEBUG logs)...

This error happens in the log right after a series of "MiqReport#remove_associated_schedules" lines, so we suspect it might be something wrong with one or more scheduled reports.

There were no error messages regarding this schedule or its associated report during previous steps of the upgrade process (when restoring our data into the new DB, during db:upgrade, etc). And we've upgraded others environments with scheduled reports successfully.

2. Steps to reproduce, including any log snippets and stack traces that will help diagnose

  1. Dump the DB on a Morphy appliance : pg_dumpall -c --if-exists | gzip > /mnt/bdd_dump/vmdb-morphy.pg.gz
  2. Import into a brand new Petrosian appliance : gunzip < /mnt/bdd_dump/vmdb-morphy.pg.gz | psql postgres
  3. Run : rake db:migrate then rake evm:automate:reset
  4. Start evmserverd

Zipped logs (DEBUG level): debug_logs.zip

We've had to rollback, but we kept the appliance around in case any more logs are needed.

Fryguy commented 2 months ago

@jrafanie Have you seen this one before? @kbrock Do you recall any changes in the MiqExpression bit here? I'm wondering if we missed a data migration.

jrafanie commented 2 months ago

looks like this method is blowing up because @associations is nil

https://github.com/ManageIQ/manageiq/blob/8484fee0f73a0d0a8aa3c1d6f80c8a0a4461e22e/lib/miq_expression/target.rb#L172-L174

jrafanie commented 2 months ago

It looks like it's blowing up during seeding when removing no longer existing reports, we try to remove reports generated for different targets using that report:

Jul 07 12:32:03 dbappliance.domain.tld evm[3958]:  INFO -- evm: MIQ(MiqReport.seed) Deleting the following MiqReport(s) as they no longer exist: "1000_IBM Power - Storage/010_PVMs_ Storage.yaml", "1000_IBM Power - Storage/011_PVMs Storage.yaml", "1000_IBM Power - Storage/012_PVMs Storage.yaml", "1000_IBM Power - Virtual Machines/010_PVMs_ Hardware.yaml", "1000_IBM Power - Virtual Machines/011_PVMs_ Hardware.yaml", "1000_IBM Power - Virtual Machines/012_PVMs_ Hardware.yaml"
Jul 07 12:32:03 dbappliance.domain.tld production[3958]: DEBUG -- production:   MiqReport Load (0.4ms)  SELECT "miq_reports".* FROM "miq_reports" WHERE "miq_reports"."id" IN ($1, $2, $3, $4, $5, $6)  [["id", 1000000000262], ["id", 1000000000263], ["id", 1000000000264], ["id", 1000000000265], ["id", 1000000000266], ["id", 1000000000267]]
Jul 07 12:32:03 dbappliance.domain.tld production[3958]: DEBUG -- production:   MiqReport Inst Including Associations (0.1ms - 6rows)
Jul 07 12:32:03 dbappliance.domain.tld evm[3958]:  INFO -- evm: MIQ(MiqReport#remove_associated_schedules) Removing any schedules associated with report: 1000000000262
Jul 07 12:32:03 dbappliance.domain.tld production[3958]: DEBUG -- production:   MiqSchedule Load (0.5ms)  SELECT "miq_schedules".* FROM "miq_schedules" WHERE "miq_schedules"."resource_type" = $1  [["resource_type", "MiqReport"]]
Jul 07 12:32:03 dbappliance.domain.tld production[3958]: DEBUG -- production:   MiqSchedule Inst Including Associations (19.0ms - 24rows)
Jul 07 12:32:03 dbappliance.domain.tld production[3958]: DEBUG -- production:   User Load (0.2ms)  SELECT "users".* FROM "users" WHERE "users"."id" BETWEEN $1 AND $2 AND "users"."userid" IS NULL LIMIT $3  [["id", 1000000000000], ["id", 1999999999999], ["LIMIT", 1]]
Jul 07 12:32:03 dbappliance.domain.tld production[3958]: DEBUG -- production:   User Inst Including Associations (0.0ms - 0rows)
Jul 07 12:32:03 dbappliance.domain.tld production[3958]: DEBUG -- production:    (0.4ms)  SELECT "miq_reports"."id" FROM "miq_reports" WHERE ("miq_reports"."id" = 1000000000148)
Jul 07 12:32:03 dbappliance.domain.tld evm[3958]:  INFO -- evm: MIQ(MiqReport#remove_associated_schedules) Schedule id: 1000000000061, targets: [1000000000148]
Jul 07 12:32:03 dbappliance.domain.tld production[3958]: DEBUG -- production:   User Load (0.3ms)  SELECT "users".* FROM "users" WHERE "users"."id" BETWEEN $1 AND $2 AND "users"."userid" IS NULL LIMIT $3  [["id", 1000000000000], ["id", 1999999999999], ["LIMIT", 1]]
Jul 07 12:32:03 dbappliance.domain.tld production[3958]: DEBUG -- production:   User Inst Including Associations (0.0ms - 0rows)
Jul 07 12:32:03 dbappliance.domain.tld production[3958]: DEBUG -- production:    (0.4ms)  SELECT "miq_reports"."id" FROM "miq_reports" WHERE ("miq_reports"."id" = 1000000000152)
Jul 07 12:32:03 dbappliance.domain.tld evm[3958]:  INFO -- evm: MIQ(MiqReport#remove_associated_schedules) Schedule id: 1000000000063, targets: [1000000000152]
...
Jul 07 12:32:03 dbappliance.domain.tld evm[3958]:  INFO -- evm: MIQ(MiqReport#remove_associated_schedules) Schedule id: 1000000000083, targets: [1000000000255]
Jul 07 12:32:03 dbappliance.domain.tld production[3958]: DEBUG -- production:   User Load (0.1ms)  SELECT "users".* FROM "users" WHERE "users"."id" BETWEEN $1 AND $2 AND "users"."userid" IS NULL LIMIT $3  [["id", 1000000000000], ["id", 1999999999999], ["LIMIT", 1]]
Jul 07 12:32:03 dbappliance.domain.tld production[3958]: DEBUG -- production:   User Inst Including Associations (0.0ms - 0rows)
Jul 07 12:32:03 dbappliance.domain.tld production[3958]: DEBUG -- production:   MiqReport Load (1.7ms)  SELECT "miq_reports".* FROM "miq_reports"
Jul 07 12:32:03 dbappliance.domain.tld production[3958]: DEBUG -- production:   MiqReport Inst Including Associations (1.7ms - 276rows)
Jul 07 12:32:03 dbappliance.domain.tld production[3958]: DEBUG -- production:   TRANSACTION (0.3ms)  ROLLBACK
Jul 07 12:32:04 dbappliance.domain.tld evm[3958]: ERROR -- evm: [TypeError]: no implicit conversion of nil into Array  Method:[block (2 levels) in <class:LogProxy>]
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]: /var/www/miq/vmdb/lib/miq_expression/target.rb:173:in `+': no implicit conversion of nil into Array (TypeError)
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/lib/miq_expression/target.rb:173:in `tag_values'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/lib/miq_expression/target.rb:169:in `tag_path'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/lib/miq_expression/target.rb:123:in `tag_path_with'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/lib/miq_expression.rb:716:in `operands2rubyvalue'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/lib/miq_expression.rb:201:in `_to_ruby'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/lib/miq_expression.rb:184:in `to_ruby'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/lib/miq_expression.rb:574:in `lenient_evaluate'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/lib/rbac/filterer.rb:884:in `matches_search_filters?'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/lib/rbac/filterer.rb:347:in `block in search'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/relation/delegation.rb:88:in `each'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/lib/rbac/filterer.rb:369:in `each'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/lib/rbac/filterer.rb:369:in `to_a'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/lib/rbac/filterer.rb:369:in `search'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/lib/rbac/filterer.rb:176:in `search'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/lib/rbac.rb:3:in `search'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/lib/rbac/filterer.rb:442:in `filtered'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/lib/rbac/filterer.rb:180:in `filtered'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/lib/rbac.rb:11:in `filtered'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/app/models/miq_schedule.rb:130:in `target_ids'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /var/www/miq/vmdb/app/models/miq_report/schedule.rb:11:in `block in remove_associated_schedules'
Jul 07 12:32:04 dbappliance.domain.tld ruby[3958]:         from /opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/relation/delegation.rb:88:in `each'
Jul 07 12:32:04 dbappliance.domain.tld evm[3958]: ERROR -- evm: /var/www/miq/vmdb/lib/miq_expression/target.rb:173:in `+'
                                                            /var/www/miq/vmdb/lib/miq_expression/target.rb:173:in `tag_values'
                                                            /var/www/miq/vmdb/lib/miq_expression/target.rb:169:in `tag_path'
                                                            /var/www/miq/vmdb/lib/miq_expression/target.rb:123:in `tag_path_with'
                                                            /var/www/miq/vmdb/lib/miq_expression.rb:716:in `operands2rubyvalue'
                                                            /var/www/miq/vmdb/lib/miq_expression.rb:201:in `_to_ruby'
                                                            /var/www/miq/vmdb/lib/miq_expression.rb:184:in `to_ruby'
                                                            /var/www/miq/vmdb/lib/miq_expression.rb:574:in `lenient_evaluate'
                                                            /var/www/miq/vmdb/lib/rbac/filterer.rb:884:in `matches_search_filters?'
                                                            /var/www/miq/vmdb/lib/rbac/filterer.rb:347:in `block in search'
                                                            /opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/relation/delegation.rb:88:in `each'
                                                            /opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/relation/delegation.rb:88:in `each'
                                                            /var/www/miq/vmdb/lib/rbac/filterer.rb:369:in `each'
                                                            /var/www/miq/vmdb/lib/rbac/filterer.rb:369:in `each'
                                                            /var/www/miq/vmdb/lib/rbac/filterer.rb:369:in `each'
                                                            /var/www/miq/vmdb/lib/rbac/filterer.rb:369:in `to_a'
                                                            /var/www/miq/vmdb/lib/rbac/filterer.rb:369:in `search'
                                                            /var/www/miq/vmdb/lib/rbac/filterer.rb:176:in `search'
                                                            /var/www/miq/vmdb/lib/rbac.rb:3:in `search'
                                                            /var/www/miq/vmdb/lib/rbac/filterer.rb:442:in `filtered'
                                                            /var/www/miq/vmdb/lib/rbac/filterer.rb:180:in `filtered'
                                                            /var/www/miq/vmdb/lib/rbac.rb:11:in `filtered'
                                                            /var/www/miq/vmdb/app/models/miq_schedule.rb:130:in `target_ids'
                                                            /var/www/miq/vmdb/app/models/miq_report/schedule.rb:11:in `block in remove_associated_schedules'
                                                            /opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/relation/delegation.rb:88:in `each'
                                                            /opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/relation/delegation.rb:88:in `each'
                                                            /var/www/miq/vmdb/app/models/miq_report/schedule.rb:10:in `remove_associated_schedules'

gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:427:in `block in make_lambda'
                                                            /opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:198:in `block (2 levels) in halting'
                                                            /opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:604:in `block (2 levels) in default_terminator'
                                                            /opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:603:in `catch'
                                                            /opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:603:in `block in default_terminator'
                                                            /opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:199:in `block in halting'
                                                            /opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:512:in `block in invoke_before'
                                                            /opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:512:in `each'
                                                            /opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:512:in `invoke_before'
                                                            /opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:105:in `run_callbacks'
                                                            /opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:824:in `_run_destroy_callbacks'
                                                            /opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/callbacks.rb:439:in `destroy'
                                                            /opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/transactions.rb:294:in `block in destroy'
                                                            /opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/transactions.rb:354:in `block in with_transaction_returning_status'
                                                            /opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/connection_adapters/abstract/database_statements.rb:318:in `transaction'
                                                            /opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/transactions.rb:350:in `with_transaction_returning_status'
                                                            /opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/transactions.rb:294:in `destroy'
                                                            /opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/persistence.rb:327:in `each'
                                                            /opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/persistence.rb:327:in `destroy'
                                                            /var/www/miq/vmdb/app/models/miq_report/seeding.rb:29:in `block in seed'
                                                            /opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/connection_adapters/abstract/database_statements.rb:318:in `transaction'
                                                            /opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/transactions.rb:209:in `transaction'
                                                            /var/www/miq/vmdb/app/models/miq_report/seeding.rb:9:in `seed'
jrafanie commented 2 months ago

@kbrock Can you take a look at this? I can't see where we're creating normal MiqExpression::Target objects, but I do see InvalidTargets being created with nil associations from this commit:

19ae1364de19b223d2f3ee8ae407c6820d7eeb78

EDIT: specifically super(nil, nil, nil)

I don't understand invalid targets to know if they should implement tag_path / tag_values with "" or []

The base Target class implements these and if the target is an invalid one, @associations will be nil.

kbrock commented 2 months ago

@jrafanie Well, setting @associations = [] would fix the first error. But that runs into the issue that column is also nil. So this will generate an MiqExpression with a <value /> node of /virtual/. This makes no sense and possibly will just throw an error while evaluating the expression.

Why does the MiqExpression have an invalid target at all?

I read remove_associated_schedules as saying, find all the schedules that say to run this report. Now, there is no foreign key, so it is filtering out all schedules that run a similar report (resource_type used to be called towhat and it has a value like Widget, MiqReport or even Vm). And then it tries to match the id (target_id) which is determined via expression. In my db, all the expressions are of the form: {"="=>{"field"=>"MiqReport-id", "value"=>11}} with a majority pointing to MiqWidget. Theoretically a schedule item could run multiple reports, but I have yet to see that in practice.

So it confuses me that such a small and simple expression could have an invalid expression. Also, if it is an invalid expression, then it would not run and probably would have printed more exceptions in the log at a previous date. But hopefully looking at one of these will answer more questions.

@pint2oo Do you know how to use rails console? Would it be possible to run a command on your console? You can run this from Morphy or Petrosian.

ssh appliance
vmdb # alias to change to our directory
./bin/rails c
schedule = MiqSchedule.find(1000000000083)  # the expression causing issues
puts "#{schedule.resource_type} :: #{schedule.filter.exp.inspect}"

We're expecting something that looks like this:

MiqWidged :: {"="=>{"field"=>"MiqWidget-id", "value"=>27}}

It is the field portion that is causing the issue. Hopefully it will show us right away why it is making all this fuss.

Thank you, Keenan

bryanfrancois commented 2 months ago

Hi @kbrock , I'm working with @pint2oo on this upgrade, i'll answer while he's on holidays. I ran the commands that you suggested and this is the output i got : 

MiqReport :: {"="=>{"field"=>"MiqReport-id", "value"=>1000000000255}}
=> nil

Thank you, Bryan

jrafanie commented 2 months ago

Is it just a missing report?

Does that report exist?

ssh appliance
vmdb # alias to change to our directory
./bin/rails c
puts MiqReport.find(1000000000255)

Does it blow up with a missing record, or display a report?

kbrock commented 2 months ago

@jrafanie I tried changing a schedule's expression to point to a report id that was not valid. it just returned an empty array.

Is there some incompatibility in the schedules that we haven't seen yet? If you go over all schedules, how many of them can not determine the target_ids?

ssh appliance
vmdb # alias to change to our directory
./bin/rails c

MiqSchedule.all.each {|ms| puts "#{ms.id} #{ms.get_filter.exp}" ; puts "==> #{ms.target_ids rescue "BAD"}" }.count

We're looking for the phrase "BAD" on the screen. Unfortunately, get_filter does queries, so it will sprinkle sql queries into there.

jrafanie commented 2 months ago

interesting @kbrock, let's see what is found...

So, schedule targets are users/groups. Is it possible we have a schedule report/widget generation for a user that doesn't exists anymore? We're supposed to clean these up when the user is removed but it's possible it was missed.

kbrock commented 1 month ago

@pint2oo @bryanfrancois did you get a chance to run that query and find the reports that display BAD on the screen?

mathieu-ui commented 4 weeks ago

Hi @kbrock, I'm working with @pint2oo and @bryanfrancois. I ran the command on Morphy, and this is the result I got:

irb(main):001:0> MiqSchedule.all.each {|ms| puts "#{ms.id} #{ms.get_filter.exp}" ; puts "==> #{ms.target_ids rescue "BAD"}" }.count
PostgreSQLAdapter#log_after_checkout, connection_pool: size: 20, connections: 1, in use: 1, waiting_in_queue: 0
1000000000061 {"="=>{"field"=>"MiqReport-id", "value"=>1000000000148}}
==> [1000000000148]
1000000000063 {"="=>{"field"=>"MiqReport-id", "value"=>1000000000152}}
==> [1000000000152]
1000000000068 {"="=>{"field"=>"MiqReport-id", "value"=>1000000000070}}
==> [1000000000070]
Traceback (most recent call last):
       15: from bin/rails:4:in `<main>'
       14: from bin/rails:4:in `require'
       13: from railties (6.0.4.4) lib/rails/commands.rb:18:in `<top (required)>'
       12: from railties (6.0.4.4) lib/rails/command.rb:46:in `invoke'
       11: from railties (6.0.4.4) lib/rails/command/base.rb:69:in `perform'
       10: from thor (1.1.0) lib/thor.rb:392:in `dispatch'
        9: from thor (1.1.0) lib/thor/invocation.rb:127:in `invoke_command'
        8: from thor (1.1.0) lib/thor/command.rb:27:in `run'
        7: from railties (6.0.4.4) lib/rails/commands/console/console_command.rb:102:in `perform'
        6: from railties (6.0.4.4) lib/rails/commands/console/console_command.rb:19:in `start'
        5: from railties (6.0.4.4) lib/rails/commands/console/console_command.rb:70:in `start'
        4: from (irb):1
        3: from activerecord (6.0.4.4) lib/active_record/relation/delegation.rb:88:in `each'
        2: from activerecord (6.0.4.4) lib/active_record/relation/delegation.rb:88:in `each'
        1: from (irb):1:in `block in irb_binding'
NoMethodError (undefined method `exp' for nil:NilClass)

The output being in error I try this to delete "exp", and this is what came out:

irb(main):002:0> MiqSchedule.all.each {|ms| puts "#{ms.id} #{ms.get_filter}" ; puts "==> #{ms.target_ids rescue "BAD"}" }.count
1000000000061 #<MiqExpression:0x00005579c9256960>
==> [1000000000148]
1000000000063 #<MiqExpression:0x00005579c9279d48>
==> [1000000000152]
1000000000068 #<MiqExpression:0x00005579c929cf50>
==> [1000000000070]
1000000000058 
==> []
1000000000059 #<MiqExpression:0x00005579c96d6da0>
==> [1000000000129]
1000000000090 #<MiqExpression:0x00005579ca916c90>
==> [1000000000081]
1000000000017 #<MiqExpression:0x00005579ca91ca78>
==> [1000000000014]
1000000000100 #<MiqExpression:0x00005579cab28e98>
==> [1000000000298]
1000000000042 #<MiqExpression:0x00005579cab31bd8>
==> [1000000000140]
1000000000091 #<MiqExpression:0x00005579cab3a2d8>
==> [1000000000057]
1000000000092 #<MiqExpression:0x00005579cab42370>
==> [1000000000280]
1000000000004 #<MiqExpression:0x00005579cab49fa8>
==> [1000000000004]
1000000000087 #<MiqExpression:0x00005579cab847e8>
==> [1000000000272]
1000000000088 #<MiqExpression:0x00005579cab93860>
==> [1000000000082]
1000000000064 #<MiqExpression:0x00005579cab9bf38>
==> [1000000000129]
1000000000076 #<MiqExpression:0x00005579cab9c758>
==> [1000000000225]
1000000000043 #<MiqExpression:0x00005579caba4930>
==> [1000000000133]
1000000000098 #<MiqExpression:0x00005579cabacb80>
==> [1000000000293]
1000000000099 #<MiqExpression:0x00005579cabb5460>
==> [1000000000004]
1000000000023 #<MiqExpression:0x00005579cabbc0f8>
==> [1000000000020]
1000000000050 #<MiqExpression:0x00005579cabc9e10>
==> [1000000000040]
1000000000046 #<MiqExpression:0x00005579cabd7718>
==> [1000000000036]
1000000000096 #<MiqExpression:0x00005579cabdd460>
==> [1000000000059]
1000000000001 #<MiqExpression:0x00005579cabeb3f8>
==> [1000000000001]
1000000000044 #<MiqExpression:0x00005579cac3f520>
==> [1000000000140]
1000000000085 #<MiqExpression:0x00005579cac49228>
==> [1000000000257]
1000000000018 #<MiqExpression:0x00005579cac50500>
==> [1000000000015]
1000000000101 #<MiqExpression:0x00005579cac9fa60>
==> [1000000000061]
1000000000081 #<MiqExpression:0x00005579caca69a0>
==> [1000000013650, 1000000013413, 1000000013422, 1000000013798, 1000000013643, 1000000013419, 1000000013414, 1000000013424, 1000000013741, 1000000013425, 1000000013756, 1000000013426, 1000000013734, 1000000013415, 1000000013596, 1000000013727, 1000000013467, 1000000013681, 1000000013682, 1000000013421, 1000000013498, 1000000013420, 1000000013542, 1000000013423, 1000000013553, 1000000013496, 1000000013789, 1000000013680, 1000000006722, 1000000007803, 1000000013667, 1000000013792, 1000000012807, 1000000013385, 1000000011707, 1000000003572, 1000000006723, 1000000012635, 1000000007806, 1000000004388, 1000000007804, 1000000005304, 1000000011126, 1000000009788, 1000000013221, 1000000003477, 1000000006821, 1000000012763, 1000000004940, 1000000011489, 1000000003719, 1000000012461, 1000000012529, 1000000012531, 1000000004557]
1000000000071 #<MiqExpression:0x00005579cf69e698>
==> [1000000000050]
1000000000060 
==> []
1000000000052 #<MiqExpression:0x00005579cf6a5060>
==> [1000000000042]
1000000000095 #<MiqExpression:0x00005579cf6b3e08>
==> [1000000000290]
1000000000066 #<MiqExpression:0x00005579cf6bb608>
==> []
1000000000009 #<MiqExpression:0x00005579cf6c2318>
==> [1000000000009]
1000000000013 #<MiqExpression:0x00005579cf706d60>
==> [1000000000011]
1000000000083 #<MiqExpression:0x00005579cf74b3e8>
==> [1000000000255]
1000000000051 #<MiqExpression:0x00005579cf752b70>
==> [1000000000041]
1000000000033 #<MiqExpression:0x00005579cf759718>
==> [1000000000030]
1000000000078 #<MiqExpression:0x00005579cf79ddf0>
==> []
1000000000002 #<MiqExpression:0x00005579c3187508>
==> [1000000000002]
1000000000036 #<MiqExpression:0x00005579c36d37f0>
==> [1000000000140]
1000000000072 #<MiqExpression:0x00005579c37ad0e0>
==> [1000000000051]
1000000000053 #<MiqExpression:0x00005579c385abc8>
==> [1000000000043]
1000000000048 #<MiqExpression:0x00005579c39348a0>
==> [1000000000038]
1000000000012 #<MiqExpression:0x00005579c39fb8d8>
==> [1000000000010]
1000000000003 #<MiqExpression:0x00005579c3ee9e80>
==> [1000000000003]
1000000000094 #<MiqExpression:0x00005579c477bb98>
==> [1000000000058]
1000000000031 #<MiqExpression:0x00005579c4850f00>
==> [1000000000028]
1000000000008 #<MiqExpression:0x00005579c91d1238>
==> [1000000000008]
1000000000040 #<MiqExpression:0x00005579c974e3f0>
==> [1000000000033]
1000000000045 #<MiqExpression:0x00005579c9812c50>
==> [1000000000035]
1000000000047 #<MiqExpression:0x00005579c982ef40>
==> [1000000000037]
1000000000034 #<MiqExpression:0x00005579c9849840>
==> [1000000000031]
1000000000032 #<MiqExpression:0x00005579c997ae30>
==> [1000000000029]
1000000000074 #<MiqExpression:0x00005579c9ac4ac0>
==> [1000000000053]
1000000000067 #<MiqExpression:0x00005579c99f7598>
==> [1000000000048]
1000000000041 #<MiqExpression:0x00005579c9a09ab8>
==> [1000000000034]
1000000000054 #<MiqExpression:0x00005579c9cb8598>
==> [1000000000044]
1000000000084 #<MiqExpression:0x00005579c9cd2d80>
==> [1000000000055]
1000000000049 #<MiqExpression:0x00005579c9ce83b0>
==> [1000000000039]
1000000000077 #<MiqExpression:0x00005579c9d07e40>
==> []
1000000000038 #<MiqExpression:0x00005579cf14f020>
==> [1000000000148]
1000000000093 #<MiqExpression:0x00005579cf4aaa30>
==> [1000000000151]
1000000000089 #<MiqExpression:0x00005579cf4b79d8>
==> [1000000000056]
1000000000055 #<MiqExpression:0x00005579cf4bc208>
==> [1000000000045]
1000000000070 #<MiqExpression:0x00005579cf4c8350>
==> [1000000000049]
1000000000097 #<MiqExpression:0x00005579cf4d4e48>
==> [1000000000060]
1000000000079 #<MiqExpression:0x00005579cf4e0f68>
==> []
1000000000019 #<MiqExpression:0x00005579cf8543e8>
==> [1000000000016]
1000000000082 #<MiqExpression:0x00005579cf8bf878>
==> [1000000000253]
1000000000037 #<MiqExpression:0x00005579cf8caca0>
==> [1000000000154]
1000000000075 #<MiqExpression:0x00005579c88b4fd8>
==> [1000000000054]
1000000000073 #<MiqExpression:0x00005579c8b0c880>
==> [1000000000052]
=> 74

Hope this can help,

Thank you.

Mathieu

kbrock commented 2 weeks ago

Thank you @mathieu-ui

Ok, so the entry after id: 1000000000068 threw an error (id: 1000000000058) since it had no filter. I'm sorry, I should have specified get_filter&.exp. Your followup is helpful.

Luckily target_ids does have a check for get_filter == nil, so that error will not occur in the app.

So my take away is you successfully ran MiqSchedule#target_ids for all scheduled items. Not sure why running this method at seed time would blow up.

I was hoping to see an miq expression with a bad "target" value.

@jrafanie or @Fryguy either of you have an opinion on this?

The only 2 ideas I can come up with are as follows:

  1. Run the above query hoping that we find an miq expression with a bad target. This time, we're adding the &. to account for nils.
MiqSchedule.all.each {|ms| puts "#{ms.id} #{ms.get_filter&.exp}" ; puts "==> #{ms.target_ids rescue "BAD"}" }.count
  1. Run the seeding but with a more targeted print statement.
diff --git a/app/models/miq_schedule.rb b/app/models/miq_schedule.rb
index 17034d5fe9..436dba549c 100644
--- a/app/models/miq_schedule.rb
+++ b/app/models/miq_schedule.rb
@@ -141,6 +141,12 @@ class MiqSchedule < ApplicationRecord
     end

     Rbac.filtered(resource_type, :filter => my_filter)
+  rescue => e
+    puts "==="
+    puts "=== error: #{e}"
+    puts "=== expression: #{(my_filter&.exp rescue "BAD") || "none"}"
+    puts "==="
+    raise
   end

   def get_filter

Would rake db:seed suffice?

mathieu-ui commented 2 weeks ago

Hello,

We re-run the new command in our migrated appliance in Petrosian version.

Here is the result command of the MiqSchedule.all.each {|ms| puts "#{ms.id} #{ms.get_filter&.exp}" ; puts "==> #{ms.target_ids rescue "BAD"}" }.count command: dump.zip

And here are the result of the rake db:seed command:

[root@digxxlrp000b vmdb]# rake db:seed
rake aborted!
TypeError: no implicit conversion of nil into Array
/var/www/miq/vmdb/lib/miq_expression/target.rb:173:in `+'
/var/www/miq/vmdb/lib/miq_expression/target.rb:173:in `tag_values'
/var/www/miq/vmdb/lib/miq_expression/target.rb:169:in `tag_path'
/var/www/miq/vmdb/lib/miq_expression/target.rb:123:in `tag_path_with'
/var/www/miq/vmdb/lib/miq_expression.rb:716:in `operands2rubyvalue'
/var/www/miq/vmdb/lib/miq_expression.rb:201:in `_to_ruby'
/var/www/miq/vmdb/lib/miq_expression.rb:184:in `to_ruby'
/var/www/miq/vmdb/lib/miq_expression.rb:574:in `lenient_evaluate'
/var/www/miq/vmdb/lib/rbac/filterer.rb:884:in `matches_search_filters?'
/var/www/miq/vmdb/lib/rbac/filterer.rb:347:in `block in search'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/relation/delegation.rb:88:in `each'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/relation/delegation.rb:88:in `each'
/var/www/miq/vmdb/lib/rbac/filterer.rb:369:in `each'
/var/www/miq/vmdb/lib/rbac/filterer.rb:369:in `each'
/var/www/miq/vmdb/lib/rbac/filterer.rb:369:in `each'
/var/www/miq/vmdb/lib/rbac/filterer.rb:369:in `to_a'
/var/www/miq/vmdb/lib/rbac/filterer.rb:369:in `search'
/var/www/miq/vmdb/lib/rbac/filterer.rb:176:in `search'
/var/www/miq/vmdb/lib/rbac.rb:3:in `search'
/var/www/miq/vmdb/lib/rbac/filterer.rb:442:in `filtered'
/var/www/miq/vmdb/lib/rbac/filterer.rb:180:in `filtered'
/var/www/miq/vmdb/lib/rbac.rb:11:in `filtered'
/var/www/miq/vmdb/app/models/miq_schedule.rb:130:in `target_ids'
/var/www/miq/vmdb/app/models/miq_report/schedule.rb:11:in `block in remove_associated_schedules'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/relation/delegation.rb:88:in `each'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/relation/delegation.rb:88:in `each'
/var/www/miq/vmdb/app/models/miq_report/schedule.rb:10:in `remove_associated_schedules'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:427:in `block in make_lambda'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:198:in `block (2 levels) in halting'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:604:in `block (2 levels) in default_terminator'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:603:in `catch'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:603:in `block in default_terminator'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:199:in `block in halting'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:512:in `block in invoke_before'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:512:in `each'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:512:in `invoke_before'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:105:in `run_callbacks'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:824:in `_run_destroy_callbacks'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/callbacks.rb:439:in `destroy'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/transactions.rb:294:in `block in destroy'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/transactions.rb:354:in `block in with_transaction_returning_status'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/connection_adapters/abstract/database_statements.rb:318:in `transaction'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/transactions.rb:350:in `with_transaction_returning_status'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/transactions.rb:294:in `destroy'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/persistence.rb:327:in `each'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/persistence.rb:327:in `destroy'
/var/www/miq/vmdb/app/models/miq_report/seeding.rb:29:in `block in seed'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/connection_adapters/abstract/database_statements.rb:318:in `transaction'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/transactions.rb:209:in `transaction'
/var/www/miq/vmdb/app/models/miq_report/seeding.rb:9:in `seed'
/var/www/miq/vmdb/lib/evm_database.rb:134:in `block (4 levels) in seed_classes'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/core_ext/benchmark.rb:14:in `ms'
/var/www/miq/vmdb/lib/evm_database.rb:134:in `block (3 levels) in seed_classes'
/var/www/miq/vmdb/lib/evm_database.rb:132:in `each'
/var/www/miq/vmdb/lib/evm_database.rb:132:in `block (2 levels) in seed_classes'
/var/www/miq/vmdb/lib/extensions/ar_table_lock.rb:21:in `block (2 levels) in with_lock'
/opt/manageiq/manageiq-gemset/gems/timeout-0.3.2/lib/timeout.rb:189:in `block in timeout'
/opt/manageiq/manageiq-gemset/gems/timeout-0.3.2/lib/timeout.rb:36:in `block in catch'
/opt/manageiq/manageiq-gemset/gems/timeout-0.3.2/lib/timeout.rb:36:in `catch'
/opt/manageiq/manageiq-gemset/gems/timeout-0.3.2/lib/timeout.rb:36:in `catch'
/opt/manageiq/manageiq-gemset/gems/timeout-0.3.2/lib/timeout.rb:198:in `timeout'
/var/www/miq/vmdb/lib/extensions/ar_table_lock.rb:21:in `block in with_lock'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/connection_adapters/abstract/database_statements.rb:320:in `block in transaction'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/connection_adapters/abstract/transaction.rb:319:in `block in within_new_transaction'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/connection_adapters/abstract/transaction.rb:317:in `within_new_transaction'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/connection_adapters/abstract/database_statements.rb:320:in `transaction'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/transactions.rb:209:in `transaction'
/var/www/miq/vmdb/lib/extensions/ar_table_lock.rb:15:in `with_lock'
/var/www/miq/vmdb/lib/evm_database.rb:131:in `block in seed_classes'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/core_ext/benchmark.rb:14:in `ms'
/var/www/miq/vmdb/lib/evm_database.rb:129:in `seed_classes'
/var/www/miq/vmdb/lib/evm_database.rb:83:in `block in seed'
/var/www/miq/vmdb/lib/evm_database.rb:67:in `with_seed'
/var/www/miq/vmdb/lib/evm_database.rb:75:in `seed'
/var/www/miq/vmdb/db/seeds.rb:8:in `<main>'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/dependencies.rb:326:in `load'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/dependencies.rb:326:in `block in load'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/dependencies.rb:299:in `load_dependency'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/dependencies.rb:326:in `load'
/opt/manageiq/manageiq-gemset/gems/railties-6.1.7.4/lib/rails/engine.rb:566:in `block in load_seed'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/execution_wrapper.rb:91:in `wrap'
/opt/manageiq/manageiq-gemset/gems/railties-6.1.7.4/lib/rails/engine.rb:640:in `block (2 levels) in <class:Engine>'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:126:in `instance_exec'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
/opt/manageiq/manageiq-gemset/gems/activesupport-6.1.7.4/lib/active_support/callbacks.rb:137:in `run_callbacks'
/opt/manageiq/manageiq-gemset/gems/railties-6.1.7.4/lib/rails/engine.rb:566:in `load_seed'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/tasks/database_tasks.rb:450:in `load_seed'
/opt/manageiq/manageiq-gemset/gems/activerecord-6.1.7.4/lib/active_record/railties/databases.rake:392:in `block (2 levels) in <main>'
/opt/manageiq/manageiq-gemset/gems/rake-13.0.6/exe/rake:27:in `<top (required)>'
Tasks: TOP => db:seed
(See full trace by running task with --trace)

STI cache is out of date in production, check that source files haven't been modified

Hope that help, Thanks, Mathieu