Hangs while migrating from SQLite3

[fluca1978]

pgloader version is 3.6.9 running on Ubuntu 24.04:

% pgloader --version
pgloader version "3.6.9"
compiled with SBCL 2.2.9.debian

 % lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 24.04 LTS
Release:        24.04
Codename:       noble

I use it to migrate from an SQLite3 database of 1.6GB in size to a PostgreSQL server. It starts running but it hangs and does not progress.
PostgreSQL version is 16.4 running on Rocky Linux 9; SQLite 3 version is 3.45.1.

My pgloader configuration file is:

% cat pgloader.migrate2PostgreSQL.load
load database
     from sqlite://db/db.sqlite3
     into postgres://franzy@rachel/franzydb

 with include drop, create tables, create no indexes, reset sequences
    , workers = 2, concurrency = 1
    , on error stop
    , batch rows = 1000

set work_mem to '64MB', maintenance_work_mem to '512 MB';

I invoke it as follows (output shown):

 % pgloader -v pgloader.migrate2PostgreSQL.load
2024-11-07T11:10:26.002000+01:00 NOTICE Starting pgloader, log system is ready.
2024-11-07T11:10:26.007000+01:00 LOG pgloader version "3.6.9"
2024-11-07T11:10:26.009000+01:00 LOG Parsing commands from file #P"/home/luca/git/fluca1978/franzy/pgloader.migrate2PostgreSQL.load"
2024-11-07T11:10:26.111002+01:00 LOG Migrating from #<SQLITE-CONNECTION sqlite:///home/luca/git/fluca1978/franzy/db/db.sqlite3 {10068A3ED3}>
2024-11-07T11:10:26.112002+01:00 LOG Migrating into #<PGSQL-CONNECTION pgsql://franzy@rachel:5432/franzydb {10068A4063}>
2024-11-07T11:10:26.130002+01:00 NOTICE SQLite column django_migrations.id uses a sequence
2024-11-07T11:10:26.130002+01:00 NOTICE SQLite column django_content_type.id uses a sequence
2024-11-07T11:10:26.131002+01:00 NOTICE SQLite column auth_group_permissions.id uses a sequence
2024-11-07T11:10:26.131002+01:00 NOTICE SQLite column auth_user_groups.id uses a sequence
2024-11-07T11:10:26.131002+01:00 NOTICE SQLite column auth_user_user_permissions.id uses a sequence
2024-11-07T11:10:26.131002+01:00 NOTICE SQLite column auth_permission.id uses a sequence
2024-11-07T11:10:26.131002+01:00 NOTICE SQLite column auth_group.id uses a sequence
2024-11-07T11:10:26.131002+01:00 NOTICE SQLite column franzy_userinfo.id uses a sequence
2024-11-07T11:10:26.131002+01:00 NOTICE SQLite column eventi.id uses a sequence
2024-11-07T11:10:26.131002+01:00 NOTICE SQLite column django_admin_log.id uses a sequence
2024-11-07T11:10:26.132002+01:00 NOTICE SQLite column tutor_riscontroattivita.id uses a sequence
2024-11-07T11:10:26.132002+01:00 NOTICE SQLite column auth_user.id uses a sequence
2024-11-07T11:10:26.133002+01:00 NOTICE SQLite column esse3_db_sync.pk uses a sequence
2024-11-07T11:10:26.133002+01:00 NOTICE SQLite column tutor_categoriaattivita.id uses a sequence
2024-11-07T11:10:26.133002+01:00 NOTICE SQLite column tutor_attivita.id uses a sequence
2024-11-07T11:10:26.133002+01:00 NOTICE SQLite column studente_foto.id uses a sequence
2024-11-07T11:10:26.152002+01:00 NOTICE Prepare PostgreSQL database.
2024-11-07T11:10:27.087018+01:00 NOTICE COPY docenti with 0 rows estimated [1/2]
2024-11-07T11:10:27.125019+01:00 NOTICE COPY docente_corso_di_laurea with 0 rows estimated [1/2]
2024-11-07T11:10:27.129019+01:00 NOTICE COPY corsi_di_studio with 0 rows estimated [1/2]
2024-11-07T11:10:27.133019+01:00 NOTICE COPY percorsi with 0 rows estimated [1/2]
2024-11-07T11:10:27.137019+01:00 NOTICE COPY ordinamenti with 0 rows estimated [1/2]
2024-11-07T11:10:27.140019+01:00 NOTICE COPY studenti with 0 rows estimated [1/2]
2024-11-07T11:10:29.128052+01:00 NOTICE COPY maturita with 0 rows estimated [1/2]
2024-11-07T11:10:29.403057+01:00 ERROR Error while formatting a row from "maturita":
2024-11-07T11:10:29.403057+01:00 ERROR The value
  6.25d0
is not of type
  (OR STRING NULL FIXNUM)
when binding PGLOADER.TRANSFORMS::INTEGER-STRING
2024-11-07T11:10:29.404057+01:00 ERROR The value
  NIL
is not of type
  NUMBER
2024-11-07T11:10:29.405057+01:00 WARNING PostgreSQL warning: there is no transaction in progress

At this point, the program is stuck. On the PostgreSQL side, I see there is no activity (apparently):

franzydb=# select datname, query, wait_event, wait_event_type from pg_stat_activity where datname = 'franzydb';
-[ RECORD 1 ]---+-------------------------------------------------------------------------------------------------------
datname         | franzydb
query           | select datname, query, wait_event, wait_event_type from pg_stat_activity where datname = 'franzydb';
wait_event      |
wait_event_type |
-[ RECORD 2 ]---+-------------------------------------------------------------------------------------------------------
datname         | franzydb
query           |                                                                                                       +
                | copy scuola (id,nome,tipo_codice,tipo,comune,provincia) FROM STDIN
wait_event      | ClientRead
wait_event_type | Client

franzydb=# select command, bytes_processed, bytes_total, tuples_processed from pg_stat_progress_copy ;
-[ RECORD 1 ]----+----------
command          | COPY FROM
bytes_processed  | 0
bytes_total      | 0
tuples_processed | 0

On the SQLite3 side, the table it is trying to copy (scuola) is:

sqlite> SELECT SUM("pgsize") FROM "dbstat" WHERE name='scuola';
3235840

If I run pgloader with -d, the point where it hangs is:

024-11-07T11:13:07.621044+01:00 INFO COPY ON ERROR STOP
2024-11-07T11:13:07.657044+01:00 DEBUG CONNECTED TO #<PGLOADER.PGSQL:PGSQL-CONNECTION pgsql://franzy@rachel:5432/franzydb {1005B5A703}>
2024-11-07T11:13:07.657044+01:00 DEBUG SET client_encoding TO 'utf8'
2024-11-07T11:13:07.657044+01:00 DEBUG SET work_mem TO '64MB'
2024-11-07T11:13:07.658044+01:00 DEBUG SET maintenance_work_mem TO '512 MB'
2024-11-07T11:13:07.658044+01:00 DEBUG SET application_name TO 'pgloader'
2024-11-07T11:13:07.659044+01:00 INFO pgsql:copy-rows-from-queue[0]: scuola (id nome tipo_codice tipo comune
                                       provincia)

and no other messages can be found in the logs.

Considering that there is an error launched on tbale maturita, while the COPY is active on another table, I tried to search for such a value causing the error, without any success:

% sqlite3 -line db/db.sqlite3  'select * from maturita;' | grep "25d0" | wc -l
0

On the PostgreSQL side, around the point where pgloader hangs, I find:

 CET [32805]: [17] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.048 ms  bind <unnamed>: select version()
 CET [32805]: [18] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.033 ms  execute <unnamed>: select version()
 CET [32805]: [19] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.005 ms  parse <unnamed>: BEGIN
 CET [32805]: [20] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.002 ms  bind <unnamed>: BEGIN
 CET [32805]: [21] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.003 ms  execute <unnamed>: BEGIN
 CET [32805]: [22] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 47.217 ms  statement: 
        copy maturita (id,studente_id,anno,voto_massimo,voto,lode,titolo,scuola_id) FROM STDIN
 CET [32805]: [23] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.010 ms  parse <unnamed>: COMMIT
 CET [32805]: [24] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.004 ms  bind <unnamed>: COMMIT
 CET [32805]: [25] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.147 ms  execute <unnamed>: COMMIT
 CET [32805]: [26] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.005 ms  parse <unnamed>: ROLLBACK
 CET [32805]: [27] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.003 ms  bind <unnamed>: ROLLBACK
 CET [32805]: [28] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 WARNING:  there is no transaction in progress
 CET [32805]: [29] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.082 ms  execute <unnamed>: ROLLBACK
 CET [32805]: [30] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  disconnection: session time: 0:00:00.063 user=franzy database=franzydb host=192.168.222.1 port=57646
 CET [32806]: [1] user=[unknown],db=[unknown],app=[unknown],client=192.168.222.1 LOG:  connection received: host=192.168.222.1 port=57660
 CET [32806]: [2] user=franzy,db=franzydb,app=[unknown],client=192.168.222.1 LOG:  connection authenticated: identity="franzy" method=scram-sha-256 (/postgres/16/data/pg_hba.conf:128)
 CET [32806]: [3] user=franzy,db=franzydb,app=[unknown],client=192.168.222.1 LOG:  connection authorized: user=franzy database=franzydb application_name=postmodern-default
 CET [32806]: [4] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.063 ms  parse <unnamed>: SET client_encoding TO 'utf8'
 CET [32806]: [5] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.014 ms  bind <unnamed>: SET client_encoding TO 'utf8'
 CET [32806]: [6] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.011 ms  execute <unnamed>: SET client_encoding TO 'utf8'
 CET [32806]: [7] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.009 ms  parse <unnamed>: SET work_mem TO '64MB'
 CET [32806]: [8] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.003 ms  bind <unnamed>: SET work_mem TO '64MB'
 CET [32806]: [9] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.005 ms  execute <unnamed>: SET work_mem TO '64MB'
 CET [32806]: [10] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.006 ms  parse <unnamed>: SET maintenance_work_mem TO '512 MB'
 CET [32806]: [11] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.002 ms  bind <unnamed>: SET maintenance_work_mem TO '512 MB'
 CET [32806]: [12] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.005 ms  execute <unnamed>: SET maintenance_work_mem TO '512 MB'
 CET [32806]: [13] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.005 ms  parse <unnamed>: SET application_name TO 'pgloader'
 CET [32806]: [14] user=franzy,db=franzydb,app=postmodern-default,client=192.168.222.1 LOG:  duration: 0.003 ms  bind <unnamed>: SET application_name TO 'pgloader'
 CET [32806]: [15] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.004 ms  execute <unnamed>: SET application_name TO 'pgloader'
 CET [32806]: [16] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.141 ms  parse <unnamed>: select version()
 CET [32806]: [17] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.049 ms  bind <unnamed>: select version()
 CET [32806]: [18] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.007 ms  execute <unnamed>: select version()
 CET [32806]: [19] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.005 ms  parse <unnamed>: BEGIN
 CET [32806]: [20] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.003 ms  bind <unnamed>: BEGIN
 CET [32806]: [21] user=franzy,db=franzydb,app=pgloader,client=192.168.222.1 LOG:  duration: 0.003 ms  execute <unnamed>: BEGIN

I cannot spot the problem at all.

[fluca1978]

Update on the problem: I tested the same loading excluding the scuola table and the application loaded almost everything.
Note that another table has a very similar problem, but:

1. the pgloader this time continues;
2. the valure that raised the error is very similar in form to the previous one, so I suspect it is not the real value rather a mangled one.

2024-11-07T13:25:18.700492Z NOTICE COPY lauree with 0 rows estimated [1/2]
2024-11-07T13:25:21.091531Z ERROR Error while formatting a row from "lauree":
2024-11-07T13:25:21.105531Z ERROR The value
  90.22d0
is not of type
  (OR STRING NULL FIXNUM)
when binding PGLOADER.TRANSFORMS::INTEGER-STRING
2024-11-07T13:25:21.148532Z ERROR The value
  NIL
is not of type
  NUMBER
2024-11-07T13:25:21.158532Z WARNING PostgreSQL warning: there is no transaction in progress
2024-11-07T13:25:21.801542Z NOTICE COPY e_db_sync with 0 rows estimated [1/2]
2024-11-07T13:25:21.845543Z NOTICE COPY tutor_categoriaattivita with 0 rows estimated [1/2]
2024-11-07T13:25:21.845543Z NOTICE COPY tutor_attivita with 0 rows estimated [1/2]
2024-11-07T13:25:21.941544Z NOTICE COPY studente_foto with 0 rows estimated [1/2]
2024-11-07T13:25:27.739637Z NOTICE copy studente_foto: 495781 rows done,  38.5 MB,   6.6 MBps
2024-11-07T13:25:27.762638Z NOTICE Completing PostgreSQL database.

So, how can I find out what are the rows causing the problem, so that I can fix them?
Second, why is not pgloader stopping once I've configured on error stop in the configuration file? Am I doing something wrong?

[fluca1978]

I changed the on error stop with , on error resume next and the process completes, but reporting errors.

The final report shows something like:

   esami                 201128    4368210    4167082   387.1 MB       1m41.201s  1m39.066s  9m31.278s
   riga_libretto     290697    6560504    6269807   569.8 MB        4m3.275s   4m2.855s  25m44.450s

where the first column is the number of errors. Is there a way to get an hint at lines that caused the error (I mean the source), so that I can fix them somehow?

[fluca1978]

Apparently there is still an issue: if I set the configuration on error stop instead of resume next the loader locks.

 % ./build/bin/pgloader --version                                                 
pgloader version "3.6.5dc1f10"
compiled with SBCL 2.2.9.debian

% ./build/bin/pgloader -d pgloader.migrate2PostgreSQL.load

...
2026-06-22T14:19:30.083083+02:00 DEBUG SET client_encoding TO 'utf8'
2026-06-22T14:19:30.083083+02:00 DEBUG SET maintenance_work_mem TO '512 MB'
2026-06-22T14:19:30.083083+02:00 DEBUG SET work_mem TO '128MB'
2026-06-22T14:19:30.083083+02:00 DEBUG SET application_name TO 'pgloader'
2026-06-22T14:19:30.084083+02:00 DEBUG SET maintenance_work_mem TO '512 MB'
2026-06-22T14:19:30.084083+02:00 DEBUG SET application_name TO 'pgloader'
2026-06-22T14:19:30.084083+02:00 SQL SET search_path TO public;
2026-06-22T14:19:30.085083+02:00 SQL SET search_path TO public;
2026-06-22T14:19:30.085083+02:00 INFO pgsql:copy-rows-from-queue[0]: public.auth_user_groups (id user_id group_id)
2026-06-22T14:19:30.085083+02:00 INFO pgsql:copy-rows-from-queue[5]: public.auth_user_groups (id user_id group_id)

On the database size:

tutoratodb=# select query, now() - state_change as since, state, wait_event_type, wait_event from pg_stat_activity where application_name = 'pgloader';
                             query                             |      since      | state  | wait_event_type | wait_event 
---------------------------------------------------------------+-----------------+--------+-----------------+------------
                                                              +| 00:04:43.048301 | active | Client          | ClientRead
 copy public.auth_user_groups (id,user_id,group_id) FROM STDIN |                 |        |                 | 
                                                              +| 00:04:43.093489 | active | Client          | ClientRead
 copy public.auth_user_groups (id,user_id,group_id) FROM STDIN |                 |        |                 | 
                                                              +| 00:04:43.033575 | active | Client          | ClientRead
 copy public.auth_user_groups (id,user_id,group_id) FROM STDIN |                 |        |                 | 
                                                              +| 00:04:43.033656 | active | Client          | ClientRead
 copy public.auth_user_groups (id,user_id,group_id) FROM STDIN |                 |        |                 | 
                                                              +| 00:04:43.028699 | active | Client          | ClientRead
 copy public.auth_user_groups (id,user_id,group_id) FROM STDIN |                 |        |                 | 
                                                              +| 00:04:43.099581 | active | Client          | ClientRead
 copy public.auth_user_groups (id,user_id,group_id) FROM STDIN |                 |        |                 | 
                                                              +| 00:04:43.028372 | active | Client          | ClientRead
 copy public.auth_user_groups (id,user_id,group_id) FROM STDIN |                 |        |                 | 
(7 rows)

The configuration file is:

 % cat pgloader.migrate2PostgreSQL.load 
load database
     from sqlite://db/db.sqlite3
     into postgres://tutorato@rachel/tutoratodb

 with include drop, create tables, create indexes,  reset sequences
    , workers = 8, concurrency = 8
    , on error stop
    , batch rows = 1000
    



set work_mem to '128MB', maintenance_work_mem to '512 MB';

[dimitri]

The root cause is now identified and fixed in PR #1748, merged to main.

What the PostgreSQL log reveals

Your server log shows the exact sequence the bug produces:

[22] copy maturita (...) FROM STDIN    ← COPY open, some rows sent
[23-25] COMMIT                         ← bug: cleanup committed before the handler ran
[26-28] ROLLBACK — WARNING: there is no transaction in progress
[29] ROLLBACK                          ← no-op, transaction was already committed
[30] disconnection

Root cause

In stream-rows-to-copy (the code path used by on error stop), COMMIT was placed inside the unwind-protect cleanup, alongside close-db-writer:

(unwind-protect
     (loop ...)
  (cl-postgres:close-db-writer copier)
  (pomo:execute "COMMIT"))  ; ← runs before the handler-case handler

In Common Lisp, handler-case handlers run after unwind-protect cleanup has finished. So when a data error occurred, the sequence was always: COMMIT (cleanup) → ROLLBACK (handler, now a no-op). The transaction was committed even on error, then the connection was left in an inconsistent state — which explains both the "no transaction in progress" warning and the subsequent hang on the next table's COPY.

The fix

COMMIT is moved to after the unwind-protect block so it is only reached when the row loop and close-db-writer both complete without error. On any error, only close-db-writer runs in the cleanup (cl-postgres leaves the connection in a clean SQL mode regardless), and the handler-case handler then correctly issues ROLLBACK against an active transaction.

A secondary fix guards against a TYPE-ERROR that was raised when stream-row returned nil for a row it could not format — this masked the primary bug in certain error paths.

To get the fix

Build pgloader from the current main branch. A Debian package build should land in the next release.

[fluca1978]

I can confirm this works!