Repository navigation
Random test suite crash #514
Description
Just ran into this on #510 (but can't reproduce it easily):
Warning 1: GPKG: bad application_id=0x00000000 on '/tmp/.tmpgi6DfV.gpkg'
ERROR 1: Layer new already exists, CreateLayer failed.
Use the layer creation option OVERWRITE=YES to replace it.
test spatial_ref::srs::tests::predicats_epsg2154 ... ok
test spatial_ref::srs::tests::get_units_epsg4326 ... ok
test spatial_ref::srs::tests::non_existing_proj_param ... ok
test vector::layer::tests::test_create_layer_options ... ok
error: test failed, to rerun pass `--lib`
Caused by:
process didn't exit successfully: `/home/grayshade/Projects/georust/gdal/target/debug/deps/gdal-0978520db0adc3dd` (signal: 11, SIGSEGV: invalid memory reference)
That looks like a temporary file name, not sure what's going on.
Activity
Atreyagaurav commentedon Jan 10, 2024
Oh yeah, I ran into it once as well. It passed the next time I ran it, though. Maybe, like it said, the temp filename was coincidently the same as last time the test was done, and the file isn't cleared?
lnicola commentedon Jan 10, 2024
No, they're checked for collisions.
Not saying it's because of your changes, I just didn't see it before.
metasim commentedon Jan 11, 2024
Been a while since I've seen this. I'd start with checking to ensure any test that mutates an on-disk fixture is using the
TempFixturetooling, so as to work on separate copies of the file.lnicola commentedon Jan 11, 2024
Hmm, I was able to reproduce the crash on
master, so it's not #510. The "Layer new already exists" message points to thepoly.gpkgtests, which we should fix.However, running
cargo test vectorin a loop doesn't seem to crash, so it's still possible that the SIGSEGV is unrelated.lnicola commentedon Jan 11, 2024
Caught it with
while gdb -ex=r -ex=quit --args target/debug/deps/gdal-0978520db0adc3dd; end.metasim commentedon Jan 11, 2024
Great tip!
Am I right that both
projandgpkguse SQLite? If so, I wonder if there's any chance one of them was compiled with a different version than the other? 🤷 Shooting in the dark here.lnicola commentedon Jan 11, 2024
They should be dynamically linked. I think SQLite is pretty robust, at least in some build configurations (unlike.. ahem.. netcdf).
And I couldn't trigger it when filtering by
layers(or anything else), so it might be interference from am unrelated test. Maybe even from proj.lnicola commentedon Jan 12, 2024
I still had gdb running, so I checked the other threads:
So indeed, it looks like proj is also calling into SQLite at the same time, not that it proves anything.
EDIT: another one, this time with debug symbols:
The crash is at:
So https://github.com/OSGeo/gdal/blob/6133cf34a78077998406c0c4045bf51f06e3f49d/ogr/ogrsf_frmts/sqlite/ogrsqlitevirtualogr.cpp#L2611 looks just about right.
However,
%raxis 0:So it looks like the
sqlite3_create_module_v2call is pointing nowhere, but I don't understand why.lnicola commentedon Jan 12, 2024
CC @rouault I don't know if I can reproduce this in pure GDAL. It might be a race on our side between
GDALAllRegisterand e.g.OSRImportFromEPSG. Or maybe there's something fishy going on aroundOGR2SQLITE_Register.I managed to reproduce this using 3 tests:
Anyway, taking a closer look at the assembly,
_ZL11sqlite3_api.lto_priv.0is NULL. That's a LTO-mangled name forsqlite3_api, from https://github.com/OSGeo/gdal/blob/6133cf34a78077998406c0c4045bf51f06e3f49d/ogr/ogrsf_frmts/sqlite/ogrsqlitevirtualogr.cpp#L135.That seems to be initialized through
OGR2SQLITE_Register(weird cast there) at https://github.com/OSGeo/gdal/blob/6133cf34a78077998406c0c4045bf51f06e3f49d/ogr/ogrsf_frmts/sqlite/ogrsqlitevirtualogr.cpp#L2760C5-L2760C27 (the macro expands tosqlite3_api = pApi).But the stack trace has:
So
OGRSQLiteDataSource::OpenOrCreateDB(..., true)should have already calledOGRSQLiteBaseDataSource::OpenOrCreateDBandOGR2SQLITE_Register, ending up at https://github.com/OSGeo/gdal/blob/6133cf34a78077998406c0c4045bf51f06e3f49d/ogr/ogrsf_frmts/sqlite/ogrsqlitedatasource.cpp#L1294. This is all on the same thread.I don't really understand how this is happening, but it's probably caused by that
sqlite3_apiglobal.metasim commentedon Jan 12, 2024
Wow, nice work, and nice case study in using
gdbwith mixed language debugging! Thanks for sharing your process!lnicola commentedon Jan 12, 2024
https://sqlite.org/src/file?name=src/sqlite3ext.h
Right, well that explains the indirect call in the asm 🤦♂️.
rouault commentedon Jan 12, 2024
@lnicola I've tried to reproduce on my system using GDAL master and SQLite 3.31.4 (ubuntu 20.04), but
target/release/deps/gdal-fcd32cea6720c7b7 "-q" "--test-threads" "2" "vector::layer::tests::test_field_in_layer" "vector::layer::tests::test_create_layer_options" "spatial_ref::transform_opts::tests::set_coordinate_operation"runs fine for me.What could help perhaps is if you could add the following debug trace to your GDAL build:
lnicola commentedon Jan 12, 2024
Will try, I have to build it first.
It's not too easy to reproduce, I was continuously running that in a loop, over 10 to 20 instances, and it still took a couple of minutes.
In any case, in my crash it's
sqlite3_apithat's null, not thecreate_module_v2pointer.rouault commentedon Jan 12, 2024
Extermely weird. I don't see how that happen. Even if OGR2SQLITE_static_register() was called with _pApi == nullptr (which can only happen if SQLite is built with SQLITE_OMIT_LOAD_EXTENSION), then the following will assign default pointers:
And sqlite3_api is declared static at line 144 (
static SQLITE_EXTENSION_INIT1), so I don't see what could mess it up behind our backlnicola commentedon Jan 12, 2024
We only call
GDALAllRegisterfrom a single thread (using something likecall_once. I'm not sure what kind of ordering it uses, but one possibility is thatsqlite3_apiis initialized on one thread, while another one sees it as null. That's likely to just initialize it twice, but..lnicola commentedon Jan 12, 2024
The other possibility is that it's racing against libproj's usage of SQLite. Though it seems less likely (I didn't check, but I assume it's not setting itself up as an extension or anything weird like that).
lnicola commentedon Jan 13, 2024
I added that debug-print (with the thread id too) and the result was not what I expected:
Successful run:
Failed run:
(tested on GDAL 3.7.3 with SQLite 3.42.0)
To reproduce:
(for POSIX shells that should be
while ...;do doneor something like that, andtarget/release/deps/gdal-a5f1a0f14e3eca4cis from the output ofcargo test --release)lnicola commentedon Jan 13, 2024
With more logging:
So, without having looked in detail at the rest of the code:
GDALAllRegisterOGRSQLiteBaseDataSource::OpenOrCreateDB->OGR2SQLITE_Register->sqlite3_auto_extensionfrom , which stores the pointer for latersqlite3_opencallsopenDatabase, which calls all extensions viasqlite3AutoLoadExtensionsOGR2SQLITE_static_register) should initializesqlite3_apibut doesn't get calledOGR2SQLITEModule::Setuptries to callsqlite3_api->sqlite3_create_module_v2, but gets a NULLrouault commentedon Jan 13, 2024
OGR2SQLITE_Register is only called by OGRSQLiteBaseDataSource::OpenOrCreateDB(), not at GDALAllRegister() time
lnicola commentedon Jan 13, 2024
Of course, not sure what I was seeing. With more logging
rouault commentedon Jan 13, 2024
I still don't manage to reproduce within a fedora:39 Docker image, even while looping for ever.
I've been digging into sqlite3 code source, and one very slightly suspicious thing is this optimization in sqlite3AutoLoadExtensions(): https://github.com/sqlite/sqlite/blob/89efa897780db03eac974eb6b0e041cfb7c39733/src/loadext.c#L873 , where wsdAutoext.nExt is tested against 0 outside of the SQLITE_MUTEX_STATIC_MAIN mutex that is normally used otherwise. But this does still seem OK given my understanding of multithreading and mutexes.
My hypothesis to explain what you observe would be:
If you have the possibility of building sqlite from source, one possibility would be to try to remove the optim https://github.com/sqlite/sqlite/blob/89efa897780db03eac974eb6b0e041cfb7c39733/src/loadext.c#L873 and see if that makes any difference
Or instrument sqlite3_reset_auto_extension() to see if some unexpected code would call it...
rouault commentedon Jan 13, 2024
OSGeo/gdal#9068 should likely stop the segfault, but there's still something missing to understand the full picture
ChristianBeilschmidt commentedon Feb 11, 2024
I don't know if I can add something valuable to the dscussion, but we've recently added
cargoas a dependency and our test suite ran with0.76but with0.77(geo-engine/geoengine#929) oneGdalOpenExcall withgeorust/gdalsuddenly had a SIGSEGV.Looking at this thread I noticed that
0.77got a dependency ofrusqlite, which again broughtlibsqlite3-sys=0.28. Removing this dependency seemed to remove the SIGSEGV… which is very scary.lnicola commentedon Sep 16, 2026
A nice reproducer, still needs a couple of runs to trigger.
lnicola commentedon Sep 16, 2026
So OSGeo/gdal#9068 said:
However,
OGRSQLiteBaseDataSource::FinishSpatialite()callsspatialite_cleanup_ex, which doessqlite3_reset_auto_extension, so it's actually pretty easy to trigger. That can preventOGR2SQLITE_static_registerfrom getting called until the nextOGR2SQLITE_Register.