PostgreSQL 11 can not restart after an unexpected shutdown

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
2 messages Options
Reply | Threaded
Open this post in threaded view
|

PostgreSQL 11 can not restart after an unexpected shutdown

csusza
Hi,


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

Unexpected shutdown:

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.png

Boot time:
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.png

In the services window it looks like that the postgresql does not running but it is running without the pg_ctl:
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
Reply | Threaded
Open this post in threaded view
|

Re: PostgreSQL 11 can not restart after an unexpected shutdown

csusza
Hi,

I would like to republish my previous bug report, because the pictures were eliminated and it made harder to understand the problem.


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 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:


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 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:


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 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 <[hidden email]> 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:

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.png

Boot time:
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.png

In the services window it looks like that the postgresql does not running but it is running without the pg_ctl:
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