2 Replies Latest reply on Sep 30, 2014 5:33 AM by AnthonyFielding

    Synchronization Doesn't Complete

    Rookie

      We have found ourselves in a situation where synchronization doesn't complete meaning we can't do much with Avalanche, even after restarting the services. The console currently looks like this:

      1.png

       

      2.PNG

       

      We have also noticed some exceptions in C:\Program Files (x86)\Wavelink\AvalancheMC\log\AvalancheServer.log:

       

      ...

      2014-09-18 14:24:01,459 DEBUG TransportAPI - 192.168.0.212:50894 Processing B1P2 message IRMC_REQ/IRMS_AGENT_SET_MOBILEDEVICES (10/1106) cat 3

      2014-09-18 14:24:01,603 DEBUG SetMobileUnits           - Received 1 MU updates. Processing time 143.0 msecs, Average per MU 143.0 msecs

      2014-09-18 14:24:02,719 DEBUG NotificationThread       - Sending message IRMC_NOT/IRMS_NOTIFY_UPDATE (12/2200) with 1 notification entries to 255.3.1.2;255.3.1.13

      2014-09-18 14:24:08,664 DEBUG TransportAPI - 192.168.0.212:50894 Processing B1P2 message IRMC_REQ/IRMS_AGENT_SET_MOBILEDEVICES (10/1106) cat 3

      2014-09-18 14:24:15,774 DEBUG SetMobileUnits           - Received 30 MU updates. Processing time 7112.0 msecs, Average per MU 237.0 msecs

      2014-09-18 14:24:15,800 DEBUG TransportAPI - 192.168.0.212:50894 Processing B1P2 message IRMC_REQ/IRMS_AGENT_SET_MOBILEDEVICES (10/1106) cat 3

      2014-09-18 14:24:20,674 DEBUG NotificationThread       - Sending message IRMC_NOT/IRMS_NOTIFY_UPDATE (12/2200) with 55 notification entries to 255.3.1.2;255.3.1.13

      2014-09-18 14:24:21,892 DEBUG SetMobileUnits           - Received 30 MU updates. Processing time 6091.0 msecs, Average per MU 203.0 msecs

      2014-09-18 14:24:21,918 DEBUG TransportAPI - 192.168.0.212:50894 Processing B1P2 message IRMC_REQ/IRMS_AGENT_SET_MOBILEDEVICES (10/1106) cat 3

      2014-09-18 14:24:26,822 DEBUG SetMobileUnits           - Received 24 MU updates. Processing time 4902.0 msecs, Average per MU 204.0 msecs

      2014-09-18 14:24:26,842 DEBUG TransportAPI - 192.168.0.212:50894 Processing B1P2 message IRMC_REQ/IRMS_AGENT_SET_MOBILEDEVICES (10/1106) cat 3

      2014-09-18 14:24:28,516 DEBUG SetMobileUnits           - Received 9 MU updates. Processing time 1672.0 msecs, Average per MU 185.0 msecs

      2014-09-18 14:24:28,525 DEBUG TransportAPI - 192.168.0.212:50894 Processing B1P2 message IRMC_REQ/IRMS_AGENT_SET_MOBILEDEVICES (10/1106) cat 3

      2014-09-18 14:24:28,869 DEBUG SetMobileUnits           - Received 2 MU updates. Processing time 343.0 msecs, Average per MU 171.0 msecs

      2014-09-18 14:24:28,873 DEBUG TransportAPI - 192.168.0.212:50894 Processing B1P2 message IRMC_REQ/IRMS_AGENT_SET_MOBILEDEVICES (10/1106) cat 3

      2014-09-18 14:24:29,132 DEBUG SetMobileUnits           - Received 1 MU updates. Processing time 257.0 msecs, Average per MU 257.0 msecs

      2014-09-18 14:24:29,832 DEBUG TransportAPI - 192.168.0.212:50894 Processing B1P2 message IRMC_REQ/IRMS_AGENT_SET_MOBILEDEVICES (10/1106) cat 3

      2014-09-18 14:24:29,983 DEBUG SetMobileUnits           - Received 1 MU updates. Processing time 149.0 msecs, Average per MU 149.0 msecs

      2014-09-18 14:24:30,987 DEBUG NotificationThread       - Sending message IRMC_NOT/IRMS_NOTIFY_UPDATE (12/2200) with 42 notification entries to 255.3.1.2;255.3.1.13

      2014-09-18 14:24:36,443 DEBUG TransportAPI - 10.22.156.222:51073 Processing C2P1 message IRMC_REQ/IRMS_CONSOLE_SET_SCHEDULED_EVENT (10/2802) cat 2

      2014-09-18 14:24:36,577 DEBUG AvalancheServerMessageDispatch - Dispatch Message To : Scheduler

      2014-09-18 14:24:36,580 DEBUG TransportAPI - [A] 10.22.156.222:51073 Sending message IRMC_RSP/IRMS_CONSOLE_SET_SCHEDULED_EVENT (11/2802)

      2014-09-18 14:24:36,581 DEBUG SchedulerFacade          - Scheduler Message: Universal Deployment Job seId: 100467,Id:[#34#],Deployment

      2014-09-18 14:24:36,677 DEBUG SchedulerFacade          - Scheduled one-shot job: seId: 100467,Id:[#34#],Deployment start: 2014-09-18 14:24:36.46

      2014-09-18 14:24:36,704 DEBUG AbstractJob - Preparing to run scheduled event job [seId: 100467,Id:[#34#],Deployment]; setting status to RUNNING (1).

      2014-09-18 14:24:36,709 DEBUG ScheduledEvent - Setting job: seId: 100467,Id:[#34#],Deployment with status: 1 and result: 2

      2014-09-18 14:24:36,709 DEBUG ScheduledEvent           - Job: seId: 100467,Id:[#34#],Deployment status: 1 required status: 2

      2014-09-18 14:24:36,709 DEBUG ScheduledEvent - Job: seId: 100467,Id:[#34#],Deployment status: 1 required status: 0

      2014-09-18 14:24:36,722 DEBUG DeploymentJob - DEPLOYMENT: Deployment job initialized and started.

      2014-09-18 14:24:36,725 INFO  AvalancheDaoSupport - getGroupIdsSharingImmutableIds() - duration: 2 ms

      2014-09-18 14:24:36,726 DEBUG EditLockControlAPI       - DEPLOYMENT: Deployment job PENDING state has been cleared.

      2014-09-18 14:24:36,726 DEBUG GroupAPI - DEPLOYMENT: Deployment starting, IN_DEPLOYMENT flag has been set

      2014-09-18 14:24:36,727 DEBUG TransportAPI - [A] Sending message IRMC_NOT/IRMS_NOTIFY_UPDATE (12/2200)

      2014-09-18 14:24:36,934 INFO TransportAPI - Messages processing on hold during deployment

      2014-09-18 14:24:36,946 INFO AvalancheServer          - cleanupDeployments() cullOrphanedDeployments - execution time: 13 ms

      2014-09-18 14:24:36,960 INFO AvalancheServer          - cleanupDeployments() cullStaleApplicationDeployments - execution time: 13 ms

      2014-09-18 14:24:36,975 INFO AvalancheServer          - cleanupDeployments() cullChildlessApplications - execution time: 14 ms

      2014-09-18 14:24:38,025 DEBUG NotificationThread       - Sending message IRMC_NOT/IRMS_NOTIFY_UPDATE (12/2200) with 1 notification entries to 255.3.1.2;255.3.1.13

      2014-09-18 14:24:38,099 DEBUG TransportAPI - 10.10.40.111:57088 Processing C1P1 message IRMC_REQ/IRMS_CONSOLE_GET_SCHEDULED_EVENT (10/2800) cat 2

      2014-09-18 14:24:38,105 INFO AvalancheServer          - cleanupDeployments() markRevisedProfiles - execution time: 1130 ms

      2014-09-18 14:24:38,125 DEBUG TransportAPI - [A] 10.10.40.111:57088 Sending message IRMC_RSP/IRMS_CONSOLE_GET_SCHEDULED_EVENT (11/2800)

      2014-09-18 14:24:38,172 INFO  AvalancheServer - cleanupDeployments() markRevisedApplications - execution time: 67 ms

      2014-09-18 14:24:38,178 INFO AvalancheServer          - cleanupDeployments() cullRemovedDeployments - execution time: 6 ms

      2014-09-18 14:24:38,183 INFO  AvalancheServer - cleanupDeployments() cullRemovedApplications - execution time: 5 ms

      2014-09-18 14:24:38,229 INFO AvalancheServer          - cleanupDeployments() cullChildlessRemovedProfiles - execution time: 46 ms

      2014-09-18 14:24:38,243 INFO  AvalancheServer - cleanupDeployments() cullChildlessRemovedProfileBases - execution time: 13 ms

      2014-09-18 14:24:38,248 INFO AvalancheServer          - cleanupDeployments() markPartiallyDeployedApplications - execution time: 5 ms

      2014-09-18 14:24:38,253 INFO  AvalancheServer - cleanupDeployments() markFullyDeployedApplications - execution time: 5 ms

      2014-09-18 14:24:38,254 INFO AvalancheServer          - cleanupDeployments( 13 ) - execution time: 1320 ms

      2014-09-18 14:24:38,327 DEBUG TransportAPI - 10.22.156.222:51073 Processing C2P1 message IRMC_REQ/IRMS_CONSOLE_GET_SCHEDULED_EVENT (10/2800) cat 2

      2014-09-18 14:24:38,328 INFO AvalancheDaoSupport      - Culled '0' orphaned device group -- device associations

      2014-09-18 14:24:38,418 INFO  AvalancheDaoSupport - Culled '0' orphaned device groups

      2014-09-18 14:24:38,433 DEBUG TransportAPI - [A] 10.22.156.222:51073 Sending message IRMC_RSP/IRMS_CONSOLE_GET_SCHEDULED_EVENT (11/2800)

      2014-09-18 14:24:38,485 INFO  AvalancheDaoSupport - Culled '1' orphaned SoftwareProfile -- SoftwarePackage associations

      2014-09-18 14:24:38,532 INFO AvalancheDaoSupport      - Found '1' orphaned profiles

      2014-09-18 14:24:38,601 DEBUG GroupAPI - Deleting alpha archive avapackages/100488.alpha.zip - last referencing SoftwarePackage being deleted

      2014-09-18 14:24:38,607 DEBUG GroupAPI - Deleting delta archive avapackages/100488_100860.delta.zip - last referencing SoftwarePackage being deleted

      2014-09-18 14:24:38,616 DEBUG GroupAPI - Deleting delta archive avapackages/100489_100861.delta.zip - last referencing SoftwarePackage being deleted

      2014-09-18 14:24:38,626 DEBUG GroupAPI - Deleting delta archive avapackages/100489_100862.delta.zip - last referencing SoftwarePackage being deleted

      2014-09-18 14:24:38,630 DEBUG GroupAPI - Deleting alpha archive avapackages/100493.alpha.zip - last referencing SoftwarePackage being deleted

      2014-09-18 14:24:38,635 DEBUG GroupAPI - Deleting delta archive avapackages/100493_100863.delta.zip - last referencing SoftwarePackage being deleted

      2014-09-18 14:24:38,644 DEBUG GroupAPI - Deleting delta archive avapackages/100500_100865.delta.zip - last referencing SoftwarePackage being deleted

      2014-09-18 14:24:38,652 DEBUG GroupAPI - Deleting delta archive avapackages/100500_100864.delta.zip - last referencing SoftwarePackage being deleted

      2014-09-18 14:24:38,660 DEBUG GroupAPI - Deleting delta archive avapackages/100500_100866.delta.zip - last referencing SoftwarePackage being deleted

      2014-09-18 14:24:38,693 ERROR DeploymentJob - Unexpected EXCEPTION encountered during Universal Deployment

      2014-09-18 14:24:38,693 ERROR DeploymentJob - ***** NullPointerException EXCEPTION *****

      2014-09-18 14:24:38,693 ERROR DeploymentJob -

      2014-09-18 14:24:38,693 DEBUG DeploymentJob - ***** STACK TRACE *****

      2014-09-18 14:24:38,693 DEBUG DeploymentJob - org.hibernate.proxy.HibernateProxyHelper.getClassWithoutInitializingProxy(HibernateProxyHelper.java:46)

      2014-09-18 14:24:38,693 DEBUG DeploymentJob - org.hibernate.impl.AbstractQueryImpl.guessType(AbstractQueryImpl.java:476)

      2014-09-18 14:24:38,694 DEBUG DeploymentJob - org.hibernate.impl.AbstractQueryImpl.determineType(AbstractQueryImpl.java:462)

      2014-09-18 14:24:38,694 DEBUG DeploymentJob - org.hibernate.impl.AbstractQueryImpl.setParameterList(AbstractQueryImpl.java:816)

      2014-09-18 14:24:38,694 DEBUG DeploymentJob - com.wavelink.avalanche.db.dao.site.AgentDaoImpl.getAgentWakeupData(AgentDaoImpl.java:307)

      2014-09-18 14:24:38,694 DEBUG DeploymentJob - com.wavelink.avalanche.server.api.AgentAPI.wakeupAgentsForLocations(AgentAPI.java:292)

      2014-09-18 14:24:38,694 DEBUG DeploymentJob - sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

      2014-09-18 14:24:38,695 DEBUG DeploymentJob - sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

      2014-09-18 14:24:38,695 DEBUG DeploymentJob - sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

      2014-09-18 14:24:38,695 DEBUG DeploymentJob - java.lang.reflect.Method.invoke(Unknown Source)

      2014-09-18 14:24:38,695 DEBUG DeploymentJob - org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)

      2014-09-18 14:24:38,695 DEBUG DeploymentJob - org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)

      2014-09-18 14:24:38,696 DEBUG DeploymentJob - org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)

      2014-09-18 14:24:38,696 DEBUG DeploymentJob - org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)

      2014-09-18 14:24:38,696 DEBUG DeploymentJob - org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)

      2014-09-18 14:24:38,696 DEBUG DeploymentJob - org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)

      2014-09-18 14:24:38,696 DEBUG DeploymentJob - $Proxy13.wakeupAgentsForLocations(Unknown Source)

      2014-09-18 14:24:38,697 DEBUG DeploymentJob - com.wavelink.avalanche.server.api.GroupAPI.doDeployment(GroupAPI.java:853)

      2014-09-18 14:24:38,697 DEBUG DeploymentJob - sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

      2014-09-18 14:24:38,697 DEBUG DeploymentJob - sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)

      2014-09-18 14:24:38,697 DEBUG DeploymentJob - sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)

      2014-09-18 14:24:38,697 DEBUG DeploymentJob - java.lang.reflect.Method.invoke(Unknown Source)

      2014-09-18 14:24:38,698 DEBUG DeploymentJob - org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)

      2014-09-18 14:24:38,698 DEBUG DeploymentJob - org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)

      2014-09-18 14:24:38,698 DEBUG DeploymentJob - org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)

      2014-09-18 14:24:38,698 DEBUG DeploymentJob - org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)

      2014-09-18 14:24:38,698 DEBUG DeploymentJob - org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)

      2014-09-18 14:24:38,699 DEBUG DeploymentJob - org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)

      2014-09-18 14:24:38,699 DEBUG DeploymentJob - $Proxy3.doDeployment(Unknown Source)

      2014-09-18 14:24:38,699 DEBUG DeploymentJob - com.wavelink.mme.server.scheduler.DeploymentJob.doInTransaction(DeploymentJob.java:72)

      2014-09-18 14:24:38,699 DEBUG DeploymentJob - org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:130)

      2014-09-18 14:24:38,699 DEBUG DeploymentJob - com.wavelink.mme.server.scheduler.DeploymentJob.doWork(DeploymentJob.java:42)

      2014-09-18 14:24:38,700 DEBUG DeploymentJob - com.wavelink.mme.server.scheduler.AbstractJob.execute(AbstractJob.java:82)

      2014-09-18 14:24:38,700 DEBUG DeploymentJob - org.quartz.core.JobRunShell.run(JobRunShell.java:216)

      2014-09-18 14:24:38,700 DEBUG DeploymentJob - org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)

      2014-09-18 14:24:38,704 ERROR AbstractJob - Exception in job: seId: 100467,Id:[#34#],Deployment

      • org.springframework.transaction.UnexpectedRollbackException: Transaction rolled back because it has been marked as rollback-only

      at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:717)

      at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:147)

      at com.wavelink.mme.server.scheduler.DeploymentJob.doWork(DeploymentJob.java:42)

      at com.wavelink.mme.server.scheduler.AbstractJob.execute(AbstractJob.java:82)

      at org.quartz.core.JobRunShell.run(JobRunShell.java:216)

      at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)

      2014-09-18 14:24:38,704 DEBUG AbstractJob - The scheduled event job [seId: 100467,Id:[#34#],Deployment] is not scheduled to run again; setting status to COMPLETE (2).

      2014-09-18 14:24:38,709 DEBUG ScheduledEvent           - Setting job: seId: 100467,Id:[#34#],Deployment with status: 2 and result: 1

      2014-09-18 14:24:38,767 INFO TransportAPI - Messages processing hold condition cleared

      2014-09-18 14:24:38,767 DEBUG TransportAPI - 192.168.0.212:50894 Processing B1P2 message IRMC_REQ/IRMS_AGENT_SET_MOBILEDEVICES (10/1106) cat 3

      2014-09-18 14:24:38,939 DEBUG SetMobileUnits           - Received 1 MU updates. Processing time 172.0 msecs, Average per MU 172.0 msecs

      2014-09-18 14:24:40,071 DEBUG NotificationThread       - Sending message IRMC_NOT/IRMS_NOTIFY_UPDATE (12/2200) with 2 notification entries to 255.3.1.2;255.3.1.13

      2014-09-18 14:24:40,136 DEBUG TransportAPI - 10.10.40.111:57088 Processing C1P1 message IRMC_REQ/IRMS_CONSOLE_GET_SCHEDULED_EVENT (10/2800) cat 2

      2014-09-18 14:24:40,150 DEBUG TransportAPI - [A] 10.10.40.111:57088 Sending message IRMC_RSP/IRMS_CONSOLE_GET_SCHEDULED_EVENT (11/2800)

      2014-09-18 14:24:40,378 DEBUG TransportAPI - 10.22.156.222:51073 Processing C2P1 message IRMC_REQ/IRMS_CONSOLE_GET_SCHEDULED_EVENT (10/2800) cat 2

      2014-09-18 14:24:40,390 DEBUG TransportAPI - [A] 10.22.156.222:51073 Sending message IRMC_RSP/IRMS_CONSOLE_GET_SCHEDULED_EVENT (11/2800)

      2014-09-18 14:24:47,363 DEBUG TransportAPI - 192.168.0.212:50894 Processing B1P2 message IRMC_REQ/IRMS_AGENT_SET_MOBILEDEVICES (10/1106) cat 3

      2014-09-18 14:24:47,514 DEBUG SetMobileUnits           - Received 1 MU updates. Processing time 149.0 msecs, Average per MU 149.0 msecs

      2014-09-18 14:24:49,122 DEBUG NotificationThread       - Sending message IRMC_NOT/IRMS_NOTIFY_UPDATE (12/2200) with 1 notification entries to 255.3.1.2;255.3.1.13

      ...

       

       

      Avalanche was fine this morning. I was adding two new group locations, one as a child of the other - both initially configured to not inherit profiles from above. When I went to the child to set it to inherit the child node dissapeared. After refreshing it still didn't come back so I re-created it. It was around performing this change that it stopped synchronising.

       

      Any helpwould be greatly appreciated.

       

      Thanks,

      Anthony Fielding