Entity save() Method Hangs with No Error

4k Views Asked by At

I am facing an issue where my Simple AGI Application hangs when saving/updating an entity and no errors are thrown. Select query / methods from Repository work as expected without any errors. I am using Spring Boot with the Spring Data JPA which persists to a MYSQL Database.

Subscriber.java :

package com.newcom.ncivr.model;

import org.joda.time.DateTime;
import org.joda.time.DateTimeZone;
import javax.persistence.*;

@Entity @Table(name = "subscribers")
public class Subscriber{

    @Id
    @GeneratedValue(strategy=GenerationType.IDENTITY)
    private int Id;
    private String msisdn;
    private String subscriptionName;
    @Column(columnDefinition = "DATETIME")
    private DateTime lastRenewal;
    private String status;

    public Subscriber() {
    }

    public Subscriber(String msisdn, String subscriptionName) {
        this.msisdn = msisdn;
        this.subscriptionName = subscriptionName;
        this.lastRenewal = DateTime.now(DateTimeZone.UTC).minusDays(1);
        this.status = "ACTIVE";
    }

 //POJO Getters and Setters Excluded from Sample

}

SubscriberRepository.java :

package com.newcom.ncivr.repository;

import com.newcom.ncivr.model.Subscriber;
import org.springframework.data.repository.CrudRepository;
import org.springframework.stereotype.Repository;

@Repository
public interface SubscriberRepository extends CrudRepository<Subscriber,Integer>{
    Subscriber findFirstByMsisdnAndSubscriptionNameAndStatus(String msisdn, String subscriptionName, String status);
}

IvrAgi.java :

package com.newcom.ncivr.agi;

import com.newcom.ncivr.model.Subscriber;
import com.newcom.ncivr.repository.SubscriberRepository;
import org.asteriskjava.fastagi.*;
import org.joda.time.DateTime;
import org.joda.time.DateTimeZone;
import org.joda.time.format.DateTimeFormat;
import org.joda.time.format.DateTimeFormatter;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Autowired;


public class IvrAgi extends BaseAgiScript {

    private Logger log = LoggerFactory.getLogger(IvrAgi.class);

    @Autowired
    SubscriberRepository subscriberRepository;

    public void service(AgiRequest request, AgiChannel channel) throws AgiException {

        log.info("********** Agi Script Started. **************");
        // Answer the channel...
        answer();
        log.info("Caller ID: "+request.getCallerIdNumber());
        mainMenu(request);
        log.info("********** Agi Script Completed. **************");

    }

    public void mainMenu(AgiRequest request) throws AgiException {
        try {

            while (true) {

                String data = getData("ivr_main_menu");

                log.info("User Input : " + data);

                if (data.equals("1")) {
                    System.out.println(request.getCallerIdNumber() + ": User Selected 1");
                    streamFile("ivr_opt_one");
                    log.info(request.getCallerIdNumber() + ": User Selected 1");

                    try {
                        Subscriber subscriber = subscriberRepository.findFirstByMsisdnAndSubscriptionNameAndStatus(request.getCallerIdNumber(),"NEWS", "ACTIVE");

                        if(subscriber != null){
                            log.info("Id --->" + subscriber.toString());

                                subscriber.setLastRenewal(DateTime.now(DateTimeZone.UTC));
                                subscriber = subscriberRepository.save(subscriber);

                                log.info("Updated Entity --> " + subscriber.toString());
                        }else{
                            log.info("User is NOT Subscribed to NEWS");
                        }

                    }catch (Exception e){
                        e.printStackTrace();
                    }

                    hangup();
                }else{
                    continue;
                }
            }

        } catch (Throwable e) {
            e.printStackTrace();
        }
    }
}

Application Main :

package com.newcom.ncivr;

import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.annotation.ImportResource;

@SpringBootApplication
@ImportResource("classpath:/asterisk/asterisk-config.xml")
public class IvrApplication {
    @Autowired
    public static void main(String[] args) {
        SpringApplication.run(IvrApplication.class, args);
    }
}

asterisk-config.xml (Mapping Asterisk AGI to Spring Boot Service) :

<?xml version="1.0" encoding="UTF-8" ?>
<beans xmlns="http://www.springframework.org/schema/beans"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="
    http://www.springframework.org/schema/beans
    http://www.springframework.org/schema/beans/spring-beans-3.1.xsd">

    <bean id="agiServer" class="org.asteriskjava.fastagi.DefaultAgiServer"
          init-method="startup" destroy-method="shutdown">
        <!--<property name="port" value="1111"/>-->
        <property name="mappingStrategy" ref="mappingStrategy"/>
    </bean>

    <bean id="vanivr" class="com.newcom.ncivr.agi.IvrAgi">
    </bean>

    <bean id="mappingStrategy" class="org.asteriskjava.fastagi.SimpleMappingStrategy">
        <property name="mappings">
            <map>
                <entry key="vanivr.agi" value-ref="vanivr"/>
            </map>
        </property>
    </bean>

</beans>

application.properties :

#Database connection settings
spring.datasource.url=jdbc:mysql://localhost:3306/ncivr?useSSL=false
spring.datasource.username=root
spring.datasource.password=
spring.jpa.database=MYSQL
spring.jpa.show-sql=true
spring.jpa.hibernate.ddl-auto=update
spring.jpa.hibernate.naming.strategy=org.hibernate.cfg.ImprovedNamingStrategy
spring.jpa.properties.hibernate.dialect=org.hibernate.dialect.MySQL5Dialect
spring.jpa.properties.jadira.usertype.autoRegisterUserTypes = true
logging.level.org.hibernate.SQL=DEBUG
logging.level.org.hibernate.type.descriptor.sql.BasicBinder=TRACE
spring.jpa.properties.hibernate.show_sql=false
spring.jpa.properties.hibernate.use_sql_comments=true
spring.jpa.properties.hibernate.format_sql=true
spring.jpa.properties.hibernate.type=trace
logging.level.org.hibernate=TRACE
debug=true
2

There are 2 best solutions below

0
On BEST ANSWER

The Issue was resolved by running the AgiServer using a AgiServerThread.

Updated asterisk-conf.xml :

<?xml version="1.0" encoding="UTF-8" ?>
<beans xmlns="http://www.springframework.org/schema/beans"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xsi:schemaLocation="
    http://www.springframework.org/schema/beans
    http://www.springframework.org/schema/beans/spring-beans-3.1.xsd">

    <bean class="org.asteriskjava.fastagi.AgiServerThread"
          init-method="startup" destroy-method="shutdown">
        <property name="agiServer" ref="agiServer"/>
    </bean>

    <bean id="agiServer" class="org.asteriskjava.fastagi.DefaultAgiServer">
          <!--init-method="startup" destroy-method="shutdown">-->
        <property name="port" value="4573"/>
        <property name="mappingStrategy" ref="mappingStrategy"/>
    </bean>

    <bean id="vanivr" class="com.newcom.ncivr.agi.IvrAgi">
    </bean>

    <bean id="mappingStrategy" class="org.asteriskjava.fastagi.SimpleMappingStrategy">
        <property name="mappings">
            <map>
                <entry key="vanivr.agi" value-ref="vanivr"/>
            </map>
        </property>
    </bean>

</beans>
1
On

I put the relevant to stack traces from the dump below.

There is one thread which is BLOCKED and it is waiting to lock <0x0000000081cc7448>. If you search the thread dump you'll find the second mentioning of 0000000081cc7448 in the other thread I included below.

That thread is named restartedMain which seems to be related to the Boot Dev Tools which monitors files and restarts your application if a file changes. See for example the question SpringBoot app starts multiple times and disconnects from logstash and the comment.

I suggest that you remove/disable the Dev Tools since they seem to be involved in the problem.

"AJ DaemonPool-1.1" #258 daemon prio=5 os_prio=0 tid=0x000000001e067800 nid=0x4c0c waiting for monitor entry [0x000000002c75e000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:187)
    - waiting to lock <0x0000000081cc7448> (a java.util.concurrent.ConcurrentHashMap)
    at org.springframework.beans.factory.support.AbstractBeanFactory.isTypeMatch(AbstractBeanFactory.java:486)
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.doGetBeanNamesForType(DefaultListableBeanFactory.java:432)
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBeanNamesForType(DefaultListableBeanFactory.java:403)
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBeanNamesForType(DefaultListableBeanFactory.java:389)
    at org.springframework.beans.factory.BeanFactoryUtils.beanNamesForTypeIncludingAncestors(BeanFactoryUtils.java:177)
    at org.springframework.beans.factory.annotation.BeanFactoryAnnotationUtils.qualifiedBeanOfType(BeanFactoryAnnotationUtils.java:89)
    at org.springframework.beans.factory.annotation.BeanFactoryAnnotationUtils.qualifiedBeanOfType(BeanFactoryAnnotationUtils.java:66)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.determineQualifiedTransactionManager(TransactionAspectSupport.java:382)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.determineTransactionManager(TransactionAspectSupport.java:363)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:272)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:136)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:133)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.data.repository.core.support.SurroundingTransactionDetectorMethodInterceptor.invoke(SurroundingTransactionDetectorMethodInterceptor.java:57)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
    at com.sun.proxy.$Proxy70.save(Unknown Source)
    at com.newcom.ncivr.agi.VanuatuIvrAgi.mainMenuOptOne(VanuatuIvrAgi.java:109)
    at com.newcom.ncivr.agi.VanuatuIvrAgi.mainMenu(VanuatuIvrAgi.java:56)
    at com.newcom.ncivr.agi.VanuatuIvrAgi.service(VanuatuIvrAgi.java:38)
    at com.newcom.ncivr.agi.VanuatuIvrAgi$$FastClassBySpringCGLIB$$1e77fb85.invoke(<generated>)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:669)
    at com.newcom.ncivr.agi.VanuatuIvrAgi$$EnhancerBySpringCGLIB$$f6639040.service(<generated>)
    at org.asteriskjava.fastagi.internal.AgiConnectionHandler.runScript(AgiConnectionHandler.java:165)
    at org.asteriskjava.fastagi.internal.AgiConnectionHandler.run(AgiConnectionHandler.java:137)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)


"restartedMain" #26 prio=5 os_prio=0 tid=0x000000001c4dc000 nid=0xf9c runnable [0x000000001de5d000]
   java.lang.Thread.State: RUNNABLE
    at java.net.DualStackPlainSocketImpl.accept0(Native Method)
    at java.net.DualStackPlainSocketImpl.socketAccept(DualStackPlainSocketImpl.java:131)
    at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
    at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:199)
    - locked <0x00000000826ab858> (a java.net.SocksSocketImpl)
    at java.net.ServerSocket.implAccept(ServerSocket.java:545)
    at java.net.ServerSocket.accept(ServerSocket.java:513)
    at org.asteriskjava.util.internal.ServerSocketFacadeImpl.accept(ServerSocketFacadeImpl.java:49)
    at org.asteriskjava.fastagi.DefaultAgiServer.startup(DefaultAgiServer.java:312)
    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.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1758)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1695)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1624)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:555)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:483)
    at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306)
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)
    - locked <0x0000000081cc7448> (a java.util.concurrent.ConcurrentHashMap)
    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302)
    at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197)
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:761)
    at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:867)
    at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:543)
    - locked <0x0000000081cd9e08> (a java.lang.Object)
    at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:693)
    at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:360)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:303)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1118)
    at org.springframework.boot.SpringApplication.run(SpringApplication.java:1107)
    at com.newcom.ncivr.NcivrApplication.main(NcivrApplication.java:13)
    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.boot.devtools.restart.RestartLauncher.run(RestartLauncher.java:49)

UPDATE

Judging from your new Thread dump this AGI thingy gets into trouble without the assistance of the Boot Dev Tools. The blocking thread looks very similar to the one posted above. It is trying to connect to some server with a call to DefaultAgiServer.startup. Not sure what is wrong there but maybe it produces some logs or fails with a meaning full error after a long time or you can debug into it? Maybe it's just wrong connection information?

I found this link when googling for the method call.