Mailing-List: contact dev-help@cloudstack.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@cloudstack.apache.org
Received-SPF: pass (nike.apache.org: domain of FKessen@schubergphilis.com
 designates 195.66.90.57 as permitted sender)
From: Funs Kessen <FKessen@schubergphilis.com>
To: "dev@cloudstack.apache.org" <dev@cloudstack.apache.org>
CC: Daan Hoogland <DHoogland@schubergphilis.com>
Subject: RE: "Bug" introduced by part of commit
 a600d8408ea86782318139c17cf346c8497943d0
Thread-Topic: "Bug" introduced by part of commit
 a600d8408ea86782318139c17cf346c8497943d0
Thread-Index: Ac+cGZCF/C4p3URqRTKV9ekQFwhUzAAAbD+AAAA0XJA=
Date: Thu, 10 Jul 2014 08:52:51 +0000
Message-ID: <DD0FA5804BCDDC4FBDF14FC4C67FC42260F88819@SBPOMB102.sbp.lan>
References: <DD0FA5804BCDDC4FBDF14FC4C67FC42260F88748@SBPOMB102.sbp.lan>
 <B3EE4F5818AFDE45A8A7CA990FF43DEB4867C74F@SINPEX01CL02.citrite.net>
In-Reply-To: 
 <B3EE4F5818AFDE45A8A7CA990FF43DEB4867C74F@SINPEX01CL02.citrite.net>
Accept-Language: en-US
Content-Language: en-US
Content-Type: text/plain; charset="us-ascii"
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0

Hi Likitha,

Ah cool thanks!

Cheers,

Funs

> -----Original Message-----
> From: Likitha Shetty [mailto:likitha.shetty@citrix.com]
> Sent: Thursday, July 10, 2014 10:50 AM
> To: dev@cloudstack.apache.org
> Cc: Daan Hoogland
> Subject: RE: "Bug" introduced by part of commit
> a600d8408ea86782318139c17cf346c8497943d0
>=20
> Funs, Santhosh fixed this problem yesterday.
> https://issues.apache.org/jira/browse/CLOUDSTACK-7079 has more details.
>=20
> Thanks,
> Likitha
>=20
> -----Original Message-----
> From: Funs Kessen [mailto:FKessen@schubergphilis.com]
> Sent: Thursday, July 10, 2014 2:10 PM
> To: dev@cloudstack.apache.org
> Cc: Daan Hoogland
> Subject: "Bug" introduced by part of commit
> a600d8408ea86782318139c17cf346c8497943d0
>=20
> Hi Devs,
>=20
> I recently noticed on master that after starting, stopping and starting t=
he
> management server again I get stacktraces about every second.
> After some digging with Daan we found that part of the
> a600d8408ea86782318139c17cf346c84979943d0 commit causes this. The
> problem is however deeper rooted, as the code is supposed to update the
> mshost table, but because another Session ID (actually _runId from
> ClusterManagerImpl.java from the previous run)  is already in there the
> update fails. The Session ID is based on time in milliseconds, and offcou=
rse
> changes when you stop and start the management server again.
> Prior to the commit it failed silently, and has done so since the initial
> checkin it seems. The real question is what the original idea is behind t=
he
> _runId, and is it something that requires fixing ?
>=20
> I've pasted part of the commit, sql and stacktrace below.
>=20
> Cheers,
>=20
> Funs
>=20
> =3D=3D=3D
> mysql> select * from mshost;
> +----+----------------+---------------+---------+-------+----------------=
+------------+--------------
> +---------------------+---------+-------------+
> | id | msid           | runid         | name    | state | version        =
| service_ip |
> service_port | last_update         | removed | alert_count |
> +----+----------------+---------------+---------+-------+----------------=
+------------+--------------
> +---------------------+---------+-------------+
> |  1 | 90520734207775 | 1404924979461 | cs-mgmt | Up    | 4.5.0-
> SNAPSHOT | 127.0.0.1  |         9090 | 2014-07-09 16:58:07 | NULL    |   =
        0 |
> +----+----------------+---------------+---------+-------+----------------=
+------------+--------------
> +---------------------+---------+-------------+
> 1 row in set (0.00 sec)
>=20
> =3D=3D=3D
> commit a600d8408ea86782318139c17cf346c8497943d0
> Author: Santhosh Edukulla <santhosh.edukulla@gmail.com> 2014-07-02
> 10:38:16
> Committer: Santhosh Edukulla <santhosh.edukulla@gmail.com> 2014-07-04
> 12:47:58
>=20
> Fixed Resource Leaks, null dereferences, few other issues reported by
> coverity
>=20
> -
> framework/cluster/src/com/cloud/cluster/dao/ManagementServerHostDaoI
> mpl.java
> diff --git
> a/framework/cluster/src/com/cloud/cluster/dao/ManagementServerHostDa
> oImpl.java
> b/framework/cluster/src/com/cloud/cluster/dao/ManagementServerHostDa
> oImpl.java
> index 3d0c3f5..89d7d27 100644
> ---
> a/framework/cluster/src/com/cloud/cluster/dao/ManagementServerHostDa
> oImpl.java
> +++
> b/framework/cluster/src/com/cloud/cluster/dao/ManagementServerHostDa
> oImpl.java
> @@ -53,15 +53,14 @@
>      @Override
>      public void invalidateRunSession(long id, long runid) {
>          TransactionLegacy txn =3D TransactionLegacy.currentTxn();
> -        PreparedStatement pstmt =3D null;
> -        try {
> -            pstmt =3D txn.prepareAutoCloseStatement("update mshost set r=
unid=3D0,
> state=3D'Down' where id=3D? and runid=3D?");
> -            pstmt.setLong(1, id);
> -            pstmt.setLong(2, runid);
> -
> -            pstmt.executeUpdate();
> +        try (PreparedStatement pstmt =3D txn.prepareStatement("update ms=
host
> set runid=3D0, state=3D'Down' where id=3D? and runid=3D?");){
> +            if(pstmt !=3D null) {
> +                pstmt.setLong(1, id);
> +                pstmt.setLong(2, runid);
> +                pstmt.executeUpdate();
> +            }
>          } catch (SQLException e) {
> -            throw new CloudRuntimeException("DB exception on " +
> pstmt.toString(), e);
> +            throw new
> CloudRuntimeException("invalidateRunSession:Exception:"+ e.getMessage(),
> e);
>          }
>      }
>=20
> =3D=3D=3D
> 2014-07-09 18:45:06,541 WARN  [c.c.c.d.ManagementServerHostDaoImpl]
> (Cluster-Heartbeat-1:ctx-5f2f8ad5) update:Exception:Invalid cluster sessi=
on
> detected
> com.cloud.utils.exception.CloudRuntimeException: Invalid cluster session
> detected
>         at
> com.cloud.cluster.dao.ManagementServerHostDaoImpl.update(Management
> ServerHostDaoImpl.java:147)
>         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>         at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.ja
> va:57)
>         at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccess
> orImpl.java:43)
>         at java.lang.reflect.Method.invoke(Method.java:606)
>         at
> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(
> AopUtils.java:317)
>         at
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoin
> point(ReflectiveMethodInvocation.java:183)
>         at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R
> eflectiveMethodInvocation.java:150)
>         at
> com.cloud.utils.db.TransactionContextInterceptor.invoke(TransactionContex
> tInterceptor.java:34)
>         at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R
> eflectiveMethodInvocation.java:161)
>         at
> org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(Ex
> poseInvocationInterceptor.java:91)
>         at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R
> eflectiveMethodInvocation.java:172)
>         at
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynam
> icAopProxy.java:204)
>         at com.sun.proxy.$Proxy158.update(Unknown Source)
>         at
> com.cloud.cluster.ClusterManagerImpl$4.runInContext(ClusterManagerImpl
> .java:545)
>         at
> org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(M
> anagedContextRunnable.java:49)
>         at
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call
> (DefaultManagedContext.java:56)
>         at
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callW
> ithContext(DefaultManagedContext.java:103)
>         at
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWi
> thContext(DefaultManagedContext.java:53)
>         at
> org.apache.cloudstack.managed.context.ManagedContextRunnable.run(Man
> agedContextRunnable.java:46)
>         at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>         at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:30=
4)
>         at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.ac
> cess$301(ScheduledThreadPoolExecutor.java:178)
>         at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.ru
> n(ScheduledThreadPoolExecutor.java:293)
>         at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.jav
> a:1145)
>         at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.ja
> va:615)
>         at java.lang.Thread.run(Thread.java:744)
> Caused by: com.cloud.cluster.ClusterInvalidSessionException: runid
> 1404924278923 is no longer valid
>         at
> com.cloud.cluster.dao.ManagementServerHostDaoImpl.update(Management
> ServerHostDaoImpl.java:147)
>         ... 26 more
> 2014-07-09 18:45:06,543 ERROR [c.c.c.ClusterManagerImpl] (Cluster-
> Heartbeat-1:ctx-5f2f8ad5) Unexpected exception in cluster heartbeat
> java.lang.RuntimeException: update:Exception:Invalid cluster session
> detected
>         at
> com.cloud.cluster.dao.ManagementServerHostDaoImpl.update(Management
> ServerHostDaoImpl.java:155)
>         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>         at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.ja
> va:57)
>         at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccess
> orImpl.java:43)
>         at java.lang.reflect.Method.invoke(Method.java:606)
>         at
> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(
> AopUtils.java:317)
>         at
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoin
> point(ReflectiveMethodInvocation.java:183)
>         at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R
> eflectiveMethodInvocation.java:150)
>         at
> com.cloud.utils.db.TransactionContextInterceptor.invoke(TransactionContex
> tInterceptor.java:34)
>         at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R
> eflectiveMethodInvocation.java:161)
>         at
> org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(Ex
> poseInvocationInterceptor.java:91)
>         at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R
> eflectiveMethodInvocation.java:172)
>         at
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynam
> icAopProxy.java:204)
>         at com.sun.proxy.$Proxy158.update(Unknown Source)
>         at
> com.cloud.cluster.ClusterManagerImpl$4.runInContext(ClusterManagerImpl
> .java:545)
>         at
> org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(M
> anagedContextRunnable.java:49)
>         at
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call
> (DefaultManagedContext.java:56)
>         at
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callW
> ithContext(DefaultManagedContext.java:103)
>         at
> org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWi
> thContext(DefaultManagedContext.java:53)
>         at
> org.apache.cloudstack.managed.context.ManagedContextRunnable.run(Man
> agedContextRunnable.java:46)
>         at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>         at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:30=
4)
>         at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.ac
> cess$301(ScheduledThreadPoolExecutor.java:178)
>         at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.ru
> n(ScheduledThreadPoolExecutor.java:293)
>         at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.jav
> a:1145)
>         at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.ja
> va:615)
>         at java.lang.Thread.run(Thread.java:744)
> Caused by: com.cloud.utils.exception.CloudRuntimeException: Invalid
> cluster session detected
>         at
> com.cloud.cluster.dao.ManagementServerHostDaoImpl.update(Management
> ServerHostDaoImpl.java:147)
>         ... 26 more
> Caused by: com.cloud.cluster.ClusterInvalidSessionException: runid
> 1404924278923 is no longer valid
>         at
> com.cloud.cluster.dao.ManagementServerHostDaoImpl.update(Management
> ServerHostDaoImpl.java:147)
>         ... 26 more
>=20
>=20