K7 / GCScheduler sa po reštarte Kraméria nespustí

[rrandiak]

Ahoj,

sem tam sa nám stane, že Kramérius prestane spúšťať naplánované procesy. Podľa toho čo som vysledoval, táto situácia nastane keď sa po štarte Kraméria GCScheduler nedokáže pripojiť k db. Nie som si istý prečo sa nedokáže pripojiť, je možné, že to spôsobuje nejaký network výpadok u nás v Kubernetes, neviem. Chyba na ktorej to padá je:
SEVERE [cz.incad.kramerius.processes.impl.GCSchedulerImpl-thread] cz.incad.kramerius.processes.GCFindCandiatesTask.run connection not ready

V každom prípade Kramérius následne beží ďalej ako by sa nič nestalo a spúšťanie procesov už nepôjde, až do ďalšieho reštartu. Keďže Kramérius nespadne, tak ho Kubernetes nereštartuje, lebo podľa neho je všetko ok. Preto by som navrhoval aby na tejto chybe Kramérius spadol, alebo aby sa scheduler pokúsil o pripojenie na viac krát, alebo nejaký iný fix.

Prikladám logy z Kraméria z dvoch takýchto výpadkov, a logy z procesov, ktoré v tom čase bežali. V logoch procesov podľa mňa nič zaujímave nie je, ale pribalil som ich pre úplnosť.
logs.zip

Róbert, MZK - OSDD

[vlahoda]

V logu Tomcatu by ve stejnem case, kdy v procesu byla vypsana chyba connection not ready, mela byt videt SQLException s presnym duvodem, proc connection neni k dipozici. Je pravdepodobne, ze je vycerpany connection pool nebo neco podobneho.

Mozna by pomohlo zvysit velikost poolu v configuration.properties, defaultni hodnota je jdbcMaximumPoolSize=20

[rrandiak]

04-Oct-2023 19:23:30.364 SEVERE [cz.incad.kramerius.processes.impl.GCSchedulerImpl-thread] com.zaxxer.hikari.pool.HikariPool.throwPoolInitializationException HikariPool-1 - Exception during pool initialization. org.postgresql.util.PSQLException: The connection attempt failed. at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:313)
...
Caused by: java.net.SocketTimeoutException: Connect timed out at java.base/sun.nio.ch.NioSocketImpl.timedFinishConnect(NioSocketImpl.java:546) at java.base/sun.nio.ch.NioSocketImpl.connect(NioSocketImpl.java:597) at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:327)
...
04-Oct-2023 19:23:30.364 INFO [cz.incad.kramerius.processes.impl.ProcessSchedulerImpl-thread] com.zaxxer.hikari.HikariDataSource.getConnection HikariPool-1 - Starting... 04-Oct-2023 19:23:30.364 SEVERE [cz.incad.kramerius.processes.impl.GCSchedulerImpl-thread] cz.incad.kramerius.processes.database.Kramerius4ConnectionProvider.get The connection attempt failed. org.postgresql.util.PSQLException: The connection attempt failed. at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:313) at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:51)
...
Caused by: java.net.SocketTimeoutException: Connect timed out at java.base/sun.nio.ch.NioSocketImpl.timedFinishConnect(NioSocketImpl.java:546) at java.base/sun.nio.ch.NioSocketImpl.connect(NioSocketImpl.java:597) at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:327)

Áno, SQLException tam je. Ale ako cause sa udáva Connect timed out a neviem čo si mám z toho vyvodiť.

[vlahoda]

To by mohlo byt zpusobene tim, ze kontejner postgresql jeste neni pripraven a tomcat uz se na nej snazi pripojit - ta vyjimka se objevi zrejme hned pri startu tomcatu, kdyz se startuje thread HikariPool-1.
Upravil jsem ted kod toho connection provideru, aby ta skutecna pricina "probublala" vys i do logu procesu, takze se to bude lip hledat. Bude ale podle me potreba zkontrolovat, jak jsou nastavene zavislosti mezi kontejnery v Kubernetes.

[zabak]

@r2it-git je možné uzavřít?

[rrandiak]

@zabak nie, keďže stále používame v7.0.29, tak úprava od pána Lahodu u nás ešte nie je nasadená a neviem to replikovať na dev inštancií (na novšej verzií). V každom prípade stále sa to stáva cca raz za 2 týždne, vtedy reštartujem Kramérius manuálne a následne to ide.

Uvidíme, možno to nejak súvisí s tými otvorenými socketmi, čo sa riešilo u nás na Slacku v roomke K7.

[rrandiak]

Ahoj,

nastal ďalší takýto výpadok, počas behu Kraméria a proces ostal zaseknutý v stave Naplánováno. Stalo sa to v našom import Kramériu v7.0.36. V tomto Kramériu sa iba plánujú import procesy a nijak sa tam nepristupuje, čiže tie logy sú "čisté" a vidno tam iba pár random hlášok a vznik tejto chyby. Keďže sa do tohto Kraméria nijak nepristupuje tak medzi 11.9. a 17.9. tam nie sú žiadne logy, nemajú byť aké.

catalina.2024-09-11.log
catalina.2024-09-17.log

Proces logy žiadne neboli, keďže sa ten proces nepustil. Po reštarte Kraméria tento proces zbehol bez problémov.

Róbert Randiak - MZK

[vlahoda]

Ahoj, problem je v tom, ze Kramerius nemohl navazat spojeni s databazi postgresql. Pritom jeste 11.9. v 5:34 doslo k restartu Tomcatu krameria a to se jeste connection pool inicializoval spravne. V 9:50 ale uz pri pokusu o start procesu connection pool hlasi, ze vsechna spojeni jsou mrtva, nedokaze vytvorti nove, protoze databaze na adrese postgres:5432 neodpovida a proces se tedy nenastartuje. Muzes zkontrolovat, co se v te dobe delo s databazi?

[rrandiak]

No k tým logom sa už nedostanem, ale predpokladám, že to mohol byť nejaký výpadok v kubernetes sieťovaní. Ale to by malo byť jedno z akého dôvodu vypadne postgres.
Podľa môjho názoru by taký výpadok mal Kramérius zvládnuť. Buď počkať na spojenie, alebo po nejakých timeoutoch sa reštartovať.

[vlahoda]

@pavel-stastny Chyba je zrejme v tom, ze ve tride NextSchedulerTask na radku 54 se pri chybe pri spousteni procesu vypne processScheduler a uz se znovu nespusti.

[pavel-stastny]

@r2it-git Nyní se scheduler po neúspěšném pokusu o spojení neukončuje. V Hikari datasrouce je nastavená proměnná socketTimeout, která definuje timeout pro maximální dostupnost/nedostupnost databáze.