Dotaz: Pře s vývojářem - java jdbc padá v produkci a jeho vývojovém prostředí nikoliv

[majales]

Zdravím, řeším problém s padajícím jdbc spojením z tomcatu8 na ubuntu 16 na MS SQL 2012 server. Nejsem ajva programátor, ale systémový admin. Vývojář vyvinul a odzkoušel na svém vývojovém prostředí jednu komponentu systému, která však v produkčním prostředí nefunguje. Demonstroval názorně, že jemu vše funguje, a že svoji práci odvedl.

Jako systémový admin ovšem neumím najít orpověď na to proč to v produkční prostředí nefunguje. tedy funguje tak že po 5-15 requestech do DB vše skončí následující chybou:

10:23:43,757 WARN  ~ SQL Error: 0, SQLState: null
10:23:43,759 ERROR ~ An attempt by a client to checkout a Connection has timed out.
10:23:44,701 ERROR ~

@79fn991al
Internal Server Error (500)

Oops: PersistenceException
An unexpected error occured caused by exception PersistenceException: org.hibernate.exception.GenericJDBCException: Cannot open connection

play.exceptions.UnexpectedException: Unexpected Error
        at play.Invoker$Invocation.onException(Invoker.java:244)
        at play.Invoker$Invocation.run(Invoker.java:286)
        at play.server.ServletWrapper$ServletInvocation.run(ServletWrapper.java:548)
        at play.Invoker.invokeInThread(Invoker.java:68)
        at play.server.ServletWrapper.service(ServletWrapper.java:142)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:292)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:494)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:141)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
        at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:616)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:522)
        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1095)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:672)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1520)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1476)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)
Caused by: javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: Cannot open connection
        at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1214)
        at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1147)
        at org.hibernate.ejb.AbstractEntityManagerImpl.throwPersistenceException(AbstractEntityManagerImpl.java:1224)
        at org.hibernate.ejb.TransactionImpl.begin(TransactionImpl.java:63)
        at play.db.jpa.JPAPlugin.startTx(JPAPlugin.java:350)
        at play.db.jpa.JPAPlugin.beforeInvocation(JPAPlugin.java:318)
        at play.plugins.PluginCollection.beforeInvocation(PluginCollection.java:428)
        at play.Invoker$Invocation.before(Invoker.java:217)
        at play.Invoker$Invocation.run(Invoker.java:277)
        ... 25 more
Caused by: org.hibernate.exception.GenericJDBCException: Cannot open connection
        at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:140)
        at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:128)
        at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
        at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:52)
        at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:449)
        at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167)
        at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:160)
        at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81)
        at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473)
        at org.hibernate.ejb.TransactionImpl.begin(TransactionImpl.java:60)
        ... 30 more
Caused by: java.sql.SQLException: An attempt by a client to checkout a Connection has timed out.
        at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:106)
        at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:65)
        at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:71)
        at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446)
        ... 35 more
Caused by: com.mchange.v2.resourcepool.TimeoutException: A client timed out while waiting to acquire a resource from com.mchange.v2.resourcepool.BasicResourcePool@e8d5b34 -- ti
meout at awaitAvailable()
        at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1317)
        at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:557)
        at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477)
        ... 37 more

K otestování se používá bash smyčka s 20-30 voláními vůči aplikaci. Aplikace se připojuje do DB a ověřuje uživatele. V application.conf je v podstatě jen připojení do DB a driver

db.url=jdbc:sqlserver://aaaa.server-sql.local:1433;databaseName=firma;user=proxy;password=tajneheslo123;
db.driver=com.microsoft.sqlserver.jdbc.SQLServerDriver

Nevíte kde by mohl být zakopaný pes?

---

---

Odpovědi

[NN]

Nema databaze omezeni na pocet spojeni, nebo nedrzi nova spojeni moc dlouho? Protoze podle hlasek se klient noveho spojeni nedocka ie .nelze se spojit z databazi:

An attempt by a client to checkout a Connection has timed out.
GenericJDBCException: Cannot open connection
TimeoutException: A client timed out while waiting to acquire a resource from com.mchange.v2.resourcepool.BasicResourcePool@e8d5b34

[dustin]

Navážu na to - tazatel píše, že se program spouští opakovaně ve smyčce. Tedy vlastní program konexi pustí (skončil), ale dozví se to databáze? Nechybí v aplikaci explicitní uzavření konexe při jejím ukončení, které by to dalo DB vědět?

Někde v této oblasti (max. počet konexí, timeout pro automatické uzavření apod.) se bude lišit vývojové prostředí od produkce.

[majales]

Pravdouje že počet konexí by mohl hrát roli, i když počet konexí je MS SQL nastaven na 0 čili neomezený. I když po tom pádu tam zůstává viset 30 konexí javy do DB.. možná to je ten problém..

[majales]

Tak jsem zvýšil connection pool na 60 a při testu se to zastavilo na 60 otevřených spojení do DB a pak to zase spadlo. Takže to asi neumí uvolňovat spojení do DB. Nebo jak to vlastně je? Uvolňuje se spojení a znovu navazuje, nebo se dělá reuse existujících spojení?

[debian+]

Co ak klient nezatvara spojenia po nacitani stranky? Nechava ich otvorene, tak potom ti skonci limit? ... este moze .... pripadne klient ma limit, kolko ma maximalne otvorenych spojeni

[cronin]

Pokud používáš connection pool, tak se spojení do DB nezavírají, ale když je aplikace "zavře", tak se vrátí do poolu a čekají tam na reuse.

Problém je pravděpodobně v tom, že aplikace spojení do poolu nevrací, a pool má omezenou kapacitu, takže časem dojdou. Ve vývojovém prostředí to funguje, protože je pool jinak nastavený (možná se vůbec nepoužívá), nebo se nedělá dost dotazů aby se vyčerpal.

Vývojář musí spojení správně zavírat (nebo jinak vracet do poolu, závisí na knihovně a na aplikačním serveru), když už je nepotřebuje.

BTW to že se spojení nemusí navazovat znova, je hlavní smysl poolu; u některých DB (ehm Oracle ehm) je otevření nového spojení velmi pomalé. To že je velikost poolu omezená je taky užitečné: chyba v aplikaci pak nevyčerpá zdroje pro ostatní aplikace které používají tu samou DB.

[Ivan]

Souhlasim, kdyby byla chyba v databazi anebo v infrastrukture, tak by se nekde ve stacktrace objevilo slovo "microsoft" a bylo by jasne, ze chybu reportoval JDBC driver.

Na druhou stranu ovsem moc nechapu jak se to mohlo stat protoze v hibernate obycene nepracujete s JDBC konexi primo a navraceni konexe do poolu se stara sam framework. A i kdyby program pracoval primo s JDBC konexi, tak Java uz davno obsahuje konstrukt try-with-resources.

[rADOn]

Dalsi pricina muze byt ze se connection pool naopak nepouziva (nebo pouziva blbe) a otevira se moc novych spojeni. Podivej se netstatem jestli nemas moc socketu ve stavu CLOSE_WAIT nebo TIME_WAIT.

[OldFrog {Ondra Nemecek}]

Ať vývojář sdělí, jak to spojení do db v Hibernate vlastně nastavuje. Vývojář práci odvedl, ale tohle bude muset opravit nebo pomoct se správným nastavením na produkci (poskytnout dokumentaci).

Adminovi by měl sdělit požadavky na nastavení aplikace. Nevím, odkud pochází application.conf, ale často se nastavuje connection pool jako datasource přímo v contextu aplikace - pomocí elementu Resource (např. conf/Catalina/vhost/ROOT.xml). Tam je uvedena i velikost poolu apod. Aplikace pak ten datasource jen použije. To, co je uvedeno v application.conf ve mě vyvolává dojem, že se pracuje přímo s jdbc spojením? Použil bych radší pool a zkontrolovat limit na počet konexí nastavený v databázi a v connection poolu.

[majales]

Nevím, čím by to mohlo být.. A nemám čas to zkoumat .. nastavil jsem tohle:

https://docs.vmware.com/en/VMware-vSphere/6.5/com.vmware.vsphere.install.doc/GUID-B15AB8CF-A123-482D-8988-F73A836EE4A7.html

A vývojáři připravil fungl novou a čistou virtuálku, kam si sám nainstaloval Javu, Tomcat a deploynul aplikaci. Výsledek jem že už to funguje i na produkci..

[Max]

Já bych třeba osobně neměl klidné spaní. Nemám rád řešení formou přeinstalace. Důvod je prostý, může se podobný problém objevit znovu, v produkci, v době, kdy už to bude rozjeté a nebude prostor pro odstávky apod.
Zdar Max

[cronin]

Nevím, čím by to mohlo být.. A nemám čas to zkoumat ..

Takto to nefunguje. Ak je aplikácia napísaná zle, je napísaná zle, a po čase vyčerpá spojenia bez ohľadu na limity a pod.

Je také ťažké dať aplikáciu zrevidovať inému vývojárovi? Ak dopredu vedia, aký typ problému hľadajú, malo by to byť relatívne ľahké a rýchle.