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"
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:
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
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
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@gmail.com> ezt írta (időpont: 2019. júl. 8., H, 9:45):
Hi,8. Waiting for server startup...Sporadically the PostgreSQL 11 server can not be restarted when an unexpected restart occurs with user defined table spaces.Unexpected shutdown: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 process2019-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"9. ERROR level: "2019-07-05 16:17:50.381 CEST [10168] FATAL: lock file "postmaster.pid" already exists2019-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:Boot time: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 progress2019-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:In the services window it looks like that the postgresql does not running but it is running without the pg_ctl: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 10Version: "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
Вложения
В списке pgsql-bugs по дате отправления: