Bug 2324182

Summary:	rubygem-pg: FTBFS in Fedora Rawhide
Product:	[Fedora] Fedora	Reporter:	Vít Ondruch <vondruch>
Component:	rubygem-pg	Assignee:	Vít Ondruch <vondruch>
Status:	CLOSED ERRATA	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	medium	Docs Contact:
Priority:	unspecified
Version:	rawhide	CC:	anezbeda, fjanus, hhorak, ruby-packagers-sig, vondruch
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Linux
URL:	https://koschei.fedoraproject.org/package/rubygem-pg
Whiteboard:
Fixed In Version:	rubygem-pg-1.5.9-2.fc42	Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2024-11-25 10:32:30 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Vít Ondruch 2024-11-06 14:46:41 UTC

Description of problem:
Package rubygem-pg fails to build from source in Fedora Rawhide.

Version-Release number of selected component (if applicable):
1.5.7-1.fc41

Steps to Reproduce:
koji build --scratch f42 rubygem-pg-1.5.7-1.fc41.src.rpm

Additional info:
This package is tracked by Koschei. See:
https://koschei.fedoraproject.org/package/rubygem-pg

Reproducible: Always




Note that it fails everywhere from f39 to Rawhide. It also started to fail in roughly the same time frame. The only difference I can spot is actually the Kernel (!!!). I have also experimentally confirmed that the package fails to build with kernel-6.11.5-100.fc39.x86_64 while works just fine with kernel-6.9.7-100.fc39.x86_64. I'll try to narrow the specific Kernel.

Comment 1 Vít Ondruch 2024-11-06 16:43:18 UTC

According to my investigation, everything works fine up to kernel-6.9.12-100.fc39.x86_64. Then with `kernel-6.10.0-64.fc41.x86_64` (not that the first f39 version was kernel-6.10.3-100.fc39, which provides the same results), the problem begins:

~~~
Failures:

  1) with a Fiber scheduler can send lots of data per put_copy_data
     Failure/Error:
       		run_with_scheduler(60) do |conn|
       			conn.exec <<-EOSQL
       				CREATE TEMP TABLE copytable (col1 TEXT);
       			EOSQL
       
       			res = nil
       			conn.copy_data( "COPY copytable FROM STDOUT CSV" ) do
       				data = "x" * 1000 * 1000
       				data << "\n"
       				50.times do

     RuntimeError:
       scheduler timeout in:
       /builddir/build/BUILD/spec/helpers/scheduler.rb:57:in `select'
       /builddir/build/BUILD/spec/helpers/scheduler.rb:57:in `run'
       /builddir/build/BUILD/spec/helpers/scheduler.rb:130:in `close'
       /builddir/build/BUILD/spec/helpers/scheduler.rb:114:in `scheduler_close'
     # /builddir/build/BUILD/spec/helpers.rb:620:in `thread_with_timeout'
     # /builddir/build/BUILD/spec/helpers.rb:625:in `run_with_scheduler'
     # ./spec/pg/scheduler_spec.rb:153:in `block (2 levels) in <top (required)>'
     # /builddir/build/BUILD/spec/helpers.rb:56:in `block in included'

Finished in 1 minute 48.55 seconds (files took 0.63329 seconds to load)
983 examples, 1 failure, 2 pending
~~~

I'll keep analyzing, because there are actually 3 failures currently with kernel-6.11.5-100.fc39.x86_64, so the thing progressed.

Comment 2 Vít Ondruch 2024-11-06 17:40:44 UTC

Starting with kernel-6.10.6-100.fc39.x86_64, there are mostly 2 failures (sometimes only 1):

~~~
  1) with a Fiber scheduler waits when sending query data
     Failure/Error:
       run_with_scheduler do |conn|
       	data = "x" * 1000 * 1000 * 10
       	res = conn.exec_params("SELECT LENGTH($1)", [data])
       	expect(res.values).to eq([[data.length.to_s]])
       end

     RuntimeError:
       scheduler timeout in:
       /builddir/build/BUILD/spec/helpers/scheduler.rb:57:in `select'
       /builddir/build/BUILD/spec/helpers/scheduler.rb:57:in `run'
       /builddir/build/BUILD/spec/helpers/scheduler.rb:130:in `close'
       /builddir/build/BUILD/spec/helpers/scheduler.rb:114:in `scheduler_close'
     # /builddir/build/BUILD/spec/helpers.rb:620:in `thread_with_timeout'
     # /builddir/build/BUILD/spec/helpers.rb:625:in `run_with_scheduler'
     # ./spec/pg/scheduler_spec.rb:43:in `block (2 levels) in <top (required)>'
     # /builddir/build/BUILD/spec/helpers.rb:56:in `block in included'

  2) with a Fiber scheduler can send lots of data per put_copy_data
     Failure/Error:
       		run_with_scheduler(60) do |conn|
       			conn.exec <<-EOSQL
       				CREATE TEMP TABLE copytable (col1 TEXT);
       			EOSQL
       
       			res = nil
       			conn.copy_data( "COPY copytable FROM STDOUT CSV" ) do
       				data = "x" * 1000 * 1000
       				data << "\n"
       				50.times do

     RuntimeError:
       scheduler timeout in:
       /builddir/build/BUILD/spec/helpers/scheduler.rb:57:in `select'
       /builddir/build/BUILD/spec/helpers/scheduler.rb:57:in `run'
       /builddir/build/BUILD/spec/helpers/scheduler.rb:130:in `close'
       /builddir/build/BUILD/spec/helpers/scheduler.rb:114:in `scheduler_close'
     # /builddir/build/BUILD/spec/helpers.rb:620:in `thread_with_timeout'
     # /builddir/build/BUILD/spec/helpers.rb:625:in `run_with_scheduler'
     # ./spec/pg/scheduler_spec.rb:153:in `block (2 levels) in <top (required)>'
     # /builddir/build/BUILD/spec/helpers.rb:56:in `block in included'
~~~

And there are the 3 failures since kernel-6.10.6-100.fc39.x86_64:

~~~
  1) with a Fiber scheduler can send lots of data per put_copy_data
     Failure/Error:
       		run_with_scheduler(60) do |conn|
       			conn.exec <<-EOSQL
       				CREATE TEMP TABLE copytable (col1 TEXT);
       			EOSQL
       
       			res = nil
       			conn.copy_data( "COPY copytable FROM STDOUT CSV" ) do
       				data = "x" * 1000 * 1000
       				data << "\n"
       				50.times do

     RuntimeError:
       scheduler timeout in:
       /builddir/build/BUILD/spec/helpers/scheduler.rb:57:in `select'
       /builddir/build/BUILD/spec/helpers/scheduler.rb:57:in `run'
       /builddir/build/BUILD/spec/helpers/scheduler.rb:130:in `close'
       /builddir/build/BUILD/spec/helpers/scheduler.rb:114:in `scheduler_close'
     # /builddir/build/BUILD/spec/helpers.rb:620:in `thread_with_timeout'
     # /builddir/build/BUILD/spec/helpers.rb:625:in `run_with_scheduler'
     # ./spec/pg/scheduler_spec.rb:153:in `block (2 levels) in <top (required)>'
     # /builddir/build/BUILD/spec/helpers.rb:56:in `block in included'

  2) with a Fiber scheduler waits when sending query data
     Failure/Error:
       run_with_scheduler do |conn|
       	data = "x" * 1000 * 1000 * 10
       	res = conn.exec_params("SELECT LENGTH($1)", [data])
       	expect(res.values).to eq([[data.length.to_s]])
       end

     RuntimeError:
       scheduler timeout in:
       /builddir/build/BUILD/spec/helpers/scheduler.rb:57:in `select'
       /builddir/build/BUILD/spec/helpers/scheduler.rb:57:in `run'
       /builddir/build/BUILD/spec/helpers/scheduler.rb:130:in `close'
       /builddir/build/BUILD/spec/helpers/scheduler.rb:114:in `scheduler_close'
     # /builddir/build/BUILD/spec/helpers.rb:620:in `thread_with_timeout'
     # /builddir/build/BUILD/spec/helpers.rb:625:in `run_with_scheduler'
     # ./spec/pg/scheduler_spec.rb:43:in `block (2 levels) in <top (required)>'
     # /builddir/build/BUILD/spec/helpers.rb:56:in `block in included'

  3) with a Fiber scheduler should convert strings and parameters to #prepare and #exec_prepared
     Failure/Error:
       run_with_scheduler do |conn|
       	conn.prepare("weiß1", "VALUES( LENGTH($1), 'grün')")
       	data = "x" * 1000 * 1000 * 10
       	r = conn.exec_prepared("weiß1", [data])
       	expect( r.values ).to eq( [[data.length.to_s, 'grün']] )
       end

     RuntimeError:
       scheduler timeout in:
       /builddir/build/BUILD/spec/helpers/scheduler.rb:57:in `select'
       /builddir/build/BUILD/spec/helpers/scheduler.rb:57:in `run'
       /builddir/build/BUILD/spec/helpers/scheduler.rb:130:in `close'
       /builddir/build/BUILD/spec/helpers/scheduler.rb:114:in `scheduler_close'
     # /builddir/build/BUILD/spec/helpers.rb:620:in `thread_with_timeout'
     # /builddir/build/BUILD/spec/helpers.rb:625:in `run_with_scheduler'
     # ./spec/pg/scheduler_spec.rb:211:in `block (2 levels) in <top (required)>'
     # /builddir/build/BUILD/spec/helpers.rb:56:in `block in included'
~~~

Comment 3 Vít Ondruch 2024-11-06 17:45:00 UTC

Re-assigning to PostgreSQL for start. Can somebody reproduce the issues with plain SQL? I think it should be possible to reconstruct the queries with the bits displayed in the errors.

Comment 4 Vít Ondruch 2024-11-06 17:51:25 UTC

(In reply to Vít Ondruch from comment #2)
> And there are the 3 failures since kernel-6.10.6-100.fc39.x86_64:

Sorry, this should have been kernel-6.10.7-100.fc39.x86_64

Comment 5 Vít Ondruch 2024-11-08 08:33:07 UTC

Just FTR, only the failing test cases can be executed with GDB like this:

~~~
$ gdb --args ruby-mri -S --verbose rspec -I~/build/BUILD/rubygem-pg-1.5.7-build/pg-1.5.7/usr/lib64/gems/ruby/pg-1.5.7 -f d spec/pg/scheduler_spec.rb:43:153:211
~~~

Comment 6 Vít Ondruch 2024-11-08 08:56:52 UTC

These are the test cases:

https://github.com/ged/ruby-pg/blob/0ac827c3b3105f5ebed625ed37657587a0b4b712/spec/pg/scheduler_spec.rb#L152C1-L169C5

~~~
	it "can send lots of data per put_copy_data" do
		run_with_scheduler(60) do |conn|
			conn.exec <<-EOSQL
				CREATE TEMP TABLE copytable (col1 TEXT);
			EOSQL

			res = nil
			conn.copy_data( "COPY copytable FROM STDOUT CSV" ) do
				data = "x" * 1000 * 1000
				data << "\n"
				50.times do
					res = conn.put_copy_data(data)
					break if res == false
				end
			end
			expect( res ).to be_truthy
		end
	end
~~~

https://github.com/ged/ruby-pg/blob/0ac827c3b3105f5ebed625ed37657587a0b4b712/spec/pg/scheduler_spec.rb#L42-L48

~~~

	it "waits when sending query data" do
		run_with_scheduler do |conn|
			data = "x" * 1000 * 1000 * 10
			res = conn.exec_params("SELECT LENGTH($1)", [data])
			expect(res.values).to eq([[data.length.to_s]])
		end
	end
~~~

https://github.com/ged/ruby-pg/blob/0ac827c3b3105f5ebed625ed37657587a0b4b712/spec/pg/scheduler_spec.rb#L210C1-L217C5

~~~
	it "should convert strings and parameters to #prepare and #exec_prepared" do
		run_with_scheduler do |conn|
			conn.prepare("weiß1", "VALUES( LENGTH($1), 'grün')")
			data = "x" * 1000 * 1000 * 10
			r = conn.exec_prepared("weiß1", [data])
			expect( r.values ).to eq( [[data.length.to_s, 'grün']] )
		end
	end
~~~

Comment 8 Vít Ondruch 2024-11-08 15:07:25 UTC

I cannot reproduce the first issue with kernel-6.10.0-0.rc0.20240514gita5131c3fdf26.2.eln136.x86_64 while it starts to appear with kernel-6.10.0-0.rc0.20240517gitea5f6ad9ad96.6.eln136.x86_64 (I have used ELN kernels, because the Fedora kernels are already garbage-collected)

Comment 9 Vít Ondruch 2024-11-08 16:59:17 UTC

Sadly, I have to disabl the offending test cases for the moment:

https://src.fedoraproject.org/rpms/rubygem-pg/c/3e119a653e7e8d123cdce3f48e749d0c5ea52889

Comment 10 Fedora Update System 2024-11-25 10:29:15 UTC

FEDORA-2024-fd8ed281fb (rubygem-pg-1.5.9-2.fc42) has been submitted as an update to Fedora 42.
https://bodhi.fedoraproject.org/updates/FEDORA-2024-fd8ed281fb

Comment 11 Fedora Update System 2024-11-25 10:32:30 UTC

FEDORA-2024-fd8ed281fb (rubygem-pg-1.5.9-2.fc42) has been pushed to the Fedora 42 stable repository.
If problem still persists, please make note of it in this bug report.

Comment 12 Vít Ondruch 2024-11-26 16:03:54 UTC

This was fixed on rubygem-pg side.