search

pramsey / pgsql-ogr-fdw

PostgreSQL foreign data wrapper for OGR
MIT License
239 stars 34 forks source link

"ERROR: unrecognized node type: 0" when using && for WFS inside function or jdbc #184

Closed lindsejs closed 4 years ago

lindsejs commented 4 years ago

I have tested with two different WFS services - "&&" works perfectly when used in psql, but the same query gives Error when executed through JDBC or in plpgsql Function.

create extension postgis;
create extension ogr_fdw;

SET client_min_messages = debug2;

drop server IF EXISTS myserver cascade;

CREATE SERVER myserver
  FOREIGN DATA WRAPPER ogr_fdw
  OPTIONS (
    datasource 'WFS:http://services.ga.gov.au/gis/services/Waste_Management_Facilities/MapServer/WFSServer',
    format 'WFS',
    config_options 'CPL_DEBUG=ON' );

CREATE FOREIGN TABLE waste_management_facilities_waste_management_facilities (
  shape Geometry(Point,4283),
  name varchar(150)
) SERVER "myserver"
OPTIONS (layer 'Waste_Management_Facilities:Waste_Management_Facilities');

-- this uses bbox as expected, everything works perfectly
SELECT STRING_AGG(name, ', ') FROM waste_management_facilities_waste_management_facilities where shape && ST_GeomFromText('POLYGON(( -35.2 149,-35.2 148,-34.2 148,-34.2 149,-35.2 149))', 4283);

-- the same query inside function
create or replace function get_waste_names()
  returns varchar as $$
begin
  return (SELECT STRING_AGG(name, ', ') FROM waste_management_facilities_waste_management_facilities where shape && ST_GeomFromText('POLYGON(( -35.2 149,-35.2 148,-34.2 148,-34.2 149,-35.2 149))', 4283));
end;
$$ language plpgsql;

-- this throws error  unrecognized node type: 0
select get_waste_names();

-- function without "&&"
create or replace function get_waste_names_without_bbox()
  returns varchar as $$
begin
  return (SELECT STRING_AGG(name, ', ') FROM waste_management_facilities_waste_management_facilities);
end;
$$ language plpgsql;

-- this works:
select get_waste_names_without_bbox();

Where could be the problem?

pramsey commented 4 years ago

Thank you for the perfect issue BTW, I have replicated your issue in under a minute because all your steps are copy-and-paste.

Problem is somewhere in the deparser, my guess. I think with your function example I can debug in and find it. May or may not be able to retain the spatial filter push-down, but at least find the error and get things running.

pramsey commented 4 years ago

Found it, it's how I'm passing parameters through fwd_private in ogrGetForeignPlan. I am passing naked pointers, which is a problem for plans that get cached and (hence) copied, since the pgsql copyObject for plans expects everything to be some kind of node type (fair enough), which means I have to pass/receive these as Value nodes instead of pointers.

pramsey commented 4 years ago

Should be fixed at cb152b7dc64bbb51f43955d88e566b47284dea4a

lindsejs commented 4 years ago

Thanks a lot, cb152b7 works perfectly. For a notice - some weird behavior with WFS appeared now on master branch (do to the last 3 commits), error is "The connection to the server was lost", though it's not the case, tried with two different WFS services.

test_db=# select get_waste_names();
DEBUG:  GDAL config option 'CPL_DEBUG' set to 'ON'
DEBUG:  GDAL None [0] WFS: http://services.ga.gov.au/gis/services/Waste_Management_Facilities/MapServer/WFSServer?SERVICE=WFS&REQUEST=GetCapabilities
DEBUG:  GDAL None [0] HTTP: Fetch(http://services.ga.gov.au/gis/services/Waste_Management_Facilities/MapServer/WFSServer?SERVICE=WFS&REQUEST=GetCapabilities)
DEBUG:  GDAL None [0] HTTP: libcurl/7.29.0 NSS/3.44 zlib/1.2.7 libidn/1.28 libssh2/1.8.0
DEBUG:  GDAL None [0] WFS: Paging support with page size 100
DEBUG:  GDAL None [0] WFS: No ImplementsStandardJoins support
DEBUG:  GDAL None [0] WFS: No transaction support
DEBUG:  GDAL None [0] GDAL: GDALOpen(WFS:http://services.ga.gov.au/gis/services/Waste_Management_Facilities/MapServer/WFSServer, this=0x245e1a0) succeeds as WFS.
DEBUG:  GDAL None [0] HTTP: Fetch(http://services.ga.gov.au/gis/services/Waste_Management_Facilities/MapServer/WFSServer?SERVICE=WFS&VERSION=2.0.0&REQUEST=DescribeFeatureType&TYPENAME=Waste_Management_Facilities:Waste_Management_Facilities)
DEBUG:  GDAL None [0] WFS: http://services.ga.gov.au/gis/services/Waste_Management_Facilities/MapServer/WFSServer?SERVICE=WFS&VERSION=2.0.0&REQUEST=DescribeFeatureType&TYPENAME=Waste_Management_Facilities:Waste_Management_Facilities
DEBUG:  GDAL None [0] HTTP: Fetch(http://services.ga.gov.au/gis/services/Waste_Management_Facilities/MapServer/WFSServer?SERVICE=WFS&VERSION=2.0.0&REQUEST=DescribeFeatureType&TYPENAME=Waste_Management_Facilities:Waste_Management_Facilities)
DEBUG:  ogrReadColumnData matched 0 FID, 1 GEOM, 1 FIELDS out of 2 PGSQL COLUMNS
DEBUG:  OGR spatial filter (-35.2 148, -34.2 149)
DEBUG:  GDAL None [0] GDAL: GDALClose(WFS:http://services.ga.gov.au/gis/services/Waste_Management_Facilities/MapServer/WFSServer, this=0x245e1a0)
DEBUG:  GDAL config option 'CPL_DEBUG' set to 'ON'
DEBUG:  GDAL None [0] WFS: http://services.ga.gov.au/gis/services/Waste_Management_Facilities/MapServer/WFSServer?SERVICE=WFS&REQUEST=GetCapabilities
DEBUG:  GDAL None [0] HTTP: Fetch(http://services.ga.gov.au/gis/services/Waste_Management_Facilities/MapServer/WFSServer?SERVICE=WFS&REQUEST=GetCapabilities)
DEBUG:  GDAL None [0] WFS: Paging support with page size 100
DEBUG:  GDAL None [0] WFS: No ImplementsStandardJoins support
DEBUG:  GDAL None [0] WFS: No transaction support
DEBUG:  GDAL None [0] GDAL: GDALOpen(WFS:http://services.ga.gov.au/gis/services/Waste_Management_Facilities/MapServer/WFSServer, this=0x2883c20) succeeds as WFS.
DEBUG:  GDAL None [0] HTTP: Fetch(http://services.ga.gov.au/gis/services/Waste_Management_Facilities/MapServer/WFSServer?SERVICE=WFS&VERSION=2.0.0&REQUEST=DescribeFeatureType&TYPENAME=Waste_Management_Facilities:Waste_Management_Facilities)
DEBUG:  GDAL None [0] WFS: http://services.ga.gov.au/gis/services/Waste_Management_Facilities/MapServer/WFSServer?SERVICE=WFS&VERSION=2.0.0&REQUEST=DescribeFeatureType&TYPENAME=Waste_Management_Facilities:Waste_Management_Facilities
DEBUG:  GDAL None [0] HTTP: Fetch(http://services.ga.gov.au/gis/services/Waste_Management_Facilities/MapServer/WFSServer?SERVICE=WFS&VERSION=2.0.0&REQUEST=DescribeFeatureType&TYPENAME=Waste_Management_Facilities:Waste_Management_Facilities)
DEBUG:  ogrReadColumnData matched 0 FID, 1 GEOM, 1 FIELDS out of 2 PGSQL COLUMNS
server closed the connection unexpectedly
    This probably means the server terminated abnormally
    before or while processing the request.
The connection to the server was lost. Attempting reset: Failed.
lindsejs commented 4 years ago

Sorry, found another interesting behavior when using "&&" in functions. When "&&" used for more than 5 times in the same DB connection, bbox doesn't anymore get passed down to WFS.

Test case:

create extension postgis;
create extension ogr_fdw;

SET client_min_messages = debug2;

drop server IF EXISTS myserver cascade;

CREATE SERVER myserver
  FOREIGN DATA WRAPPER ogr_fdw
  OPTIONS (
    datasource 'WFS:http://services.ga.gov.au/gis/services/Waste_Management_Facilities/MapServer/WFSServer',
    format 'WFS',
    config_options 'CPL_DEBUG=ON' );

CREATE FOREIGN TABLE waste_management_facilities_waste_management_facilities (
  shape Geometry(Point,4283),
  name varchar(150)
) SERVER "myserver"
OPTIONS (layer 'Waste_Management_Facilities:Waste_Management_Facilities');

create or replace function get_waste_names_bbox(bbox varchar)
  returns varchar as $$
begin
  return (SELECT STRING_AGG(name, ', ') FROM waste_management_facilities_waste_management_facilities where shape && ST_GeomFromText(bbox, 4283));
end;
$$ language plpgsql;

-- first 5 calls work as expected
select get_waste_names_bbox('POLYGON(( -35.2 149,-35.2 148,-34.1 148,-34.1 149,-35.2 149))');
select get_waste_names_bbox('POLYGON(( -35.2 149,-35.2 148,-34.1 148,-34.1 149,-35.2 149))');
select get_waste_names_bbox('POLYGON(( -35.2 149,-35.2 148,-34.1 148,-34.1 149,-35.2 149))');
select get_waste_names_bbox('POLYGON(( -35.2 149,-35.2 148,-34.1 148,-34.1 149,-35.2 149))');
select get_waste_names_bbox('POLYGON(( -35.2 149,-35.2 148,-34.1 148,-34.1 149,-35.2 149))');
-- from here on, bbox isn't passed down to WFS
select get_waste_names_bbox('POLYGON(( -35.2 149,-35.2 148,-34.1 148,-34.1 149,-35.2 149))');
select get_waste_names_bbox('POLYGON(( -35.2 149,-35.2 148,-34.1 148,-34.1 149,-35.2 149))');

-- all the plain queries work without any limitation on call count
SELECT STRING_AGG(name, ', ') FROM waste_management_facilities_waste_management_facilities where shape && ST_GeomFromText('POLYGON(( -35.2 149,-35.2 148,-34.1 148,-34.1 149,-35.2 149))', 4283);
SELECT STRING_AGG(name, ', ') FROM waste_management_facilities_waste_management_facilities where shape && ST_GeomFromText('POLYGON(( -35.2 149,-35.2 148,-34.1 148,-34.1 149,-35.2 149))', 4283);
SELECT STRING_AGG(name, ', ') FROM waste_management_facilities_waste_management_facilities where shape && ST_GeomFromText('POLYGON(( -35.2 149,-35.2 148,-34.1 148,-34.1 149,-35.2 149))', 4283);
SELECT STRING_AGG(name, ', ') FROM waste_management_facilities_waste_management_facilities where shape && ST_GeomFromText('POLYGON(( -35.2 149,-35.2 148,-34.1 148,-34.1 149,-35.2 149))', 4283);
SELECT STRING_AGG(name, ', ') FROM waste_management_facilities_waste_management_facilities where shape && ST_GeomFromText('POLYGON(( -35.2 149,-35.2 148,-34.1 148,-34.1 149,-35.2 149))', 4283);
SELECT STRING_AGG(name, ', ') FROM waste_management_facilities_waste_management_facilities where shape && ST_GeomFromText('POLYGON(( -35.2 149,-35.2 148,-34.1 148,-34.1 149,-35.2 149))', 4283);
pramsey commented 4 years ago

Are you seeing The connection to the server was lost. Attempting reset: Failed. regularly? This is a huge problem since it's the back-end crashing. (PostgreSQL crashing, not the WFS server.) I didn't see this, and the CI is running fine, so it's unfortunate you're seeing it. Does it happen all the time for certain queries? If you have reproduction, I would love to have it.

Edit: nevermind, I'm seeing it too. I am embarassed I let that get by.

pramsey commented 4 years ago

The 5 calls thing is a side effect of the plan caching, and might be really hard to fix... PostgreSQL actually maintains a couple plans when it things about caching, and swaps them after 5 calls depending on the results... it looks like it's deciding the && operator is no help after 5 calls and ditching it in the plan it finally chooses to cache. It will take quite a bit of sleuthing to figure out precisely what's going on there... I wouldn't particularly care, but unfortunately the same thing will happen with JDBC, since JDBC by default uses prepared statements, which means cached plans again.

pramsey commented 4 years ago

Crasher fixed at 7785af5

davecramer commented 4 years ago

The 5 calls thing is a side effect of the plan caching, and might be really hard to fix... PostgreSQL actually maintains a couple plans when it things about caching, and swaps them after 5 calls depending on the results... it looks like it's deciding the && operator is no help after 5 calls and ditching it in the plan it finally chooses to cache. It will take quite a bit of sleuthing to figure out precisely what's going on there... I wouldn't particularly care, but unfortunately the same thing will happen with JDBC, since JDBC by default uses prepared statements, which means cached plans again.

Sadly not very well documented but you can disable named statements in JDBC by setting prepareThreshold=0

https://github.com/pgjdbc/pgjdbc/blob/f3abb4eb19357ac353d4a1e59d2920135619ad9a/pgjdbc/src/main/java/org/postgresql/jdbc/PgConnection.java#L824

pramsey commented 4 years ago

So, fun, if you want to see the plans changing, do this:

prepare fdw(text) as SELECT STRING_AGG(name, ', ') FROM waste_management_facilities_waste_management_facilities where shape && ST_GeomFromText($1, 4283);
-- repeat 6 times
explain (analyze, buffers) execute fdw('POLYGON(( -35.2 149,-35.2 148,-34.1 148,-34.1 149,-35.2 149))');

What you'll see is the initial plan for 5 times:

 Aggregate  (cost=1027.50..1027.51 rows=1 width=32) (actual time=421.117..421.117 rows=1 loops=1)
   ->  Foreign Scan on waste_management_facilities_waste_management_facilities  (cost=25.00..1025.00 rows=1000 width=318) (actual time=420.045..421.080 rows=19 loops=1)
         Filter: (shape && '0103000020BB10000001000000050000009A999999999941C00000000000A062409A999999999941C00000000000806240CDCCCCCCCC0C41C00000000000806240CDCCCCCCCC0C41C00000000000A062409A999999999941C00000000000A06240'::geometry)
 Planning Time: 1176.111 ms
 Execution Time: 1618.436 ms

And then the generic plan (which, unfortunately, is slower, because: no pushdown)

 Aggregate  (cost=1027.50..1027.51 rows=1 width=32) (actual time=13269.491..13269.491 rows=1 loops=1)
   ->  Foreign Scan on waste_management_facilities_waste_management_facilities  (cost=25.00..1025.00 rows=1000 width=318) (actual time=548.771..13269.435 rows=19 loops=1)
         Filter: (shape && st_geomfromtext($1, 4283))
         Rows Removed by Filter: 2266
 Planning Time: 1174.861 ms
 Execution Time: 14453.489 ms

What does this tell us?

What is happening is that the specific plan is materializing the call the ST_GeomFromText() into a geometry literal. Then the FDW system is recognizing that geometry literal as something it can push down. And it does.

But after five goes, the system flips back to a plan that does not materialize the geometry, and the FDW system says "I have a Var on one side and a Proc on the other, I cannot pushdown", and it doesn't. And so things are slow.

Unfortunately, it seems like the generic plan never materializes a geometry there... even when the prepared statement is explicitly using a geometry type on there. This doesn't work either:

prepare fdw2(text) as SELECT STRING_AGG(name, ', ') FROM waste_management_facilities_waste_management_facilities where shape && $1;

Fixing this might require making the spatial push-down support a lot smarter about when it has a value suitable for pushdown on one side of the && operator.

pramsey commented 4 years ago

Moved the plan-five-times discussion to #186