Periodic regression test "expr" failures

[saygoodbyye]

Describe the bug Regression test "expr" fails in rare cases

How are you accessing AGE (Command line, driver, etc.)? Accessing AGE through command line.

What data setup do we need to do? Apache AGE (master branch) with PostgreSQL (REL_15_STABLE).

What is the necessary configuration info needed? ./configure CFLAGS=" -Og" --enable-tap-tests --enable-debug --enable-cassert --prefix=/tmp/pgsql

What is the command that caused the error? I removed all tests except "expr" from the Makefile and put "make installcheck" in a loop to reproduce the failure.

diff --git a/Makefile b/Makefile
index ab98665..2f08858 100644
--- a/Makefile
+++ b/Makefile
@@ -76,30 +76,8 @@ EXTENSION = age
 DATA = age--1.4.0.sql
 
 # sorted in dependency order
-REGRESS = scan \
-          graphid \
-          agtype \
-          catalog \
-          cypher \
-          expr \
-          cypher_create \
-          cypher_match \
-          cypher_unwind \
-          cypher_set \
-          cypher_remove \
-          cypher_delete \
-          cypher_with \
-          cypher_vle \
-          cypher_union \
-          cypher_call \
-          cypher_merge \
-          age_global_graph \
-          age_load \
-          index \
-          analyze \
-          graph_generation \
-          name_validation \
-          drop
+
+REGRESS = expr
 
 srcdir=`pwd`

Start tests:

for i in `seq 1000000`;do echo "iteration $i";NO_TEMP_INSTALL=1 make -s installcheck || break;done

The test may fail at a random iteration. I received failures at iteration ~600, at iteration ~3500, and during the last run the test failed at iteration 199 with following "regression.diffs":

iteration 199
+++ regress install-check in  +++
============== creating temporary instance            ==============
============== initializing database system           ==============
============== starting postmaster                    ==============
running on port 61958 with PID 3302580
============== creating database "contrib_regression" ==============
CREATE DATABASE
ALTER DATABASE
ALTER DATABASE
ALTER DATABASE
ALTER DATABASE
ALTER DATABASE
ALTER DATABASE
============== installing age                         ==============
CREATE EXTENSION
============== running regression test queries        ==============
test expr                         ... FAILED      643 ms
============== shutting down postmaster               ==============

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

regression.diffs:

diff -U3 /home/test/work/subtree/age/regress/expected/expr.out /home/test/work/subtree/age/regre>
--- /home/test/work/subtree/age/regress/expected/expr.out       2023-12-06 13:30:29.282207296 +0>
+++ /home/test/work/subtree/age/regress/results/expr.out        2023-12-06 13:42:58.481465465 +0>
@@ -7217,12 +7217,12 @@
 SELECT * FROM cypher('keys', $$MATCH ()-[e]-() RETURN keys(e)$$) AS (edge_keys agtype);
  edge_keys
 -----------
- []
- []
  ["song"]
  ["song"]
  ["song"]
  ["song"]
+ []
+ []
 (6 rows)

 SELECT * FROM cypher('keys', $$RETURN keys({a:1,b:'two',c:[1,2,3]})$$) AS (keys agtype);

But in some cases the test may fail with another regression.diffs:

diff -U3 /opt/pgpro/ent-14/src/apache-age-test/./regress/expected/expr.out /opt/pgpro/ent-14/src/apache-age-test/./regress/results/expr.out
--- /opt/pgpro/ent-14/src/apache-age-test/./regress/expected/expr.out	2023-09-26 17:35:01.000000000 +0300
+++ /opt/pgpro/ent-14/src/apache-age-test/./regress/results/expr.out	2023-11-30 06:00:38.531000000 +0300
@@ -6612,6 +6612,7 @@
 ERROR:  keys() argument must be a vertex, edge, object or null
 SELECT * from cypher('keys', $$MATCH u=()-[]-() RETURN keys(u)$$) as (keys agtype);
 ERROR:  keys() argument must be a vertex, edge, object or null
+CONTEXT:  parallel worker
 SELECT create_graph('list');
 NOTICE:  graph "list" has been created
  create_graph 

Expected behavior Consistent test passing

Best regards, Egor Chindyaskin Postgres Professional: http://postgrespro.com/

[rafsun42]

Do these failures occur if NO_TEMP_INSTALL=1 is not set? I am assuming this env variable is causing the tests to run in an existing installation of Postgres, rather than a temporary one.

[saygoodbyye]

Yes, test fail occurs without this env variable aswell. I've checked this recently

for i in `seq 1000000`;do echo "iter $i";make -s installcheck || break;done

regression.diffs:

diff -U3 /home/test/work/subtree/age/regress/expected/expr.out /home/test/work/subtree/age/regress/results/expr.out
--- /home/test/work/subtree/age/regress/expected/expr.out       2023-12-06 13:30:29.282207296 +0700
+++ /home/test/work/subtree/age/regress/results/expr.out        2023-12-11 10:54:03.833000000 +0700
@@ -7217,12 +7217,12 @@
 SELECT * FROM cypher('keys', $$MATCH ()-[e]-() RETURN keys(e)$$) AS (edge_keys agtype);
  edge_keys
 -----------
- []
- []
  ["song"]
  ["song"]
  ["song"]
  ["song"]
+ []
+ []
 (6 rows)

 SELECT * FROM cypher('keys', $$RETURN keys({a:1,b:'two',c:[1,2,3]})$$) AS (keys agtype);

Alse reproduced another diff:

diff -U3 /home/test/work/subtree/age/regress/expected/expr.out /home/test/work/subtree/age/regress/results/expr.out
--- /home/test/work/subtree/age/regress/expected/expr.out       2023-12-06 13:30:29.282207296 +0700
+++ /home/test/work/subtree/age/regress/results/expr.out        2023-12-11 12:59:12.813963408 +0700
@@ -7252,6 +7252,7 @@
 ERROR:  keys() argument must be a vertex, edge, object or null
 SELECT * from cypher('keys', $$MATCH u=()-[]-() RETURN keys(u)$$) as (keys agtype);
 ERROR:  keys() argument must be a vertex, edge, object or null
+CONTEXT:  parallel worker
 SELECT create_graph('list');
 NOTICE:  graph "list" has been created
  create_graph

[rafsun42]

Interesting.

As Postgres suggests, regression tests are 'not so pedantic'. Therefore, some tests might fail despite the test queries yielding correct results.

The first one is failing due to row-ordering difference. However, the output itself is correct. Since the order is not well-defined by the specification, we can assume ordering differences do not indicate incorrect result.

The second one is failing due to an addition of the notice 'CONTEXT: parallel worker'. Since the diff does not show any other changes, I am assuming the query is producing the expected result. Except it is being executed by parallel workers.

It may be possible to fix the fails by adding an order by clause and setting config parameters.

[jrgemignani]

@rafsun42 We should make those changes so that these regression tests don't fail. Failing, but still okay, doesn't give warm fuzzies.

[rafsun42]

@saygoodbyye I could not reproduce the failure on my machine. But, I added a draft PR #1483 which may solve this issue. Let us know if it does, if possible.

[saygoodbyye]

@rafsun42 Thank you! I have tested PR #1483. I have understood how to reproduce the issue faster. If you run tests on a virtual machine exactly with 2 cores, the error will repeat itself many times faster. So, on 2 core system I get the following results: regression.out:

test scan                         ... ok          292 ms
test graphid                      ... ok           11 ms
test agtype                       ... ok           68 ms
test catalog                      ... ok           71 ms
test cypher                       ... ok           21 ms
test expr                         ... FAILED      371 ms
test cypher_create                ... ok           88 ms
test cypher_match                 ... ok          500 ms
test cypher_unwind                ... ok           40 ms
test cypher_set                   ... ok           90 ms
test cypher_remove                ... ok           68 ms
test cypher_delete                ... ok          161 ms
test cypher_with                  ... ok           58 ms
test cypher_vle                   ... ok          792 ms
test cypher_union                 ... ok           21 ms
test cypher_call                  ... ok           33 ms
test cypher_merge                 ... ok          183 ms
test age_global_graph             ... ok          104 ms
test age_load                     ... ok         1283 ms
test index                        ... ok          100 ms
test analyze                      ... ok           19 ms
test graph_generation             ... ok           57 ms
test name_validation              ... ok          110 ms
test jsonb_operators              ... ok           78 ms
test drop                         ... ok          221 ms

regression.diffs:

diff -U3 /home/egor/work/age/regress/expected/expr.out /home/egor/work/age/regress/results/expr.out
--- /home/egor/work/age/regress/expected/expr.out       2024-01-11 13:04:18.474303239 +0300
+++ /home/egor/work/age/regress/results/expr.out        2024-01-12 07:55:56.036808105 +0300
@@ -1506,11 +1506,13 @@
        RETURN e
 $$) AS (i bigint);
 ERROR:  cannot cast agtype edge to type int
+CONTEXT:  parallel worker
 SELECT * FROM cypher('type_coercion', $$
        MATCH p=()-[]-()
        RETURN p
 $$) AS (i bigint);
 ERROR:  cannot cast agtype path to type int
+CONTEXT:  parallel worker
 --
 -- Test typecasting '::' transform and execution logic
 --
@@ -7249,6 +7251,7 @@
 \set debug_parallel_query to regress -- suppresses context message from a parallel worker
 SELECT * from cypher('keys', $$MATCH u=()-[]-() RETURN keys(u)$$) as (keys agtype);
 ERROR:  keys() argument must be a vertex, edge, object or null
+CONTEXT:  parallel worker
 \unset debug_parallel_query
 SELECT create_graph('list');
 NOTICE:  graph "list" has been created

Also, due to the setting of 2 cores, the "cypher_match" test began to fail. I've created a PR #1507 that fixes this test.

[rafsun42]

@saygoodbyye It seems debug_parallel_query to regress didn't quite work. I will try to reproduce the issue with smaller number of cores.

[rafsun42]

@saygoodbyye May I ask your CPU info and linux distro where you ran the tests?

[saygoodbyye]

@rafsun42 , i5-12400F, Ubuntu 22.04

[rafsun42]

@saygoodbyye

It seems the debug_parallel_query parameter was called force_parallel_mode in PG15. If you are in PG15, could you try setting force_parallel_mode to regress instead. This should suppress the +CONTEXT: parallel worker line as explained here.

[saygoodbyye]

@rafsun42 I got around to this test again. I tried setting the debug_parallel_query parameter to regress and it worked for apache age 16 and master. For versions 11 to 15, setting the force_parallel_query parameter to regress worked, as you suggested. If you don't mind, I would prepare a PR for all apache age branches with my patches bellow: 16-master:

diff --git a/regress/expected/expr.out b/regress/expected/expr.out
index cc582cc..cc28ad6 100644
--- a/regress/expected/expr.out
+++ b/regress/expected/expr.out
@@ -19,6 +19,7 @@
 SET extra_float_digits = 0;
 LOAD 'age';
 SET search_path TO ag_catalog;
+SET debug_parallel_query TO regress;
 SELECT * FROM create_graph('expr');
 NOTICE:  graph "expr" has been created
  create_graph
@@ -7263,7 +7264,7 @@ SELECT * FROM cypher('keys', $$MATCH (v) RETURN keys(v)$$) AS (vertex_keys agtyp
  ["age", "job", "name"]
 (4 rows)

-SELECT * FROM cypher('keys', $$MATCH ()-[e]-() RETURN keys(e)$$) AS (edge_keys agtype);
+SELECT * FROM cypher('keys', $$MATCH ()-[e]-() RETURN keys(e) ORDER BY e DESC $$) AS (edge_keys agtype);
  edge_keys
 -----------
  []
diff --git a/regress/sql/expr.sql b/regress/sql/expr.sql
index d580271..5b80ece 100644
--- a/regress/sql/expr.sql
+++ b/regress/sql/expr.sql
@@ -20,7 +20,7 @@
 SET extra_float_digits = 0;
 LOAD 'age';
 SET search_path TO ag_catalog;
-
+SET debug_parallel_query TO regress;
 SELECT * FROM create_graph('expr');

 --
@@ -3024,7 +3024,7 @@ SELECT * FROM cypher('keys', $$CREATE ({name: 'keiko fuji', age: 62, job: 'singe
 SELECT * FROM cypher('keys', $$MATCH (a),(b) WHERE a.name = 'hikaru utada' AND b.name = 'alexander guy cook' CREATE (a)-[:collaborated_with {song:"one last kiss"}]->(b)$$) AS (result agtype);
 SELECT * FROM cypher('keys', $$MATCH (a),(b) WHERE a.name = 'hikaru utada' AND b.name = 'keiko fuji' CREATE (a)-[:knows]->(b)$$) AS (result agtype);
 SELECT * FROM cypher('keys', $$MATCH (v) RETURN keys(v)$$) AS (vertex_keys agtype);
-SELECT * FROM cypher('keys', $$MATCH ()-[e]-() RETURN keys(e)$$) AS (edge_keys agtype);
+SELECT * FROM cypher('keys', $$MATCH ()-[e]-() RETURN keys(e) ORDER BY e DESC $$) AS (edge_keys agtype);
 SELECT * FROM cypher('keys', $$RETURN keys({a:1,b:'two',c:[1,2,3]})$$) AS (keys agtype);

 --should return empty list

11-15:

diff --git a/regress/expected/expr.out b/regress/expected/expr.out
index cc582cc..b208190 100644
--- a/regress/expected/expr.out
+++ b/regress/expected/expr.out
@@ -19,6 +19,7 @@
 SET extra_float_digits = 0;
 LOAD 'age';
 SET search_path TO ag_catalog;
+SET force_parallel_mode TO regress;
 SELECT * FROM create_graph('expr');
 NOTICE:  graph "expr" has been created
  create_graph
@@ -7263,7 +7264,7 @@ SELECT * FROM cypher('keys', $$MATCH (v) RETURN keys(v)$$) AS (vertex_keys agtyp
  ["age", "job", "name"]
 (4 rows)

-SELECT * FROM cypher('keys', $$MATCH ()-[e]-() RETURN keys(e)$$) AS (edge_keys agtype);
+SELECT * FROM cypher('keys', $$MATCH ()-[e]-() RETURN keys(e) ORDER BY e DESC $$) AS (edge_keys agtype);
  edge_keys
 -----------
  []
diff --git a/regress/sql/expr.sql b/regress/sql/expr.sql
index d580271..d33a9c7 100644
--- a/regress/sql/expr.sql
+++ b/regress/sql/expr.sql
@@ -20,7 +20,7 @@
 SET extra_float_digits = 0;
 LOAD 'age';
 SET search_path TO ag_catalog;
-
+SET force_parallel_mode TO regress;
 SELECT * FROM create_graph('expr');

 --
@@ -3024,7 +3024,7 @@ SELECT * FROM cypher('keys', $$CREATE ({name: 'keiko fuji', age: 62, job: 'singe
 SELECT * FROM cypher('keys', $$MATCH (a),(b) WHERE a.name = 'hikaru utada' AND b.name = 'alexander guy cook' CREATE (a)-[:collaborated_with {song:"one last kiss"}]->(b)$$) AS (result agtype);
 SELECT * FROM cypher('keys', $$MATCH (a),(b) WHERE a.name = 'hikaru utada' AND b.name = 'keiko fuji' CREATE (a)-[:knows]->(b)$$) AS (result agtype);
 SELECT * FROM cypher('keys', $$MATCH (v) RETURN keys(v)$$) AS (vertex_keys agtype);
-SELECT * FROM cypher('keys', $$MATCH ()-[e]-() RETURN keys(e)$$) AS (edge_keys agtype);
+SELECT * FROM cypher('keys', $$MATCH ()-[e]-() RETURN keys(e) ORDER BY e DESC $$) AS (edge_keys agtype);
 SELECT * FROM cypher('keys', $$RETURN keys({a:1,b:'two',c:[1,2,3]})$$) AS (keys agtype);

 --should return empty list

[rafsun42]

@saygoodbyye Sure.

I have one question. Do you think we should unset debug_parallel_query\force_parallel_mode at the end of that particular query?

Also, my draft pr #1483 addresses similar issue. You can include it with your PR, so all relevent changes are put together.

[saygoodbyye]

@rafsun42 Thank you. I noticed that this is not the only query that can cause the "CONTEXT: parallel worker" message to appear, so I decided to set this option for the entire test.

[github-actions[bot]]

This issue is stale because it has been open 45 days with no activity. Remove "Abondoned" label or comment or this will be closed in 7 days.

[MuhammadTahaNaveed]

Closing this as the issue has been resolved by PRs #1772 and #1678.