osdir.com

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Re: DB Communication Link Failure


Hi Nicolas – not to dig too far into your analysis or log entries – but in my experience any time we see “Communications link failure” the problem is exactly that – a communications issue between management and DB, rather than an internal DB issue.

Regards,
Dag Sonstebo
Cloud Architect
ShapeBlue

From: Nicolas Bouige <n.bouige@xxxxxxxx>
Reply-To: "users@xxxxxxxxxxxxxxxxxxxxx" <users@xxxxxxxxxxxxxxxxxxxxx>
Date: Wednesday, 13 June 2018 at 15:04
To: "users@xxxxxxxxxxxxxxxxxxxxx" <users@xxxxxxxxxxxxxxxxxxxxx>
Subject: DB Communication Link Failure

Hello All,

Tonight du to a network issue our management cloudstack server and MariaDb server have been shutdowned and restarted this morning.

Unfortunately, we  get some issues of « connectivity » between the mgmt server and db server.
Both service (cloudstack-management/mysqld) are up and running without any errors.
Db server are available from mgmt server (telnet OK, mysql –h dbserver…ok, firewall policies are good from both sides)

However, when we want to login to the GUI cloudstack an execption is raised in mgmt-server.log :

2018-06-13 15:28:41,019 DEBUG [c.c.u.d.T.Transaction] (qtp1796488937-13:ctx-88e441c4) (logid:f9e9b399) Rolling back the transaction: Time = 97 Name =  qtp1796488937-13; called by -TransactionLegacy.rollback:889-TransactionLegacy.removeUpTo:832-TransactionLegacy.close:656-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:174-ExposeInvocationInterceptor.invoke:92-ReflectiveMethodInvocation.proceed:185-JdkDynamicAopProxy.invoke:212-$Proxy121.persist:-1-ActionEventUtils.persistActionEvent:186-ActionEventUtils.onActionEvent:98-AccountManagerImpl.logoutUser:2096
2018-06-13 15:28:41,020 WARN  [c.c.u.d.T.Transaction] (qtp1796488937-13:ctx-88e441c4) (logid:f9e9b399) Unable to rollback
com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Communications link failure during rollback(). Transaction resolution unknown.
        at sun.reflect.GeneratedConstructorAccessor98.newInstance(Unknown Source)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
        at com.mysql.jdbc.Util.getInstance(Util.java:386)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1015)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:989)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:975)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:920)
        at com.mysql.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:5067)
        at org.apache.commons.dbcp.DelegatingConnection.rollback(DelegatingConnection.java:368)
        at org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.rollback(PoolingDataSource.java:323)
        at com.cloud.utils.db.TransactionLegacy.rollbackTransaction(TransactionLegacy.java:851)
        at com.cloud.utils.db.TransactionLegacy.rollback(TransactionLegacy.java:889)
        at com.cloud.utils.db.TransactionLegacy.removeUpTo(TransactionLegacy.java:832)
        at com.cloud.utils.db.TransactionLegacy.close(TransactionLegacy.java:656)
        at com.cloud.utils.db.TransactionContextInterceptor.invoke(TransactionContextInterceptor.java:36)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
        at com.sun.proxy.$Proxy121.persist(Unknown Source)
        at com.cloud.event.ActionEventUtils.persistActionEvent(ActionEventUtils.java:186)
        at com.cloud.event.ActionEventUtils.onActionEvent(ActionEventUtils.java:98)
        at com.cloud.user.AccountManagerImpl.logoutUser(AccountManagerImpl.java:2096)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:338)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:197)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
        at com.sun.proxy.$Proxy40.logoutUser(Unknown Source)
        at com.cloud.api.ApiServer.logoutUser(ApiServer.java:1104)
        at com.cloud.api.ApiServlet.processRequestInContext(ApiServlet.java:234)
        at com.cloud.api.ApiServlet$1.run(ApiServlet.java:130)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
        at com.cloud.api.ApiServlet.processRequest(ApiServlet.java:127)
        at com.cloud.api.ApiServlet.doGet(ApiServlet.java:89)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:686)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:791)
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:852)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:535)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
        at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:527)
        at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
        at org.eclipse.jetty.server.Server.handle(Server.java:530)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:347)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:256)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:382)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:708)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:626)
        at java.lang.Thread.run(Thread.java:748)
2018-06-13 15:28:41,024 ERROR [c.c.a.ApiServlet] (qtp1796488937-13:ctx-88e441c4) (logid:f9e9b399) unknown exception writing api response
com.cloud.utils.exception.CloudRuntimeException: DB Exception on: com.mysql.jdbc.JDBC4PreparedStatement@168d9c37: INSERT INTO event (event.type, event.state, event.description, event.created, event.user_id, event.account_id, event.domain_id, event.level, event.start_id, event.parameters, event.uuid, event.archived, event.display) VALUES (_binary'USER.LOGOUT', 'Completed', _binary'user has logged out', '2018-06-13 13:28:40', 2, 2, 1, _binary'INFO', 0, null, _binary'd9009f21-6550-4a18-a6e9-9213bbb8eabb', 0, 1)
        at com.cloud.utils.db.GenericDaoBase.persist(GenericDaoBase.java:1436)
        at sun.reflect.GeneratedMethodAccessor118.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:338)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:197)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
        at com.cloud.utils.db.TransactionContextInterceptor.invoke(TransactionContextInterceptor.java:34)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
        at com.sun.proxy.$Proxy121.persist(Unknown Source)
        at com.cloud.event.ActionEventUtils.persistActionEvent(ActionEventUtils.java:186)
        at com.cloud.event.ActionEventUtils.onActionEvent(ActionEventUtils.java:98)
        at com.cloud.user.AccountManagerImpl.logoutUser(AccountManagerImpl.java:2096)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:338)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:197)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
        at com.sun.proxy.$Proxy40.logoutUser(Unknown Source)
        at com.cloud.api.ApiServer.logoutUser(ApiServer.java:1104)
        at com.cloud.api.ApiServlet.processRequestInContext(ApiServlet.java:234)
        at com.cloud.api.ApiServlet$1.run(ApiServlet.java:130)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
        at com.cloud.api.ApiServlet.processRequest(ApiServlet.java:127)
        at com.cloud.api.ApiServlet.doGet(ApiServlet.java:89)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:686)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:791)
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:852)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:535)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
        at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:527)
        at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
        at org.eclipse.jetty.server.Server.handle(Server.java:530)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:347)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:256)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:382)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:708)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:626)
        at java.lang.Thread.run(Thread.java:748)
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 94 milliseconds ago.  The last packet sent successfully to the server was 93 milliseconds ago.
        at sun.reflect.GeneratedConstructorAccessor96.newInstance(Unknown Source)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
        ... 82 more
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3119)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3570)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3559)
        ... 78 more



We were able to connect to the GUI during 30 min with same kind of errors each time we tried to start an instance or VR…and it’s now impossible to connect to the GUI.

Seems to be a problem with the rollback transaction but i dont know how to deal with it except  wait they finish their jobs

Here log from mysqld.log :

he manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
180613 14:24:19 mysqld_safe Number of processes running now: 0
180613 14:24:19 mysqld_safe mysqld restarted
2018-06-13 14:24:19 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explici
2018-06-13 14:24:19 0 [Note] /usr/sbin/mysqld (mysqld 5.6.39) starting as process 15999 ...
2018-06-13 14:24:19 15999 [Warning] Buffered warning: Changed limits: max_open_files: 1024 (requested 500

2018-06-13 14:24:19 15999 [Warning] Buffered warning: Changed limits: table_open_cache: 431 (requested 20

2018-06-13 14:24:19 15999 [Note] Plugin 'FEDERATED' is disabled.
2018-06-13 14:24:19 15999 [Note] InnoDB: Using atomics to ref count buffer pool pages
2018-06-13 14:24:19 15999 [Note] InnoDB: The InnoDB memory heap is disabled
2018-06-13 14:24:19 15999 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-06-13 14:24:19 15999 [Note] InnoDB: Memory barrier is not used
2018-06-13 14:24:19 15999 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-06-13 14:24:19 15999 [Note] InnoDB: Using Linux native AIO
2018-06-13 14:24:19 15999 [Note] InnoDB: Using CPU crc32 instructions
2018-06-13 14:24:19 15999 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2018-06-13 14:24:19 15999 [Note] InnoDB: Completed initialization of buffer pool
2018-06-13 14:24:19 15999 [Note] InnoDB: Highest supported file format is Barracuda.
2018-06-13 14:24:19 15999 [Note] InnoDB: Log scan progressed past the checkpoint lsn 7513843395
2018-06-13 14:24:19 15999 [Note] InnoDB: Database was not shutdown normally!
2018-06-13 14:24:19 15999 [Note] InnoDB: Starting crash recovery.
2018-06-13 14:24:19 15999 [Note] InnoDB: Reading tablespace information from the .ibd files...
2018-06-13 14:24:19 15999 [Note] InnoDB: Restoring possible half-written data pages
2018-06-13 14:24:19 15999 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 7513851738
2018-06-13 14:24:19 15999 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
2018-06-13 14:24:20 15999 [Note] InnoDB: 128 rollback segment(s) are active.
2018-06-13 14:24:20 15999 [Note] InnoDB: Waiting for purge to start
2018-06-13 14:24:20 15999 [Note] InnoDB: 5.6.39 started; log sequence number 7513851738
2018-06-13 14:24:20 15999 [Note] Server hostname (bind-address): '172.8.22.170'; port: 3306
2018-06-13 14:24:20 15999 [Note]   - '172.8.22.170' resolves to '172.8.22.170';
2018-06-13 14:24:20 15999 [Note] Server socket created on IP: '172.8.22.170'.
2018-06-13 14:24:20 15999 [Note] Event Scheduler: Loaded 0 events
2018-06-13 14:24:20 15999 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.39'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)
^C
[root@FRPRCSSQB1 /]# tail -f /var/log/mysqld.log
InnoDB: Apply batch completed
2018-06-13 15:28:42 17230 [Note] InnoDB: 128 rollback segment(s) are active.
2018-06-13 15:28:42 17230 [Note] InnoDB: Waiting for purge to start
2018-06-13 15:28:42 17230 [Note] InnoDB: 5.6.39 started; log sequence number 7517034692
2018-06-13 15:28:42 17230 [Note] Server hostname (bind-address): '172.8.22.170'; port: 3306
2018-06-13 15:28:42 17230 [Note]   - '172.8.22.170' resolves to '172.8.22.170';
2018-06-13 15:28:42 17230 [Note] Server socket created on IP: '172.8.22.170'.
2018-06-13 15:28:42 17230 [Note] Event Scheduler: Loaded 0 events
2018-06-13 15:28:42 17230 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.39'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)

Thanks upfront for any technical help or better understanding of what is going on ;)

Best regards,
[ignatureBouige]


Dag.Sonstebo@xxxxxxxxxxxxx 
www.shapeblue.com
53 Chandos Place, Covent Garden, London  WC2N 4HSUK
@shapeblue