Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
pint2oo opened this issue Jul 9, 2024 · 14 comments
Open

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

pint2oo opened this issue Jul 9, 2024 · 14 comments
Assignees
Labels

Comments

@pint2oo
Copy link

pint2oo commented Jul 9, 2024

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.

@pint2oo pint2oo added the bug label Jul 9, 2024
@Fryguy
Copy link
Member

Fryguy commented Jul 9, 2024

@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
Copy link
Member

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

def tag_values
['virtual'] + @associations + [@column]
end

@jrafanie
Copy link
Member

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
Copy link
Member

jrafanie commented Jul 10, 2024

@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:

19ae136

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
Copy link
Member

kbrock commented Jul 19, 2024

@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
Copy link

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
Copy link
Member

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
Copy link
Member

kbrock commented Jul 19, 2024

@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
Copy link
Member

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
Copy link
Member

kbrock commented Aug 13, 2024

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

@mathieu-ui
Copy link

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
Copy link
Member

kbrock commented Sep 3, 2024

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
Copy link

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

@lamm
Copy link

lamm commented Oct 11, 2024

We just noticed that we can't delete reports on the ManageIq environment which throws this error when we try to migrate it.
I don't know if it's relevant to this issue but here is the error we get when trying to delete a report:

[----] E, [2024-10-11T14:28:33.387620 #2965:2b1dd838a6b4] ERROR -- evm: MIQ(report_controller-x_button): Report "toto": Error during 'miq_report_delete': undefined method `each_with_index' for "":String
Did you mean? each_line

On the GUI side we have this popup :
image

Hope that can help to resolve this issue.
Thanks for your help.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

7 participants