blocking_activity_logger: can't convert String into an exact number

[jakswa]

safe-pg-migrations/lib/safe-pg-migrations/plugins/blocking_activity_logger.rb

Lines 68 to 87 in 07a3551

	rescue ActiveRecord::LockWaitTimeout
	SafePgMigrations.say 'Lock timeout.', true
	queries =
	begin
	blocking_queries_retriever_thread.value
	rescue StandardError => e
	SafePgMigrations.say("Error while retrieving blocking queries: #{e}", true)
	nil
	end
	raise if queries.nil?
	if queries.empty?
	SafePgMigrations.say 'Could not find any blocking query.', true
	else
	SafePgMigrations.say(
	"Statement was being blocked by the following #{'query'.pluralize(queries.size)}:", true
	)
	SafePgMigrations.say '', true
	output_blocking_queries(queries)

currently debugging locally a (probably gem versioning) issue where this value has a string timestamp like:

[["select pg_sleep(300), id from table limit 1;", "2021-09-27 14:58:18.677782+00"]]

and then the time formatter blows up with:

can't convert String into an exact number
--
 0: /home/me/.rbenv/versions/2.7.3/lib/ruby/gems/2.7.0/gems/activesupport-5.2.6/lib/active_support/core_ext/time/calculations.rb:275:in `-'
 1: /home/me/.rbenv/versions/2.7.3/lib/ruby/gems/2.7.0/gems/activesupport-5.2.6/lib/active_support/core_ext/time/calculations.rb:275:in `minus_with_duration'
 2: /home/me/.rbenv/versions/2.7.3/lib/ruby/gems/2.7.0/gems/activesupport-5.2.6/lib/active_support/core_ext/time/calculations.rb:286:in `minus_with_coercion'
 3: /home/me/.rbenv/versions/2.7.3/lib/ruby/gems/2.7.0/gems/safe-pg-migrations-1.2.3/lib/safe-pg-migrations/plugins/blocking_activity_logger.rb:115:in `format_start_time'
 4: /home/me/.rbenv/versions/2.7.3/lib/ruby/gems/2.7.0/gems/safe-pg-migrations-1.2.3/lib/safe-pg-migrations/plugins/blocking_activity_logger.rb:100:in `block in output_blocking_queries'
 5: /home/me/.rbenv/versions/2.7.3/lib/ruby/gems/2.7.0/gems/safe-pg-migrations-1.2.3/lib/safe-pg-migrations/plugins/blocking_activity_logger.rb:100:in `each'
 6: /home/me/.rbenv/versions/2.7.3/lib/ruby/gems/2.7.0/gems/safe-pg-migrations-1.2.3/lib/safe-pg-migrations/plugins/blocking_activity_logger.rb:100:in `output_blocking_queries'
 [...]

[jakswa]

mid-testing on this patch, maybe it solves things for older gem versions (if that's the issue): jakswa@3077be4

     def format_start_time(start_time, reference_time = Time.now)
+      start_time = Time.parse(start_time) if start_time.is_a?(String)
       duration = (reference_time - start_time).round
       "transaction started #{duration} #{'second'.pluralize(duration)} ago"
     end

[rchoquet]

Hello @jakswa, thanks for the report!

Which version of PG and of the pg gem are you using?

Your fix looks right, but it might be valuable to identify the root cause.

[jakswa]

Hello @jakswa, thanks for the report!

No problem! I'm excited to try and guard against some of the blunders this gem seems to solve.

Which version of PG and of the pg gem are you using?

I was testing this locally on:

• PostgreSQL 13.4 (Ubuntu 13.4-0ubuntu0.21.04.1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 10.3.0-1ubuntu1) 10.3.0, 64-bit
• pg gem version 1.2.3

Your fix looks right, but it might be valuable to identify the root cause.

Agree. I tried some quick digs trying to find a version to alter and test, but I am in a bit of a time crunch in a big rails repo with lots of gem dependencies.

[rchoquet]

Ok, you could be missing the proper type_map_for_results on your PG connection, could you check the output of SafePgMigrations.alternate_connection.raw_connection.type_map_for_results?

For me it's PG::TypeMapByOid, I suspect yours could be the default one (PG::TypeMapAllStrings).
If that's the case, it might have to do with the version of activerecord you are using, that might create the connection without the proper defaults.

Could you please indicate the version of activerecord you are using so I can check?

(a proper fix in this case could be to assign the right type map for the alternate connection, so the PG client takes types into account)

[jakswa]

the above was on activerecord 5.2.6

[jakswa]

> SafePgMigrations.alternate_connection.raw_connection.type_map_for_results
=> #<PG::TypeMapByOid:0x0000560181136720>
``

[jakswa]

The last message got me thinking that we might have a monkey-patch or override in play somewhere messing with this, but so far my attempts at disabling random hooks/gems/etc have failed to get the issue to go away. So, that's saying: This could be a me/us issue if no one else can reproduce and maybe we're just settling in to maintain our forked patch.

If I find time to get a rails skeleton going to reproduce, I'll give that a go, so there's hope later maybe. Maybe I can get solid steps for reproduction.

[jakswa]

Haven't gotten around to find time for accurate reproduction steps, I'll close this until there's more movement. Sorry to leave it hanging around!

[ThHareau]

Hey @jakswa, I was lucky enough to reproduce this issue; it's now fixed :)