Source: pg-fact-loader
Version: 1.7.0-2
Severity: serious
User: debian...@lists.debian.org
Usertags: regression

Dear maintainer(s),

With a recent upload of pg-fact-loader the autopkgtest of pg-fact-loader fails in testing when that autopkgtest is run with the binary packages of pg-fact-loader from unstable. It passes when run with only packages from testing. In tabular form:

                       pass            fail
pg-fact-loader         from testing    1.7.0-2
versioned deps [0]     from testing    from unstable
all others             from testing    from testing

I copied some of the output at the bottom of this report.

Currently this regression is blocking the migration to testing [1]. Can you please investigate the situation and fix it?

More information about this bug and the reason for filing it can be found on
https://wiki.debian.org/ContinuousIntegration/RegressionEmailInformation

Paul

[0] You can see what packages were added from the second line of the log file quoted below. The migration software adds source package from unstable to the list if they are needed to install packages from pg-fact-loader/1.7.0-2. I.e. due to versioned dependencies or breaks/conflicts.
[1] https://qa.debian.org/excuses.php?package=pg-fact-loader

https://ci.debian.net/data/autopkgtest/testing/amd64/p/pg-fact-loader/27687022/log.gz

### PostgreSQL 15 installcheck ###
Creating new PostgreSQL cluster 15/regress ...
echo "+++ regress install-check in +++" && /usr/lib/postgresql/15/lib/pgxs/src/makefiles/../../src/test/regress/pg_regress --inputdir=./ --bindir='/usr/lib/postgresql/15/bin' --dbname=contrib_regression 01_create_ext 02_schema 03_audit 04_seeds 05_pgl_setup 06_basic_workers 07_launch_worker 08_fact_table_deps 09_purge 10_delete 11_more_data 12_no_proid 13_cutoff_no_dep_on_filter 14_null_key 15_source_change_date 16_1_2_features 17_1_3_features
+++ regress install-check in  +++
(using postmaster on localhost, port 5433)
============== dropping database "contrib_regression" ==============
SET
DROP DATABASE
============== creating database "contrib_regression" ==============
CREATE DATABASE
ALTER DATABASE
ALTER DATABASE
ALTER DATABASE
ALTER DATABASE
ALTER DATABASE
ALTER DATABASE
============== running regression test queries        ==============
test 01_create_ext                ... ok          146 ms
test 02_schema                    ... ok           92 ms
test 03_audit                     ... ok           41 ms
test 04_seeds                     ... ok           64 ms
test 05_pgl_setup                 ... ok           27 ms
test 06_basic_workers             ... ok         8854 ms
test 07_launch_worker             ... ok         4031 ms
test 08_fact_table_deps           ... ok         2663 ms
test 09_purge                     ... ok          176 ms
test 10_delete                    ... ok        13701 ms
test 11_more_data                 ... ok         6198 ms
test 12_no_proid                  ... ok        10785 ms
test 13_cutoff_no_dep_on_filter   ... ok        36008 ms
test 14_null_key                  ... ok          238 ms
test 15_source_change_date        ... ok          101 ms
test 16_1_2_features              ... ok         3220 ms
test 17_1_3_features              ... FAILED     8219 ms

=======================
 1 of 17 tests failed. =======================

The differences that caused some tests to fail can be viewed in the
file "/tmp/autopkgtest-lxc.68jcp06n/downtmp/build.L0a/src/regression.diffs". A copy of the test summary that you see above is saved in the file "/tmp/autopkgtest-lxc.68jcp06n/downtmp/build.L0a/src/regression.out".

make: *** [/usr/lib/postgresql/15/lib/pgxs/src/makefiles/pgxs.mk:433: installcheck] Error 1 *** /tmp/pg_virtualenv.Azz268/log/postgresql-15-regress.log (last 100 lines) ***
        
        , update_key AS (
        SELECT qdwr.queue_table_dep_id,
          --Cutoff the id to that newly found, otherwise default to last value
          COALESCE(mu.last_cutoff_id, qdwr.last_cutoff_id) AS last_cutoff_id,
--This cutoff time must always be the same for all queue tables for given fact table. --Even if there are no new records, we move this forward to wherever the stream is at
          qdwr.maximum_cutoff_time AS last_cutoff_source_time
        FROM fact_loader.queue_deps_all qdwr
LEFT JOIN new_metadata mu ON mu.queue_table_dep_id = qdwr.queue_table_dep_id
        WHERE qdwr.fact_table_id = 2
        --Exclude dependent fact tables from updates directly to 
queue_table_deps
          AND qdwr.fact_table_dep_id IS NULL
        )
        
        /****
This SQL also nearly matches that for the queue_table_deps but would be a little ugly to try to DRY up
        ****/
        , update_key_fact_dep AS (
        SELECT qdwr.fact_table_dep_queue_table_dep_id,
          qdwr.fact_table_id,
          COALESCE(mu.last_cutoff_id, qdwr.last_cutoff_id) AS last_cutoff_id,
          qdwr.maximum_cutoff_time AS last_cutoff_source_time
        FROM fact_loader.queue_deps_all qdwr
LEFT JOIN new_metadata_fact_dep mu ON mu.fact_table_dep_queue_table_dep_id = qdwr.fact_table_dep_queue_table_dep_id
        WHERE qdwr.fact_table_id = 2
        --Include dependent fact tables only
          AND qdwr.fact_table_dep_id IS NOT NULL
        )
        
        , updated_queue_table_deps AS (
        UPDATE fact_loader.queue_table_deps qtd
        SET last_cutoff_id = uk.last_cutoff_id,
          last_cutoff_source_time = uk.last_cutoff_source_time
        FROM update_key uk
        WHERE qtd.queue_table_dep_id = uk.queue_table_dep_id
        RETURNING qtd.*)
        
        , updated_fact_table_deps AS (
        UPDATE fact_loader.fact_table_dep_queue_table_deps ftd
        SET last_cutoff_id = uk.last_cutoff_id,
          last_cutoff_source_time = uk.last_cutoff_source_time
        FROM update_key_fact_dep uk
WHERE ftd.fact_table_dep_queue_table_dep_id = uk.fact_table_dep_queue_table_dep_id
        RETURNING uk.*)
        
        UPDATE fact_loader.fact_tables ft
        SET last_refresh_source_cutoff = uqtd.last_cutoff_source_time,
          last_refresh_attempted_at = now(),
          last_refresh_succeeded = TRUE
        FROM
        (SELECT fact_table_id, last_cutoff_source_time
        FROM updated_queue_table_deps
        --Must use UNION to get only distinct values
        UNION
        SELECT fact_table_id, last_cutoff_source_time
        FROM updated_fact_table_deps) uqtd
        WHERE uqtd.fact_table_id = ft.fact_table_id;
        
2022-10-31 02:12:34.480 UTC [3119] debci@contrib_regression CONTEXT: PL/pgSQL function fact_loader.load(integer) line 65 at RAISE
        SQL statement "SELECT fact_loader.load(p_fact_table_id)"
        PL/pgSQL function fact_loader.try_load(integer) line 40 at PERFORM
        PL/pgSQL function fact_loader.worker() line 16 at IF
2022-10-31 02:12:34.505 UTC [3119] debci@contrib_regression DEBUG: time to inline: 0.000s, opt: 0.007s, emit: 0.000s 2022-10-31 02:12:34.659 UTC [3119] debci@contrib_regression DEBUG: time to inline: 0.000s, opt: 0.007s, emit: 0.152s 2022-10-31 02:12:34.662 UTC [3119] debci@contrib_regression DEBUG: time to inline: 0.000s, opt: 0.007s, emit: 0.153s 2022-10-31 02:12:34.683 UTC [3119] debci@contrib_regression DEBUG: time to inline: 0.000s, opt: 0.005s, emit: 0.000s 2022-10-31 02:12:34.794 UTC [3119] debci@contrib_regression DEBUG: drop auto-cascades to sequence process_queue_process_queue_id_seq 2022-10-31 02:12:34.794 UTC [3119] debci@contrib_regression CONTEXT: SQL statement "DISCARD TEMP"
        PL/pgSQL function fact_loader.worker() line 19 at SQL statement
2022-10-31 02:12:34.794 UTC [3119] debci@contrib_regression DEBUG: drop auto-cascades to type process_queue 2022-10-31 02:12:34.794 UTC [3119] debci@contrib_regression CONTEXT: SQL statement "DISCARD TEMP"
        PL/pgSQL function fact_loader.worker() line 19 at SQL statement
2022-10-31 02:12:34.794 UTC [3119] debci@contrib_regression DEBUG: drop auto-cascades to type process_queue[] 2022-10-31 02:12:34.794 UTC [3119] debci@contrib_regression CONTEXT: SQL statement "DISCARD TEMP"
        PL/pgSQL function fact_loader.worker() line 19 at SQL statement
2022-10-31 02:12:34.794 UTC [3119] debci@contrib_regression DEBUG: drop auto-cascades to default value for column process_queue_id of table process_queue 2022-10-31 02:12:34.794 UTC [3119] debci@contrib_regression CONTEXT: SQL statement "DISCARD TEMP"
        PL/pgSQL function fact_loader.worker() line 19 at SQL statement
2022-10-31 02:12:34.794 UTC [3119] debci@contrib_regression DEBUG: drop auto-cascades to toast table pg_toast_temp_4.pg_toast_17514 2022-10-31 02:12:34.794 UTC [3119] debci@contrib_regression CONTEXT: SQL statement "DISCARD TEMP"
        PL/pgSQL function fact_loader.worker() line 19 at SQL statement
2022-10-31 02:12:34.795 UTC [3119] debci@contrib_regression DEBUG: drop auto-cascades to index pg_toast_temp_4.pg_toast_17514_index 2022-10-31 02:12:34.795 UTC [3119] debci@contrib_regression CONTEXT: SQL statement "DISCARD TEMP"
        PL/pgSQL function fact_loader.worker() line 19 at SQL statement
2022-10-31 02:12:34.795 UTC [3119] debci@contrib_regression DEBUG: drop cascades to table process_queue 2022-10-31 02:12:34.795 UTC [3119] debci@contrib_regression CONTEXT: SQL statement "DISCARD TEMP"
        PL/pgSQL function fact_loader.worker() line 19 at SQL statement
2022-10-31 02:12:41.904 UTC [3126] LOG:  pg_fact_loader worker initialized
2022-10-31 02:12:44.918 UTC [3052] LOG: background worker "pg_fact_loader" (PID 3126) exited with exit code 1 2022-10-31 02:13:55.825 UTC [3165] debci@contrib_regression LOG: ADDING fact_loader_batch_id COLUMN TO queue table test_fact_audit_raw.orders_fact_audit: ALTER TABLE test_fact_audit_raw.orders_fact_audit
        ADD COLUMN fact_loader_batch_id
        BIGINT
        DEFAULT nextval('fact_loader.batch_id');
        
2022-10-31 02:13:55.825 UTC [3165] debci@contrib_regression CONTEXT: PL/pgSQL function fact_loader.add_batch_id_fields() line 29 at RAISE 2022-10-31 02:13:55.825 UTC [3165] debci@contrib_regression STATEMENT: SELECT fact_loader.add_batch_id_fields();
2022-10-31 02:13:59.034 UTC [3176] LOG:  pg_fact_loader worker initialized
2022-10-31 02:14:00.035 UTC [3177] LOG:  pg_fact_loader worker initialized
Dropping cluster 15/regress ...
**** regression.diffs ****
diff -U3 /tmp/autopkgtest-lxc.68jcp06n/downtmp/build.L0a/src/expected/17_1_3_features.out /tmp/autopkgtest-lxc.68jcp06n/downtmp/build.L0a/src/results/17_1_3_features.out --- /tmp/autopkgtest-lxc.68jcp06n/downtmp/build.L0a/src/expected/17_1_3_features.out 2022-08-24 17:29:13.000000000 +0000 +++ /tmp/autopkgtest-lxc.68jcp06n/downtmp/build.L0a/src/results/17_1_3_features.out 2022-10-31 02:14:07.224467952 +0000
@@ -15,7 +15,7 @@
 FROM fact_loader.safely_terminate_workers();
number_terminated | number_still_live | pids_still_live_ct -------------------+-------------------+--------------------
-                 0 |                 2 |                  2
+                   |                   |                    (1 row)
--Should work because the processes should have been idle now for at least 5 seconds
@@ -31,7 +31,7 @@
 FROM fact_loader.safely_terminate_workers();
number_terminated | number_still_live | pids_still_live_ct -------------------+-------------------+-------------------- - 2 | 0 | + | | (1 row)
  INSERT INTO test.orders (order_id, customer_id, order_date, total)
### End 15 installcheck (FAILED with exit code 1) ###
autopkgtest [02:14:07]: test installcheck

Attachment: OpenPGP_signature
Description: OpenPGP digital signature

Reply via email to