Re: crash pg_restore

Le mer. 23 juin 2021 à 16:06, Alain Benard <alain(dot)benard(at)inrae(dot)fr> a écrit :

> Ok voici ce que j’ai fait :
>
> · Suppression de toutes les autres bases du serveur (il n’est pas
> accessible ni connu d’autres user pour l’instant).
>
> · Arrêt Postgresql 12 / Suppression fichier log / Redémarrage PG
> 12
>
> · Lancement de la restauration : pg_restore -C --dbname=template1
> --clean --if-exists --format=c --verbose
> /data/save/2021-06-23db_bouquetins.gz 1>bouquetins 2>bouquetins.err
>
>
>
> Voici le log complet Postgresql :
>
> *2021-06-23 14:01:31.775 CEST [4268] LOG: database system was shut down
> at 2021-06-23 14:01:10 CEST*
>
> *2021-06-23 14:01:31.779 CEST [4265] LOG: database system is ready to
> accept connections*
>
> *2021-06-23 14:08:13.962 CEST [4293] ERROR: canceling autovacuum task*
>
> *2021-06-23 14:08:13.962 CEST [4293] CONTEXT: SQL function "raster_eq"
> statement 1*
>
> * automatic analyze of table
> "db_bouquetins.env_data.t_pne_oso_2017"*
>
> *2021-06-23 14:08:14.980 CEST [4296] ERROR: canceling autovacuum task*
>
> *2021-06-23 14:08:14.980 CEST [4296] CONTEXT: SQL function "raster_eq"
> statement 1*
>
> * automatic analyze of table
> "db_bouquetins.env_data.t_pnp_oso_2017"*
>
> *free(): invalid pointer*
>
> *free(): invalid pointer*
>
> *2021-06-23 14:08:38.288 CEST [4265] LOG: background worker "parallel
> worker" (PID 4301) was terminated by signal 6: Aborted*
>
> *2021-06-23 14:08:38.288 CEST [4265] LOG: terminating any other active
> server processes*
>
> *2021-06-23 14:08:38.288 CEST [4285] WARNING: terminating connection
> because of crash of another server process*
>
> *2021-06-23 14:08:38.288 CEST [4285] DETAIL: The postmaster has commanded
> this server process to roll back the current transaction and exit, because
> another server process exited abnormally and possibly corrupted shared
> memory.*
>
> *2021-06-23 14:08:38.288 CEST [4285] HINT: In a moment you should be able
> to reconnect to the database and repeat your command.*
>
> *2021-06-23 14:08:38.296 CEST [4272] WARNING: terminating connection
> because of crash of another server process*
>
> *2021-06-23 14:08:38.296 CEST [4272] DETAIL: The postmaster has commanded
> this server process to roll back the current transaction and exit, because
> another server process exited abnormally and possibly corrupted shared
> memory.*
>
> *2021-06-23 14:08:38.296 CEST [4272] HINT: In a moment you should be able
> to reconnect to the database and repeat your command.*
>
> *2021-06-23 14:08:38.297 CEST [4299] WARNING: terminating connection
> because of crash of another server process*
>
> *2021-06-23 14:08:38.297 CEST [4299] DETAIL: The postmaster has commanded
> this server process to roll back the current transaction and exit, because
> another server process exited abnormally and possibly corrupted shared
> memory.*
>
> *2021-06-23 14:08:38.297 CEST [4299] HINT: In a moment you should be able
> to reconnect to the database and repeat your command.*
>
> *2021-06-23 14:08:38.336 CEST [4296] WARNING: terminating connection
> because of crash of another server process*
>
> *2021-06-23 14:08:38.336 CEST [4296] DETAIL: The postmaster has commanded
> this server process to roll back the current transaction and exit, because
> another server process exited abnormally and possibly corrupted shared
> memory.*
>
> *2021-06-23 14:08:38.336 CEST [4296] HINT: In a moment you should be able
> to reconnect to the database and repeat your command.*
>
> *2021-06-23 14:08:38.336 CEST [4296] CONTEXT: SQL function "raster_eq"
> statement 1*
>
> *2021-06-23 14:08:38.725 CEST [4265] LOG: all server processes
> terminated; reinitializing*
>
> *2021-06-23 14:08:39.033 CEST [4309] LOG: database system was
> interrupted; last known up at 2021-06-23 14:02:32 CEST*
>
> *2021-06-23 14:08:39.381 CEST [4309] LOG: database system was not
> properly shut down; automatic recovery in progress*
>
> *2021-06-23 14:08:39.390 CEST [4309] LOG: redo starts at 1A/E1553A28*
>
> *2021-06-23 14:09:35.626 CEST [4309] LOG: invalid record length at
> 1B/B14992A0: wanted 24, got 0*
>
> *2021-06-23 14:09:35.626 CEST [4309] LOG: redo done at 1B/B1499268*
>
> *2021-06-23 14:09:39.061 CEST [4265] LOG: database system is ready to
> accept connections*
>
> Voici le petit bout de bouquetins.err où démarre l’erreur :
>
> *pg_restore: création de CHECK CONSTRAINT « env_data.t_pnra_oso_2017
> enforce_max_extent_rast »*
>
> *pg_restore: création de CONSTRAINT « env_data.t_cesbio t_cesbio_pkey »*
>
> *pg_restore: WARNING: terminating connection because of crash of another
> server process*
>
> *DÉTAIL : The postmaster has commanded this server process to roll back
> the current transaction and exit, because another server process exited
> abnormally and possibly corrupted shared memory.*
>
> *ASTUCE : In a moment you should be able to reconnect to the database and
> repeat your command.*
>
> *pg_restore: pendant le traitement de la TOC (« PROCESSING TOC ») :*
>
> *pg_restore: de l'entrée TOC 5292 ; 2606 832468 CONSTRAINT t_cesbio
> t_cesbio_pkey ychaval*
>
> *pg_restore: erreur : could not execute query: la connexion au serveur a
> été coupée de façon inattendue*
>
> * Le serveur s'est peut-être arrêté anormalement avant ou durant le*
>
> * traitement de la requête.*
>
> J’espère que tout y est. Est l’autovacuum ?? Du coup j’ai essayé avec
> autovacuum = off dans Postgresql.conf et voici le résultat :
>
> *2021-06-23 14:33:14.225 CEST [4415] LOG: background worker "parallel
> worker" (PID 4437) was terminated by signal 6: Aborted*
>
> *2021-06-23 14:33:14.225 CEST [4415] LOG: terminating any other active
> server processes*
>
> *2021-06-23 14:33:14.226 CEST [4435] WARNING: terminating connection
> because of crash of another server process*
>
> *2021-06-23 14:33:14.226 CEST [4435] DETAIL: The postmaster has commanded
> this server process to roll back the current transaction and exit, because
> another server process exited abnormally and possibly corrupted shared
> memory.*
>
> *2021-06-23 14:33:14.226 CEST [4435] HINT: In a moment you should be able
> to reconnect to the database and repeat your command.*
>
> *2021-06-23 14:33:14.732 CEST [4415] LOG: all server processes
> terminated; reinitializing*
>
> *2021-06-23 14:33:14.989 CEST [4443] LOG: database system was
> interrupted; last known up at 2021-06-23 14:28:14 CEST*
>
> *2021-06-23 14:33:15.159 CEST [4443] LOG: database system was not
> properly shut down; automatic recovery in progress*
>
> *2021-06-23 14:33:15.175 CEST [4443] LOG: redo starts at 1B/B14A0588*
>
> *2021-06-23 14:34:22.565 CEST [4443] LOG: invalid record length at
> 1C/8130CF00: wanted 24, got 0*
>
> *2021-06-23 14:34:22.565 CEST [4443] LOG: redo done at 1C/8130CEC8*
>
> *2021-06-23 14:34:26.218 CEST [4415] LOG: database system is ready to
> accept connections*
>
> Les log postgres ne donnent donc visiblement pas grand-chose et
> probablement que le message d’erreur ne reflète pas vraiment la réalité.
>

Si, ils donnent quelques informations, notamment ces trois lignes :

free(): invalid pointer
free(): invalid pointer
2021-06-23 14:08:38.288 CEST [4265] LOG: background worker "parallel
worker" (PID 4301) was terminated by signal 6: Aborted

Les deux premières ne viennent pas de PostgreSQL, donc probablement d'une
extension (PostGIS ou une autre que vous avez installé). Et vu le message
d'erreur en question, ça peut occasionner un crash du serveur.
La troisième indique que le processus qui s'est terminé est un processus de
parallélisation (process worker). Un premier test possible serait de
désactiver la parallélisation pour savoir si cela améliore les choses ou
pas.

--
Guillaume.