[BUG] Seg Fault when creating index with NULL vectors

[bshreddy]

I have a table with null-able vector column. When I tried to create an index, it failed. And on checking the logs, I found it's due to Seg Fault.

SQL Query for Creating Index

CREATE INDEX "my-remote-index"
ON my_table 
USING pinecone (embedding) 
WITH (host = 'xxx.svc.aped-4627-b74a.pinecone.io')

Postgres Log:

2024-04-21 19:27:50.412 IST [15464] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2024-04-21 19:27:50.420 IST [15464] DEBUG:  building index "al-remote-index" on table "application_log" serially
2024-04-21 19:27:50.421 IST [15464] DEBUG:  Initializing CURL handle
2024-04-21 19:27:50.428 IST [15394] DEBUG:  snapshot of 1+0 running transaction ids (lsn 5/A6EC45E8 oldest xid 4527446 latest complete 4527445 next xid 4527447)
2024-04-21 19:27:51.564 IST [15464] DEBUG:  Response (write_callback): {"namespaces":{"":{"vectorCount":33000}},"dimension":384,"indexFullness":0,"totalVectorCount":33000}
2024-04-21 19:27:51.565 IST [15464] DEBUG:  Host specified in reloptions, checking if it is empty. Got response: {
		"namespaces":	{
			"":	{
				"vectorCount":	33000
			}
		},
		"dimension":	384,
		"indexFullness":	0,
		"totalVectorCount":	33000
	}
2024-04-21 19:27:54.352 IST [15464] DEBUG:  Freeing request body
2024-04-21 19:27:54.352 IST [15464] DEBUG:  Response (write_callback): {"upsertedCount":100}
...
2024-04-21 19:29:05.245 IST [15464] DEBUG:  Freeing request body
2024-04-21 19:29:05.245 IST [15464] DEBUG:  Response (write_callback): {"upsertedCount":100}
2024-04-21 19:29:05.302 IST [83682] DEBUG:  reaping dead processes
2024-04-21 19:29:05.302 IST [83682] DEBUG:  server process (PID 15464) was terminated by signal 11: Segmentation fault: 11
2024-04-21 19:29:05.302 IST [83682] DETAIL:  Failed process was running: CREATE INDEX "my-remote-index"
	ON my_table 
	USING pinecone (embedding) 
	WITH (host = 'xxx.svc.aped-4627-b74a.pinecone.io');
2024-04-21 19:29:05.302 IST [83682] LOG:  server process (PID 15464) was terminated by signal 11: Segmentation fault: 11
2024-04-21 19:29:05.302 IST [83682] DETAIL:  Failed process was running: CREATE INDEX "my-remote-index"
	ON my_table 
	USING my_table (embedding) 
	WITH (host = 'xxx.svc.aped-4627-b74a.pinecone.io');
2024-04-21 19:29:05.302 IST [83682] LOG:  terminating any other active server processes
2024-04-21 19:29:05.302 IST [83682] DEBUG:  sending SIGQUIT to process 15397
2024-04-21 19:29:05.302 IST [83682] DEBUG:  sending SIGQUIT to process 15394
2024-04-21 19:29:05.303 IST [83682] DEBUG:  sending SIGQUIT to process 15393
2024-04-21 19:29:05.303 IST [83682] DEBUG:  sending SIGQUIT to process 15395
2024-04-21 19:29:05.303 IST [83682] DEBUG:  sending SIGQUIT to process 15396
2024-04-21 19:29:05.303 IST [83682] DEBUG:  reaping dead processes
2024-04-21 19:29:05.304 IST [83682] DEBUG:  forked new backend, pid=15601 socket=11
2024-04-21 19:29:05.304 IST [83682] DEBUG:  reaping dead processes
2024-04-21 19:29:05.306 IST [15601] FATAL:  the database system is in recovery mode
2024-04-21 19:29:05.306 IST [15601] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2024-04-21 19:29:05.306 IST [15601] DEBUG:  shmem_exit(1): 0 on_shmem_exit callbacks to make
2024-04-21 19:29:05.306 IST [15601] DEBUG:  proc_exit(1): 1 callbacks to make
2024-04-21 19:29:05.306 IST [15601] DEBUG:  exit(1)
2024-04-21 19:29:05.306 IST [15601] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2024-04-21 19:29:05.306 IST [15601] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2024-04-21 19:29:05.306 IST [15601] DEBUG:  proc_exit(-1): 0 callbacks to make
2024-04-21 19:29:05.307 IST [83682] DEBUG:  reaping dead processes
2024-04-21 19:29:05.307 IST [83682] DEBUG:  server process (PID 15601) exited with exit code 1
2024-04-21 19:29:05.307 IST [83682] LOG:  all server processes terminated; reinitializing
2024-04-21 19:29:05.309 IST [83682] DEBUG:  shmem_exit(1): 0 before_shmem_exit callbacks to make
2024-04-21 19:29:05.309 IST [83682] DEBUG:  shmem_exit(1): 5 on_shmem_exit callbacks to make
2024-04-21 19:29:05.309 IST [83682] DEBUG:  cleaning up orphaned dynamic shared memory with ID 2288057058
2024-04-21 19:29:05.309 IST [83682] DEBUG:  cleaning up dynamic shared memory control segment with ID 762501520
2024-04-21 19:29:05.310 IST [83682] DEBUG:  invoking IpcMemoryCreate(size=149528576)
2024-04-21 19:29:05.312 IST [83682] DEBUG:  dynamic shared memory system will support 674 segments
2024-04-21 19:29:05.312 IST [83682] DEBUG:  created dynamic shared memory control segment 2607114590 (26976 bytes)
2024-04-21 19:29:05.313 IST [15602] LOG:  database system was interrupted; last known up at 2024-04-21 19:26:17 IST
2024-04-21 19:29:05.313 IST [15602] DEBUG:  removing all temporary WAL segments
2024-04-21 19:29:05.313 IST [15603] DEBUG:  checkpointer updated shared memory configuration values
2024-04-21 19:29:05.443 IST [15602] DEBUG:  checkpoint record is at 5/A6EB0E10
2024-04-21 19:29:05.443 IST [15602] DEBUG:  redo record is at 5/A6EB0E10; shutdown true
2024-04-21 19:29:05.443 IST [15602] DEBUG:  next transaction ID: 4527446; next OID: 589824
2024-04-21 19:29:05.443 IST [15602] DEBUG:  next MultiXactId: 1; next MultiXactOffset: 0
2024-04-21 19:29:05.443 IST [15602] DEBUG:  oldest unfrozen transaction ID: 722, in database 1
2024-04-21 19:29:05.443 IST [15602] DEBUG:  oldest MultiXactId: 1, in database 1
2024-04-21 19:29:05.443 IST [15602] DEBUG:  commit timestamp Xid oldest/newest: 0/0
2024-04-21 19:29:05.443 IST [15602] LOG:  database system was not properly shut down; automatic recovery in progress
2024-04-21 19:29:05.443 IST [15602] DEBUG:  transaction ID wrap limit is 2147484369, limited by database with OID 1
2024-04-21 19:29:05.443 IST [15602] DEBUG:  MultiXactId wrap limit is 2147483648, limited by database with OID 1
2024-04-21 19:29:05.443 IST [15602] DEBUG:  starting up replication slots
2024-04-21 19:29:05.443 IST [15602] DEBUG:  xmin required by slots: data 0, catalog 0
2024-04-21 19:29:05.443 IST [15602] DEBUG:  starting up replication origin progress state
2024-04-21 19:29:05.443 IST [15602] DEBUG:  didn't need to unlink permanent stats file "pg_stat/pgstat.stat" - didn't exist
2024-04-21 19:29:05.443 IST [15602] DEBUG:  resetting unlogged relations: cleanup 1 init 0
2024-04-21 19:29:05.445 IST [15602] LOG:  redo starts at 5/A6EB0E88
2024-04-21 19:29:05.445 IST [83682] DEBUG:  postmaster received pmsignal signal
2024-04-21 19:29:05.445 IST [15602] LOG:  invalid record length at 5/A6EC4840: expected at least 24, got 0
2024-04-21 19:29:05.445 IST [15602] LOG:  redo done at 5/A6EC4808 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
2024-04-21 19:29:05.445 IST [15602] DEBUG:  resetting unlogged relations: cleanup 0 init 1
2024-04-21 19:29:05.447 IST [15602] DEBUG:  MultiXactId wrap limit is 2147483648, limited by database with OID 1
2024-04-21 19:29:05.447 IST [15602] DEBUG:  MultiXact member stop limit is now 4294914944 based on MultiXact 1
2024-04-21 19:29:05.447 IST [15603] LOG:  checkpoint starting: end-of-recovery immediate wait
2024-04-21 19:29:05.447 IST [15603] DEBUG:  performing replication slot checkpoint
2024-04-21 19:29:05.449 IST [15603] DEBUG:  checkpoint sync: number=1 file=base/395417/3455 time=0.058 ms
2024-04-21 19:29:05.449 IST [15603] DEBUG:  checkpoint sync: number=2 file=base/395417/2674 time=0.066 ms
2024-04-21 19:29:05.449 IST [15603] DEBUG:  checkpoint sync: number=3 file=base/395417/2608 time=0.079 ms
2024-04-21 19:29:05.449 IST [15603] DEBUG:  checkpoint sync: number=4 file=base/395417/589824 time=0.063 ms
2024-04-21 19:29:05.449 IST [15603] DEBUG:  checkpoint sync: number=5 file=base/395417/2678 time=0.044 ms
2024-04-21 19:29:05.449 IST [15603] DEBUG:  checkpoint sync: number=6 file=base/395417/2658 time=0.049 ms
2024-04-21 19:29:05.449 IST [15603] DEBUG:  checkpoint sync: number=7 file=base/395417/1249 time=0.048 ms
2024-04-21 19:29:05.449 IST [15603] DEBUG:  checkpoint sync: number=8 file=base/395417/2662 time=0.075 ms
2024-04-21 19:29:05.449 IST [15603] DEBUG:  checkpoint sync: number=9 file=base/395417/1259 time=0.045 ms
2024-04-21 19:29:05.449 IST [15603] DEBUG:  checkpoint sync: number=10 file=pg_multixact/offsets/0000 time=0.024 ms
2024-04-21 19:29:05.450 IST [15603] DEBUG:  checkpoint sync: number=11 file=base/395417/2679 time=0.052 ms
2024-04-21 19:29:05.450 IST [15603] DEBUG:  checkpoint sync: number=12 file=pg_xact/0004 time=0.025 ms
2024-04-21 19:29:05.450 IST [15603] DEBUG:  checkpoint sync: number=13 file=base/395417/2608_fsm time=0.086 ms
2024-04-21 19:29:05.450 IST [15603] DEBUG:  checkpoint sync: number=14 file=base/395417/2673 time=0.044 ms
2024-04-21 19:29:05.450 IST [15603] DEBUG:  checkpoint sync: number=15 file=base/395417/2610 time=0.048 ms
2024-04-21 19:29:05.450 IST [15603] DEBUG:  checkpoint sync: number=16 file=base/395417/2663 time=0.051 ms
2024-04-21 19:29:05.450 IST [15603] DEBUG:  checkpoint sync: number=17 file=base/395417/2659 time=0.049 ms
2024-04-21 19:29:05.450 IST [15603] DEBUG:  attempting to remove WAL segments older than log file 0000000000000005000000A5
2024-04-21 19:29:05.450 IST [15603] LOG:  checkpoint complete: wrote 21 buffers (0.1%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.002 s, total=0.003 s; sync files=17, longest=0.001 s, average=0.001 s; distance=78 kB, estimate=78 kB; lsn=5/A6EC4840, redo lsn=5/A6EC4840
2024-04-21 19:29:05.450 IST [15602] DEBUG:  shmem_exit(0): 4 before_shmem_exit callbacks to make
2024-04-21 19:29:05.450 IST [15602] DEBUG:  shmem_exit(0): 6 on_shmem_exit callbacks to make
2024-04-21 19:29:05.450 IST [15602] DEBUG:  proc_exit(0): 1 callbacks to make
2024-04-21 19:29:05.450 IST [15602] DEBUG:  exit(0)

I was able to fix the issue by adding a WHERE Clause

CREATE INDEX "my-remote-index"
ON my_table 
USING pinecone (embedding) 
WITH (host = 'xxx.svc.aped-4627-b74a.pinecone.io')
WHERE embedding IS NOT NULL;

Please let me know if you need any more info.

[swetavooda]

Thank you for reporting the bug. We've identified the issue with NULL vectors and have addressed it in our latest branch, pgvr/main, through PR #20 . This fix ensures smoother handling of such error scenarios in the future.

Since Pinecone doesn't accept NULL vectors, we've updated our code to handle this more gracefully. Moving forward, please note that the fix will be included in our upcoming release.

We'll keep you informed of any further updates regarding the release. If you have any questions or need assistance, please feel free to reach out.

Thank you.