Aggiornamento 2.6.0 Beta4 fallito con quelli che sembrano errori db

Supporto Installazione
1

Hi,

I just tried doing a command line ‘launcher rebuild app’ to update from 2.6.0.beta3 (7afb5be5f9), which has been running fine for a while, to 2.6.0.beta4 (as of 20 minutes ago). This is how I usually do my updates.

The update failed, please see output below. I tried running launcher rebuild once more, but it failed with the same error. Next I ran discourse-doctor, which also errored out on the rebuild, but which managed to start Discourse back up on 2.6.0.beta3.

Just to recap that last bit: I’m back up on 2.6.0.beta3 and the site is functioning. But I’m not about to try an update to 2.6.0.beta4 again until I understand what happened.

The launcher output says “database system was interrupted”, but Discourse was up and running fine when I started the launcher rebuild command.

Discourse resides on AWS EFS, so has virtually unlimited space. The server has 32 GB of memory, which is plenty for this site (about 1.3 million pageviews/month).

Appreciate any help and pointers in figuring this out.

Here’s the full output log from running rebuild:

gunnar@dewis:/var/discourse$ sudo ./launcher rebuild app

WARNING: We are about to start downloading the Discourse base image
This process may take anywhere between a few minutes to an hour, depending on your network speed

Please be patient

2.0.20201004-2310: Pulling from discourse/base
Digest: sha256:076ad6f035d7f38e08a2d4fdd4f429ad7a40a9cc72d9958445261cdb9e743d26
Status: Downloaded newer image for discourse/base:2.0.20201004-2310
docker.io/discourse/base:2.0.20201004-2310
Ensuring launcher is up to date
Fetching origin
remote: Enumerating objects: 15, done.
remote: Counting objects: 100% (15/15), done.
remote: Compressing objects: 100% (12/12), done.
remote: Total 15 (delta 5), reused 9 (delta 3), pack-reused 0
Unpacking objects: 100% (15/15), done.
From https://github.com/discourse/discourse_docker
   1b97cb1..468f1f9  master                 -> origin/master
 * [new branch]      imagemagick-policy-xml -> origin/imagemagick-policy-xml
Updating Launcher...
Updating 1b97cb1..468f1f9
Fast-forward
 samples/mail-receiver.yml | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)
Launcher updated, restarting...
Ensuring launcher is up to date
Fetching origin
Launcher is up-to-date
Stopping old container
+ /usr/bin/docker stop -t 60 app
app
cd /pups && git pull && /pups/bin/pups --stdin
Already up to date.
I, [2020-10-19T18:46:41.157056 #1]  INFO -- : Loading --stdin
I, [2020-10-19T18:46:41.162007 #1]  INFO -- : > locale-gen $LANG && update-locale
I, [2020-10-19T18:46:41.197444 #1]  INFO -- : Generating locales (this might take a while)...
Generation complete.

I, [2020-10-19T18:46:41.197650 #1]  INFO -- : > mkdir -p /shared/postgres_run
I, [2020-10-19T18:46:41.202176 #1]  INFO -- : 
I, [2020-10-19T18:46:41.202375 #1]  INFO -- : > chown postgres:postgres /shared/postgres_run
I, [2020-10-19T18:46:41.208709 #1]  INFO -- : 
I, [2020-10-19T18:46:41.208877 #1]  INFO -- : > chmod 775 /shared/postgres_run
I, [2020-10-19T18:46:41.215819 #1]  INFO -- : 
I, [2020-10-19T18:46:41.215957 #1]  INFO -- : > rm -fr /var/run/postgresql
I, [2020-10-19T18:46:41.219629 #1]  INFO -- : 
I, [2020-10-19T18:46:41.219800 #1]  INFO -- : > ln -s /shared/postgres_run /var/run/postgresql
I, [2020-10-19T18:46:41.222805 #1]  INFO -- : 
I, [2020-10-19T18:46:41.222936 #1]  INFO -- : > socat /dev/null UNIX-CONNECT:/shared/postgres_run/.s.PGSQL.5432 || exit 0 && echo postgres already running stop container ; exit 1
2020/10/19 18:46:41 socat[27] E connect(6, AF=1 "/shared/postgres_run/.s.PGSQL.5432", 36): Connection refused
I, [2020-10-19T18:46:41.237039 #1]  INFO -- : 
I, [2020-10-19T18:46:41.237173 #1]  INFO -- : > rm -fr /shared/postgres_run/.s*
I, [2020-10-19T18:46:41.292499 #1]  INFO -- : 
I, [2020-10-19T18:46:41.292674 #1]  INFO -- : > rm -fr /shared/postgres_run/*.pid
I, [2020-10-19T18:46:41.304292 #1]  INFO -- : 
I, [2020-10-19T18:46:41.304434 #1]  INFO -- : > mkdir -p /shared/postgres_run/12-main.pg_stat_tmp
I, [2020-10-19T18:46:41.310575 #1]  INFO -- : 
I, [2020-10-19T18:46:41.310782 #1]  INFO -- : > chown postgres:postgres /shared/postgres_run/12-main.pg_stat_tmp
I, [2020-10-19T18:46:41.317554 #1]  INFO -- : 
I, [2020-10-19T18:46:41.322287 #1]  INFO -- : File > /etc/service/postgres/run  chmod: +x  chown: 
I, [2020-10-19T18:46:41.326660 #1]  INFO -- : File > /etc/service/postgres/log/run  chmod: +x  chown: 
I, [2020-10-19T18:46:41.330737 #1]  INFO -- : File > /etc/runit/3.d/99-postgres  chmod: +x  chown: 
I, [2020-10-19T18:46:41.334906 #1]  INFO -- : File > /root/upgrade_postgres  chmod: +x  chown: 
I, [2020-10-19T18:46:41.335100 #1]  INFO -- : > chown -R root /var/lib/postgresql/12/main
I, [2020-10-19T18:46:42.155381 #1]  INFO -- : 
I, [2020-10-19T18:46:42.155536 #1]  INFO -- : > [ ! -e /shared/postgres_data ] && install -d -m 0755 -o postgres -g postgres /shared/postgres_data && sudo -E -u postgres /usr/lib/postgresql/12/bin/initdb -D /shared/postgres_data || exit 0
I, [2020-10-19T18:46:42.157629 #1]  INFO -- : 
I, [2020-10-19T18:46:42.157703 #1]  INFO -- : > chown -R postgres:postgres /shared/postgres_data
I, [2020-10-19T18:47:06.520719 #1]  INFO -- : 
I, [2020-10-19T18:47:06.520876 #1]  INFO -- : > chown -R postgres:postgres /var/run/postgresql
I, [2020-10-19T18:47:06.523564 #1]  INFO -- : 
I, [2020-10-19T18:47:06.523706 #1]  INFO -- : > /root/upgrade_postgres
I, [2020-10-19T18:47:06.540126 #1]  INFO -- : 
I, [2020-10-19T18:47:06.540286 #1]  INFO -- : > rm /root/upgrade_postgres
I, [2020-10-19T18:47:06.542555 #1]  INFO -- : 
I, [2020-10-19T18:47:06.543828 #1]  INFO -- : Replacing data_directory = '/var/lib/postgresql/12/main' with data_directory = '/shared/postgres_data' in /etc/postgresql/12/main/postgresql.conf
I, [2020-10-19T18:47:06.544330 #1]  INFO -- : Replacing (?-mix:#?listen_addresses *=.*) with listen_addresses = '*' in /etc/postgresql/12/main/postgresql.conf
I, [2020-10-19T18:47:06.545027 #1]  INFO -- : Replacing (?-mix:#?synchronous_commit *=.*) with synchronous_commit = $db_synchronous_commit in /etc/postgresql/12/main/postgresql.conf
I, [2020-10-19T18:47:06.545814 #1]  INFO -- : Replacing (?-mix:#?shared_buffers *=.*) with shared_buffers = $db_shared_buffers in /etc/postgresql/12/main/postgresql.conf
I, [2020-10-19T18:47:06.546523 #1]  INFO -- : Replacing (?-mix:#?work_mem *=.*) with work_mem = $db_work_mem in /etc/postgresql/12/main/postgresql.conf
I, [2020-10-19T18:47:06.547230 #1]  INFO -- : Replacing (?-mix:#?default_text_search_config *=.*) with default_text_search_config = '$db_default_text_search_config' in /etc/postgresql/12/main/postgresql.conf
I, [2020-10-19T18:47:06.547896 #1]  INFO -- : > install -d -m 0755 -o postgres -g postgres /shared/postgres_backup
I, [2020-10-19T18:47:06.561717 #1]  INFO -- : 
I, [2020-10-19T18:47:06.562046 #1]  INFO -- : Replacing (?-mix:#?checkpoint_segments *=.*) with checkpoint_segments = $db_checkpoint_segments in /etc/postgresql/12/main/postgresql.conf
I, [2020-10-19T18:47:06.562327 #1]  INFO -- : Replacing (?-mix:#?logging_collector *=.*) with logging_collector = $db_logging_collector in /etc/postgresql/12/main/postgresql.conf
I, [2020-10-19T18:47:06.563080 #1]  INFO -- : Replacing (?-mix:#?log_min_duration_statement *=.*) with log_min_duration_statement = $db_log_min_duration_statement in /etc/postgresql/12/main/postgresql.conf
I, [2020-10-19T18:47:06.564238 #1]  INFO -- : Replacing (?-mix:^#local +replication +postgres +peer$) with local replication postgres  peer in /etc/postgresql/12/main/pg_hba.conf
I, [2020-10-19T18:47:06.564505 #1]  INFO -- : Replacing (?-mix:^host.*all.*all.*127.*$) with host all all 0.0.0.0/0 md5 in /etc/postgresql/12/main/pg_hba.conf
I, [2020-10-19T18:47:06.565039 #1]  INFO -- : > HOME=/var/lib/postgresql USER=postgres exec chpst -u postgres:postgres:ssl-cert -U postgres:postgres:ssl-cert /usr/lib/postgresql/12/bin/postmaster -D /etc/postgresql/12/main
I, [2020-10-19T18:47:06.566806 #1]  INFO -- : > sleep 5
2020-10-19 18:47:06.629 UTC [50] LOG:  starting PostgreSQL 12.4 (Debian 12.4-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.3.0-6) 8.3.0, 64-bit
2020-10-19 18:47:06.629 UTC [50] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2020-10-19 18:47:06.629 UTC [50] LOG:  listening on IPv6 address "::", port 5432
2020-10-19 18:47:06.665 UTC [50] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2020-10-19 18:47:07.211 UTC [53] LOG:  database system was interrupted; last known up at 2020-10-19 18:40:46 UTC
I, [2020-10-19T18:47:11.568937 #1]  INFO -- : 
I, [2020-10-19T18:47:11.569207 #1]  INFO -- : > su postgres -c 'createdb discourse' || true
2020-10-19 18:47:11.636 UTC [57] postgres@postgres FATAL:  the database system is starting up
2020-10-19 18:47:11.638 UTC [58] postgres@template1 FATAL:  the database system is starting up
createdb: error: could not connect to database template1: FATAL:  the database system is starting up
I, [2020-10-19T18:47:11.640042 #1]  INFO -- : 
I, [2020-10-19T18:47:11.640270 #1]  INFO -- : > su postgres -c 'psql discourse -c "create user discourse;"' || true
2020-10-19 18:47:11.704 UTC [69] postgres@discourse FATAL:  the database system is starting up
psql: error: could not connect to server: FATAL:  the database system is starting up
I, [2020-10-19T18:47:11.706232 #1]  INFO -- : 
I, [2020-10-19T18:47:11.706429 #1]  INFO -- : > su postgres -c 'psql discourse -c "grant all privileges on database discourse to discourse;"' || true
2020-10-19 18:47:11.761 UTC [80] postgres@discourse FATAL:  the database system is starting up
psql: error: could not connect to server: FATAL:  the database system is starting up
I, [2020-10-19T18:47:11.763159 #1]  INFO -- : 
I, [2020-10-19T18:47:11.763357 #1]  INFO -- : > su postgres -c 'psql discourse -c "alter schema public owner to discourse;"'
2020-10-19 18:47:11.818 UTC [91] postgres@discourse FATAL:  the database system is starting up
psql: error: could not connect to server: FATAL:  the database system is starting up
I, [2020-10-19T18:47:11.819734 #1]  INFO -- : 
I, [2020-10-19T18:47:11.819998 #1]  INFO -- : Terminating async processes
I, [2020-10-19T18:47:11.820025 #1]  INFO -- : Sending INT to HOME=/var/lib/postgresql USER=postgres exec chpst -u postgres:postgres:ssl-cert -U postgres:postgres:ssl-cert /usr/lib/postgresql/12/bin/postmaster -D /etc/postgresql/12/main pid: 50
2020-10-19 18:47:11.820 UTC [50] LOG:  received fast shutdown request
I, [2020-10-19T18:47:21.820568 #1]  INFO -- : HOME=/var/lib/postgresql USER=postgres exec chpst -u postgres:postgres:ssl-cert -U postgres:postgres:ssl-cert /usr/lib/postgresql/12/bin/postmaster -D /etc/postgresql/12/main pid:50 did not terminate cleanly, forcing termination!


FAILED
--------------------
Pups::ExecError: su postgres -c 'psql discourse -c "alter schema public owner to discourse;"' failed with return #<Process::Status: pid 81 exit 2>
Location of failure: /pups/lib/pups/exec_command.rb:112:in `spawn'
exec failed with the params "su postgres -c 'psql $db_name -c \"alter schema public owner to $db_user;\"'"
809e00dc988196b9a3c0bfe215ff0ba30fa00056e1d2ad92818bc6b9d911df62
** FAILED TO BOOTSTRAP ** please scroll up and look for earlier error messages, there may be more than one.
./discourse-doctor may help diagnose the problem.
gunnar@dewis:/var/discourse$
1 Mi Piace
2

Questa è una scelta molto particolare. Perché non usare RDS?

Ciò si verifica quando il contenitore non viene arrestato correttamente, quindi PostgreSQL dovrà eseguire un processo di recupero al prossimo avvio.

Di solito questo processo è molto veloce, ma se il tuo database è grande (come nel tuo caso) e/o il disco è lento (davvero nel tuo caso), potrebbe essere troppo lento e il nostro script di rebuild non sa come gestire la situazione.

Un metodo semplice di recupero è riavviare il contenitore con ./launcher start app, lasciarlo funzionare serenamente per un po’ di tempo (diciamo un’ora) e provare a eseguire il rebuild in seguito.

5 Mi Piace
3

Perché non ho la minima idea di come iniziare a implementarlo. È un’idea interessante, però.

EFS è semplicemente un file system, quindi facile da implementare. E abbastanza veloce per le operazioni normali, almeno per il nostro caso d’uso. O, almeno, questo è quello che pensavo.

Esatto, è quello che pensavo. La parte interessante è che quando ho avviato il launcher, Discourse era già in esecuzione da un po’. Quindi, è stato lo script del launcher stesso ad arrestare PostgreSQL.

OK, proverò così. Grazie!

2 Mi Piace
4

Sai quando è stato l’ultimo rebuild precedente?

Ho aumentato il tempo di attesa per l’arresto corretto del DB in wait a bit more if necessary for container stop · discourse/discourse_docker@49ed141 · GitHub, quindi se eri in una versione precedente a quell’commit, questo era un problema comune.

2 Mi Piace
5

Non sono sicuro, ma è stato sicuramente dopo maggio, quando ho visto che la modifica è stata commitata. Probabilmente più o meno un mese fa. Puoi anche vedere “-t 60” nell’output qui sopra.

Ho appena provato di nuovo il rebuild e questa volta è andato a buon fine. Immagino che in futuro dovrò prima verificare e assicurarmi che PostgreSQL sia inattivo o quasi inattivo prima di avviare il rebuild.

Grazie per tutto il tuo aiuto!

2 Mi Piace
6

Non so come abbia fatto a non notarlo :man_facepalming:.

Ricordi se quel passaggio ha impiegato l’intero minuto e ha continuato dopo?

Yay!

1 Mi Piace
7

Non posso dirlo con certezza, ma sono quasi sicuro che non abbia richiesto 60 secondi. D’ora in poi, quando ricostruirò, farò più attenzione a questo aspetto.

2 Mi Piace
8

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.