Re: PostgreSQL 11 can not restart after an unexpected shutdown

Hi,

I would like to republish my previous bug report, because the pictures were
eliminated and it made harder to understand the problem.
Link to the previous post:
https://www.postgresql.org/message-id/CAJtpbKT6U91U7-zTRpSpp9T0nXB%2BxdJcR8gSTYVzGs7Eb0Svaw%40mail.gmail.com

Sporadically the PostgreSQL 11 server can not be restarted when an
unexpected restart occurs with user defined table spaces.

Unexpected shutdown:
Picture: https://i.imgur.com/c7QM120.png

Event logs:
After restart the postgresql does the following based on the event logs:
1. "Wating for server startup..."
2. "2019-07-05 16:15:22.661 CEST [4608] LOG: listening on IPv6 address
"::", port 5432"
3. "2019-07-05 16:15:22.661 CEST [4608] LOG: listening on IPv4 address
"0.0.0.0", port 5432"
4. "2019-07-05 16:15:23.548 CEST [4608] LOG: could not open directory
"pg_tblspc/211347/PG_11_201809051": No such file or directory"
5. "2019-07-05 16:15:23.548 CEST [4608] LOG: could not open directory
"pg_tblspc/211349/PG_11_201809051": No such file or directory"
... (Plenty of this kind of logs about could not open directory pg_tblspc)
6. "2019-07-05 16:15:23.618 CEST [4608] LOG: redirecting log output to
logging collector process
2019-07-05 16:15:23.618 CEST [4608] HINT: Future log output will
appear in directory "log"."
7. ERROR level: "Timed out waiting for server startup"
8. Waiting for server startup...
9. ERROR level: "2019-07-05 16:17:50.381 CEST [10168] FATAL: lock file
"postmaster.pid" already exists
2019-07-05 16:17:50.381 CEST [10168] HINT: Is another postmaster (PID
4608) running in data directory "C:/Program Files/PostgreSQL/11/data"?"
10. ERROR level: "Timed out waiting for server startup"

Then it keeps trying without a success:
Picture:
https://i.imgur.com/YQ74JGx.png

Boot time:
Picture: https://i.imgur.com/M5qwy7H.png

Postgresql Logs:
2019-07-05 16:15:24.153 CEST [6668] LOG: database system was interrupted;
last known up at 2019-07-05 16:09:51 CEST
2019-07-05 16:18:04.155 CEST [6668] LOG: could not stat file
"./pg_tblspc/211347": No such file or directory
.."Plenty of logs about this "could not stat file..."...
2019-07-05 16:18:30.623 CEST [6668] LOG: could not open directory
"pg_tblspc/211347/PG_11_201809051": No such file or directory
.."Plenty of logs about this "could not open directory"...
*2019-07-05 16:18:30.632 CEST [6668] LOG: database system was not properly
shut down; automatic recovery in progress*
2019-07-05 16:18:31.209 CEST [6668] LOG: redo starts at A/1CC62250
2019-07-05 16:18:31.210 CEST [6668] WARNING: could not open directory
"pg_tblspc/310943/PG_11_201809051/310944": No such file or directory
2019-07-05 16:18:31.210 CEST [6668] CONTEXT: WAL redo at A/1CC622F8 for
Database/DROP: dir 310944/310943
2019-07-05 16:18:31.210 CEST [6668] WARNING: some useless files may be
left behind in old database directory
"pg_tblspc/310943/PG_11_201809051/310944"
2019-07-05 16:18:31.210 CEST [6668] CONTEXT: WAL redo at A/1CC622F8 for
Database/DROP: dir 310944/310943
2019-07-05 16:18:31.210 CEST [6668] LOG: could not stat file
"pg_tblspc/310810": No such file or directory
2019-07-05 16:18:31.210 CEST [6668] CONTEXT: WAL redo at A/1CC63348 for
Tablespace/DROP: 310810
2019-07-05 16:18:31.210 CEST [6668] LOG: could not stat file
"pg_tblspc/310943": No such file or directory
2019-07-05 16:18:31.210 CEST [6668] CONTEXT: WAL redo at A/1CC633E8 for
Tablespace/DROP: 310943
2019-07-05 16:18:32.542 CEST [6668] LOG: invalid record length at
A/1CC696A8: wanted 24, got 0
2019-07-05 16:18:32.542 CEST [6668] LOG: redo done at A/1CC69670
2019-07-05 16:18:32.690 CEST [6668] LOG: last completed transaction was at
log time 2019-07-05 16:09:53.420563+02
2019-07-05 16:18:32.693 CEST [6668] LOG: could not open directory
"pg_tblspc/211347/PG_11_201809051": No such file or directory
.."Plenty of logs about this "could not open directory"...
2019-07-05 16:18:35.488 CEST [4608] LOG: database system is ready to
accept connections
*(^But the pg_ctl does not running therefore in the eventlogs it can be
seen that:*
Picture: https://i.imgur.com/TKrulAa.png

In the services window it looks like that the postgresql does not running
but it is running without the pg_ctl:
Picture: https://i.imgur.com/3jA4Mc5.png

So in case i want to start the postgresql manually in the services it does
not allow me, so I have to kill these processes and restart the Postgresql.

Configuration: Windows 10
Version: "PostgreSQL 11.1, compiled by Visual C++ build 1914, 64-bit"

Note: MS SQL Server is also installed on the device.

Best Regards,
Adam Maracska

Ádám Maracska <csusza(at)gmail(dot)com> ezt írta (időpont: 2019. júl. 8., H, 9:45):

> Hi,
>
>
> Sporadically the PostgreSQL 11 server can not be restarted when an
> unexpected restart occurs with user defined table spaces.
>
> Unexpected shutdown:
>
> [image: systemrebootunexp.PNG]
>
> Event logs:
> After restart the postgresql does the following based on the event logs:
> 1. "Wating for server startup..."
> 2. "2019-07-05 16:15:22.661 CEST [4608] LOG: listening on IPv6 address
> "::", port 5432"
> 3. "2019-07-05 16:15:22.661 CEST [4608] LOG: listening on IPv4 address
> "0.0.0.0", port 5432"
> 4. "2019-07-05 16:15:23.548 CEST [4608] LOG: could not open directory
> "pg_tblspc/211347/PG_11_201809051": No such file or directory"
> 5. "2019-07-05 16:15:23.548 CEST [4608] LOG: could not open directory
> "pg_tblspc/211349/PG_11_201809051": No such file or directory"
> ... (Plenty of this kind of logs about could not open directory pg_tblspc)
> 6. "2019-07-05 16:15:23.618 CEST [4608] LOG: redirecting log output to
> logging collector process
> 2019-07-05 16:15:23.618 CEST [4608] HINT: Future log output will
> appear in directory "log"."
> 7. ERROR level: "Timed out waiting for server startup"
> 8. Waiting for server startup...
> 9. ERROR level: "2019-07-05 16:17:50.381 CEST [10168] FATAL: lock file
> "postmaster.pid" already exists
> 2019-07-05 16:17:50.381 CEST [10168] HINT: Is another postmaster (PID
> 4608) running in data directory "C:/Program Files/PostgreSQL/11/data"?"
> 10. ERROR level: "Timed out waiting for server startup"
>
> Then it keeps trying without a success:
> [image: image.png]
>
> Boot time:
> [image: image.png]
>
>
>
> Postgresql Logs:
> 2019-07-05 16:15:24.153 CEST [6668] LOG: database system was interrupted;
> last known up at 2019-07-05 16:09:51 CEST
> 2019-07-05 16:18:04.155 CEST [6668] LOG: could not stat file
> "./pg_tblspc/211347": No such file or directory
> .."Plenty of logs about this "could not stat file..."...
> 2019-07-05 16:18:30.623 CEST [6668] LOG: could not open directory
> "pg_tblspc/211347/PG_11_201809051": No such file or directory
> .."Plenty of logs about this "could not open directory"...
> *2019-07-05 16:18:30.632 CEST [6668] LOG: database system was not
> properly shut down; automatic recovery in progress*
> 2019-07-05 16:18:31.209 CEST [6668] LOG: redo starts at A/1CC62250
> 2019-07-05 16:18:31.210 CEST [6668] WARNING: could not open directory
> "pg_tblspc/310943/PG_11_201809051/310944": No such file or directory
> 2019-07-05 16:18:31.210 CEST [6668] CONTEXT: WAL redo at A/1CC622F8 for
> Database/DROP: dir 310944/310943
> 2019-07-05 16:18:31.210 CEST [6668] WARNING: some useless files may be
> left behind in old database directory
> "pg_tblspc/310943/PG_11_201809051/310944"
> 2019-07-05 16:18:31.210 CEST [6668] CONTEXT: WAL redo at A/1CC622F8 for
> Database/DROP: dir 310944/310943
> 2019-07-05 16:18:31.210 CEST [6668] LOG: could not stat file
> "pg_tblspc/310810": No such file or directory
> 2019-07-05 16:18:31.210 CEST [6668] CONTEXT: WAL redo at A/1CC63348 for
> Tablespace/DROP: 310810
> 2019-07-05 16:18:31.210 CEST [6668] LOG: could not stat file
> "pg_tblspc/310943": No such file or directory
> 2019-07-05 16:18:31.210 CEST [6668] CONTEXT: WAL redo at A/1CC633E8 for
> Tablespace/DROP: 310943
> 2019-07-05 16:18:32.542 CEST [6668] LOG: invalid record length at
> A/1CC696A8: wanted 24, got 0
> 2019-07-05 16:18:32.542 CEST [6668] LOG: redo done at A/1CC69670
> 2019-07-05 16:18:32.690 CEST [6668] LOG: last completed transaction was
> at log time 2019-07-05 16:09:53.420563+02
> 2019-07-05 16:18:32.693 CEST [6668] LOG: could not open directory
> "pg_tblspc/211347/PG_11_201809051": No such file or directory
> .."Plenty of logs about this "could not open directory"...
> 2019-07-05 16:18:35.488 CEST [4608] LOG: database system is ready to
> accept connections
> *(^But the pg_ctl does not running therefore in the eventlogs it can be
> seen that:*
> [image: image.png]
>
> In the services window it looks like that the postgresql does not running
> but it is running without the pg_ctl:
> [image: image.png]
>
> So in case i want to start the postgresql manually in the services it does
> not allow me, so I have to kill these processes and restart the Postgresql.
>
>
> Configuration: Windows 10
> Version: "PostgreSQL 11.1, compiled by Visual C++ build 1914, 64-bit"
>
> Note: MS SQL Server is also installed on the device.
>
>
> Best Regards,
> Adam Maracska
>