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,
[SignatureBouige]
