Re: Cluster seems broken after pg_basebackup

Dear Adrian,

Thanks for helping me. Sorry for the lack of details, I had said to myself
I had to not forget to give these details but I hit the send button too
fast. You know how it is...

I added more info in your reply below.

2015-02-06 11:28 GMT-05:00 Adrian Klaver <adrian(dot)klaver(at)aklaver(dot)com>:

> On 02/06/2015 05:03 AM, Guillaume Drolet wrote:
>
>> Hi,
>>
>> Yesterday I ran a pg_basebackup of my cluster. Since it has completed,
>> my cluster doesn't work properly. I tried restarting the computer (or
>> service) a few times but I always get the same messages in my logs (it's
>> in French. If someone is willing to help me I can try to translate the
>> logs. Just ask):
>>
>
> Enter Google Translate:)
>

Not a big fan. I've seen bad misunderstandings happen there!

>
> First some questions:
>
> 1) What Postgres version?
>

9.3

>
> 2) What OS(s)? I am assuming Windows from the log info below, but we all
> know what assuming gets you.
>

Windows 7

>
> 3) Where were you backing up from and to?
>

Backing up from my only cluster (PGDATA) on disk E, to a backup directory
on an other disk (F:) using this command:

pg_basebackup -D "F:\\db_base_backup" -Fp -Xs -R -P
--label="basebackup20150205" --username=postgres

What's weird is that I did some successful tests last week on the same
system (backing up, archiving, recovering) using the same procedure. Only
difference was the cluster, which was much smaller for testing purposes,
but located at the same place (i.e. E:\data) and PostgresSQL installed in
C:\Programs\...

> 4) Which cluster does not start, the master or the child you created with
> pg_basebackup?
>

The master. I haven't tried the child yet. But I saw that the message about
role "208375PT$" is in logs from before the backup too.

>
>
>> 2015-02-06 07:11:38 EST LOG: le système de bases de données a été
>> interrompu ; dernier lancement connu à 2015-02-06 07:05:05 EST
>> 2015-02-06 07:11:38 EST LOG: le système de bases de données n'a pas été
>> arrêté proprement ; restauration
>> automatique en cours
>> 2015-02-06 07:11:38 EST LOG: record with zero length at 24B/2C000160
>> 2015-02-06 07:11:38 EST LOG: la ré-exécution n'est pas nécessaire
>> 2015-02-06 07:11:38 EST LOG: le système de bases de données est prêt
>> pour accepter les connexions
>> 2015-02-06 07:11:38 EST LOG: lancement du processus autovacuum
>> 2015-02-06 07:11:38 EST FATAL: le rôle « 208375PT$ » n'existe pas
>>
>
> So where is role 208375PT$ supposed to come from?
>

This is the local domain of my machine. I log onto my machine with a local
admin account and using domain name 208375PT (I didn't set this part of my
machine, the IT guys here at work did). The thing is: I don't understand
why it's there in the log file??

>
>
>> Then if I start pgAdmin I get a series of pop-ups I have to click OK to
>> to continue:
>>
>> An error has ocurred: Column not found in pgSet: "datlastsysoid"
>> An error has ocurred: Column not found in pgSet: datlastsysoid
>> An error has ocurred: Column not found in pgSet: oid
>> An error has ocurred: Column not found in pgSet: encoding
>> An error has ocurred: Column not found in pgSet: Connection to database
>> broken
>>
>
> Not sure about that this, someone more versed in pgAdmin will have to
> answer.
>
>
>> And after that, I went back to the log file and there's new information
>> added:
>>
>> 2015-02-06 07:51:05 EST LOG: processus serveur (PID 184) a été arrêté
>> par l'exception 0x80000004
>> 2015-02-06 07:51:05 EST DÉTAIL: Le processus qui a échoué exécutait :
>> SELECT version();
>> 2015-02-06 07:51:05 EST ASTUCE : Voir le fichier d'en-tête C «
>> ntstatus.h » pour une description de la valeur
>> hexadécimale.
>>
>
> Well according to here:
>
> https://msdn.microsoft.com/en-us/library/cc704588.aspx
>
> 0x80000004
> STATUS_SINGLE_STEP
>
>
> {EXCEPTION} Single Step A single step or trace operation has just been
> completed.
>
> A developer is going to have explain what that means.
>
>
> 2015-02-06 07:51:05 EST LOG: arrêt des autres processus serveur actifs
>> 2015-02-06 07:51:05 EST ATTENTION: arrêt de la connexion à cause de
>> l'arrêt brutal d'un autre processus serveur
>> 2015-02-06 07:51:05 EST DÉTAIL: Le postmaster a commandé à ce processus
>> serveur d'annuler la transaction
>> courante et de quitter car un autre processus serveur a quitté
>> anormalement
>> et qu'il existe probablement de la mémoire partagée corrompue.
>> 2015-02-06 07:51:05 EST ASTUCE : Dans un moment, vous devriez être
>> capable de vous reconnecter à la base de
>> données et de relancer votre commande.
>> 2015-02-06 07:51:05 EST LOG: processus d'archivage (PID 692) quitte
>> avec le code de sortie 1
>> 2015-02-06 07:51:05 EST LOG: tous les processus serveur se sont
>> arrêtés, réinitialisation
>> 2015-02-06 07:51:15 EST FATAL: le bloc de mémoire partagé pré-existant
>> est toujours en cours d'utilisation
>> 2015-02-06 07:51:15 EST ASTUCE : Vérifier s'il n'y a pas de vieux
>> processus serveur en cours d'exécution. Si c'est le
>> cas, fermez-les.
>>
>> I was about to try restarting postgresql using the base backup I made
>> yesterday but since this means I'll have to copy my database again (700
>> GB takes a while...) I am looking for a better solution from more
>> experienced people.
>>
>
>
> My suspicion is you copied at least partly over a running server.
>
>
How would that be possible? Using the pg_basebackup command I wrote above,
it is clear that I wrote the backup on disk F and not E.

While writing this post, I started my backup using:

pg_ctl start -D "F:\db_basebackup"

Similar stuff happened with pgAdmin and the log (message about symbolic
link is related to my post from yesterday. I don't know if this could be
involved in the current problem):

2015-02-06 12:13:58 EST LOG: le système de bases de données a été
interrompu ; dernier lancement connu à 2015-02-05 14:30:34 EST
2015-02-06 12:13:58 EST LOG: création du répertoire manquant «
pg_xlog/archive_status » pour les journaux de transactions
2015-02-06 12:13:58 EST LOG: la ré-exécution commence à 24B/28000090
2015-02-06 12:13:58 EST LOG: n'a pas pu supprimer le lien symbolique «
pg_tblspc/940585 » : No such file or directory
2015-02-06 12:13:58 EST CONTEXTE : xlog redo drop tablespace: 940585
2015-02-06 12:13:58 EST LOG: état de restauration cohérent atteint à
24B/290000B8
2015-02-06 12:13:58 EST LOG: ré-exécution faite à 24B/290000B8
2015-02-06 12:13:58 EST LOG: la dernière transaction a eu lieu à
2015-02-05 09:06:04.892-05 (moment de la journalisation)
2015-02-06 12:13:59 EST LOG: le système de bases de données est prêt pour
accepter les connexions
2015-02-06 12:13:59 EST LOG: lancement du processus autovacuum
2015-02-06 12:14:42 EST LOG: processus serveur (PID 1784) a été arrêté par
l'exception 0x80000004
2015-02-06 12:14:42 EST DÉTAIL: Le processus qui a échoué exécutait :
SELECT version();
2015-02-06 12:14:42 EST ASTUCE : Voir le fichier d'en-tête C « ntstatus.h
» pour une description de la valeur
hexadécimale.
2015-02-06 12:14:42 EST LOG: arrêt des autres processus serveur actifs
2015-02-06 12:14:42 EST ATTENTION: arrêt de la connexion à cause de
l'arrêt brutal d'un autre processus serveur
2015-02-06 12:14:42 EST DÉTAIL: Le postmaster a commandé à ce processus
serveur d'annuler la transaction
courante et de quitter car un autre processus serveur a quitté
anormalement
et qu'il existe probablement de la mémoire partagée corrompue.
2015-02-06 12:14:42 EST ASTUCE : Dans un moment, vous devriez être capable
de vous reconnecter à la base de
données et de relancer votre commande.
2015-02-06 12:14:42 EST LOG: tous les processus serveur se sont arrêtés,
réinitialisation

Any ideas where to go from here?

Thanks a lot again.

>> Thanks a lot for helping! Guillaume
>>
>>
>
> --
> Adrian Klaver
> adrian(dot)klaver(at)aklaver(dot)com
>