No i co tu poradzić? Połączenia do bazy danych czasami się udają, ale nawet wtedy po krótkiej chwili sesja jest zabijana i można znaleźć komunikaty
WARNING: terminating connection because of crash of another server process DETAIL: The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory. HINT: In a moment you should be able to reconnect to the database and repeat your command. server closed the connection unexpectedly This probably means the server terminated abnormally before or while processing the request. The connection to the server was lost. Attempting reset: Failed.
edb-psql: error: FATAL: the database system is in recovery mode
Zwykle pierwszym dobrym krokiem, kiedy chce się zobaczyć coś więcej od środka, jest analiza zapisów w logu systemowym. Znajdziesz je w /var/lib/edb/as13/data/logs. Log pełen był zapisów w postaci:
2021-07-18 08:28:51 UTC LOG: database system is ready to accept connections
2021-07-18 08:28:51 UTC LOG: dbms_aq launcher started
2021-07-18 08:29:14 UTC LOG: duration: 7574.980 ms statement: SELECT pem.process_one_alert()
2021-07-18 08:29:15 UTC LOG: server process (PID 15066) was terminated by signal 11: Segmentation fault
2021-07-18 08:29:15 UTC DETAIL: Failed process was running: WITH agent_info AS ( SELECT ar.agent_id, ar
.runtime_id FROM pem.agent a JOIN pem.agent_runtime ar ON (a.active AND ar.agent_id = a.id) WHERE a.id =
1), jobs AS ( UPDATE pem.job J SET jobarid = A.runtime_id, joblastrun=now(), agent_id=A.agent_id FROM a
gent_info A WHERE (J.agent_id = A.agent_id OR J.is_global_job = true) AND J.jobenabled AND (J.jobarid IS
NULL OR A.runtime_id != J.jobarid) AND J.jobnextrun <= now() AND ( dependent_on_job IS NULL OR pem.job
_is_complete( dependent_on_job, execute_on_dep_job_status, jobid )) RETURNING J.jobid, J.jobnextrun)
INSERT INTO pem.joblog(jlgid, jlgjobid, jlgstatus) SELECT nextval('pem.joblog_jlgid_seq'), jobid, 'r' FR
OM jobs ORDER BY jobnextrun RETURNING jlgjobid, jlgid
2021-07-18 08:29:15 UTC LOG: terminating any other active server processes
2021-07-18 08:29:15 UTC WARNING: terminating connection because of crash of another server process
2021-07-18 08:29:15 UTC DETAIL: The postmaster has commanded this server process to roll back the curre
nt transaction and exit, because another server process exited abnormally and possibly corrupted shared
memory.
2021-07-18 08:29:15 UTC HINT: In a moment you should be able to reconnect to the database and repeat yo
ur command.
Niby to trochę lepiej, bo widać już zapytanie, przy którym dochodzi do błędu, ale… i tak nic to nie mówi w zakresie kolejnych kroków do wykonania. Rzeczywiście, ten serwer był monitorowany przez PEM, rzeczywiście PEM zgłaszał serwer jako niedostępny, ale… to raczej skutek tego problemu, a nie przyczyna. Jakoś nie chce mi się wierzyć w to, że zapytanie generowane przez agenta PEM powoduje „segmentation fault” na systemie. Użytkownicy wysyłający zwariowane zapytania powinni być skutecznie odfiltrowani przez serwer bazy danych, który jeśli widzi, że koszt zapytania jest nieakceptowalny, raczej zakończy w łagodny sposób taką sesję, niż pozwoli przewrócić się na łopatki.
No ale skoro błąd wygląda na systemowy, wewnątrz procesu postgres, to może coś uda się znaleźć w logu sytemowym w /var/log/messages? Rzeczywiście:
Jul 18 07:26:05 dbserv10 systemd-coredump[10160]: Process 10141 (edb-postmaster) of user 1005 dumped core.#012#012Stack trace of thread 10141:#012#0 0x00007f771aeb3e93 __memmove_avx_unaligned_erms (libc.so.6)#012#1 0x00000000006f1398 list_delete_nt h_cell (edb-postgres)#012#2 0x00007f7714e8cbe9 index_advisor (index_advisor.so)#012#3 0x00007f7714e8d0db planner_callback ( index_advisor.so)#012#4 0x0000000000745e49 planner (edb-postgres)#012#5 0x000000000080b301 pg_plan_query (edb-postgres)#012 #6 0x000000000080b3f3 pg_plan_queries (edb-postgres)#012#7 0x0000000000931703 BuildCachedPlan (edb-postgres)#012#8 0x00000 00000931924 GetCachedPlan (edb-postgres)#012#9 0x00000000006c3e52 _SPI_execute_plan (edb-postgres)#012#10 0x00000000006c48b6 SPI_execute_plan_with_paramlist (edb-postgres)#012#11 0x00007f76d6a96386 exec_stmt_execsql (plpgsql.so)#012#12 0x00007f76d6a 970a3 exec_stmt (plpgsql.so)#012#13 0x00007f76d6a9a33b exec_stmts (plpgsql.so)#012#14 0x00007f76d6a9a6c9 exec_stmt_block (plp gsql.so)#012#15 0x00007f76d6a97deb exec_stmt (plpgsql.so)#012#16 0x00007f76d6a99ed6 plpgsql_exec_function (plpgsql.so)#012#17
W wygenerowanym tutaj bełkocie odnajduje się słowo „index_advisor”. To rozszerzenie jest uruchamiane wewnatrz procesu postgresql i szczerze – mało mu ufam. Byłbym więc w stanie wyobrazić sobie sytuację, w której jakiś wewnętrzny bug index_advisora powoduje awarię całego procesu postgres obsługującego sesję. Dlatego postanowiłem to sprawdzić i wyłączyć index_advisora. Robi się to przez modyfikację pliku
/var/lib/edb/as13/data/postgresql.conf
Odpowiedni wpis dotyczący index_advisora należy usunąć z parametru
shared_preload_libraries
Po restarcie postgresa
pg_ctl restart
… wszystkie problemy zniknęły. Bazy są dostępne, można się do nich podłączyć i nawet PEM zaczął je raportować jako dostępne. Bingo!
