Re: logical replication snapshots

On 2018-07-25 12:31:01 -0700, Adrian Klaver wrote:
> On 07/25/2018 11:10 AM, Dimitri Maziuk wrote:
> > On 07/25/2018 11:16 AM, Adrian Klaver wrote:
> >
> > > Where you using pg_export_snapshot() by any chance?:
> >
> > If it's not in chapter 31 of TFM then I have not touched it. The only
> > notable thing I changed from 31.9 quickstart is that replica identity is
> > full on all tables (the data's a mess).
>
> So no.
>
> >
> > > Where there any relevant error messages in the log before the database
> > > hung?
> >
> > Do you seriously expect me to know what "relevant" is? ;) -- It's 7
> > days' worth of
>
> Generally speaking relevancy increases the closer you get to the fall over
> event. So we are most interested in entries close to the point where the
> database stopped/failed.
>
> >
> > > 2018-07-23 09:43:12.851 CDT [7975] STATEMENT: COPY macromolecules."Entity_common_name" TO STDOUT
> > > 2018-07-23 09:43:12.925 CDT [7982] LOG: logical decoding found consistent point at 19/E6942408
> > > 2018-07-23 09:43:12.925 CDT [7982] DETAIL: There are no running transactions.
> > > 2018-07-23 09:43:12.935 CDT [7982] ERROR: permission denied for schema macromolecules
> > > 2018-07-23 09:43:12.935 CDT [7982] STATEMENT: COPY macromolecules."Assembly" TO STDOUT
> > > 2018-07-23 09:43:13.034 CDT [7987] LOG: logical decoding found consistent point at 19/E6942440
> > > 2018-07-23 09:43:13.034 CDT [7987] DETAIL: There are no running transactions.
> > > 2018-07-23 09:43:13.044 CDT [7987] ERROR: permission denied for schema macromolecules
> > > 2018-07-23 09:43:13.044 CDT [7987] STATEMENT: COPY macromolecules."Spectral_transition" TO STDOUT
> > > 2018-07-23 09:43:13.135 CDT [7990] LOG: logical decoding found consistent point at 19/E6942478
> > > 2018-07-23 09:43:13.135 CDT [7990] DETAIL: There are no running transactions.
> > > 2018-07-23 09:43:13.145 CDT [7990] ERROR: permission denied for schema macromolecules
> > > 2018-07-23 09:43:13.145 CDT [7990] STATEMENT: COPY macromolecules."Assembly_db_link" TO STDOUT
> >
> > that ends with
> >
> > > 2018-07-23 09:45:40.280 CDT [6032] LOG: database system was interrupted; last known up at 2018-07-06 17:04:28 CDT
> > > 2018-07-23 09:45:40.281 CDT [6033] FATAL: the database system is starting up
> > > 2018-07-23 09:45:40.282 CDT [6034] FATAL: the database system is starting up
> > ... ad infinitum ...
> >
> > Would "permission denied" be relevant?
>
> Logical decoding is something I am still learning. The "permission denied"
> would to me be relevant only to the extent that it seems to be provoking:

Yes, it looks related. Looks like logical rep was trying to perform the
intiial sync of those tables, and couldn't due to permission errors.

> "LOG: logical decoding found consistent point at 19/E6942440"
> DETAIL: There are no running transactions."
>
> Others with more experience in this area would need to fill whether that
> might account for the 13 million files in the ~snapshot/ directory.

That indicates there's some error handling issues to be resolved. Petr?

Greetings,

Andres Freund