Exception: The operation has timed out

Version 1
    This document was generated from CDN thread

    Created by: Mayank Sharma on 19-05-2009 06:51:14 PM
    I am performing a simple UPDATE query using AXL API. I update the EndUser fields like Manager, Dapartment etc. using the enduser userid. 
    AXLAPIService service = (AXLAPIService)Session["AXLAPIService"];       
    ExecuteSQLUpdateReq req = new ExecuteSQLUpdateReq();
    req.sql = query;
    service.executeSQLUpdate(req);
     

    While this query is being performed, the End User page on the CUCM Web Interface hangs (probably because the EndUser table is locked, not sure). But the main problem is that the query takes forever to complete and in the end I get this exception:
     
    The operation has timed out.

    I am only a updating a single user, the user information gets updated and I get the above mentioned exception after waiting for a long time.
     
    Any clue what is going on?
     
    Thanks,
    Max 

    Subject: RE: Exception: The operation has timed out
    Replied by: David Staudt on 20-05-2009 12:50:31 PM
    Is the UCM configured to sync with an external LDAP directory (like AD?) 
     
    Can you check the AXL service logs for any messages or errors (via RTMT?)

    Subject: RE: Exception: The operation has timed out
    Replied by: Mayank Sharma on 21-05-2009 12:43:14 PM
    Thanks for your response David.

    Is the UCM configured to sync with an external LDAP directory (like AD?)
      
     
    I am not sure. I have to check that.

    Can you check the AXL service logs for any messages or errors (via RTMT?)

     
    Where should I check these? This is what I did and did not get anything:
     
    RTMT -> Trace & Log Central -> Collect Files -> Cisco AXL Web Service.
     
    It went thru the whole process and in the end got a message that no files exist for this date range.
     
    Update: We have another CUCM for testing and I tried the query on that box and it was almost instantaneous and I am sure that is not synched with any LDAP directory. Let me find out if our production one is... 

    Subject: RE: Exception: The operation has timed out
    Replied by: Mayank Sharma on 21-05-2009 02:43:47 PM
    I checked everything under System -> LDAP on CUCM web interface and nothing seems to be configured. Anything or anywhere else I should check?

    Subject: RE: Exception: The operation has timed out
    Replied by: David Staudt on 22-05-2009 02:30:04 PM
    If there are no AXL logs, that suggests the AXL service hasn't been started..?

    Subject: RE: Exception: The operation has timed out
    Replied by: Mayank Sharma on 27-05-2009 02:44:49 PM
    If there are no AXL logs, that suggests the AXL service hasn't been started..?

    That's strange because the update does work, I can see the new values for the user in CUCM web interface once the operation has timed out and I wait for a while to refreh the page (since it seems like the table is being locked).
     
    Also, I checked the AXL Service and it is started.
     
    Is there no other place where AXL notifications are logged in RTMT? 
    Thanks,
    Max

    Subject: RE: Exception: The operation has timed out
    Replied by: Mayank Sharma on 27-05-2009 03:26:00 PM
    Finally looked in the right place and got this (Real Time Trace):
     
    2009-05-27 11:19:12,990 INFO  [http-8443-Processor15] axl.AXLRouter - <?xml version="1.0" encoding="utf-8"?><soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="[url=http://www.w3.org/2001/XMLSchema"><soap:Body><executeSQLUpdate]http://www.w3.org/2001/XMLSchema"><soap:Body><executeSQLUpdate xmlns="[url=http://www.cisco.com/AXL/API/6.1"><sql]http://www.cisco.com/AXL/API/6.1"><sql xmlns="">UPDATE EndUser SET department='Sales' WHERE userid='JDoe'</sql></executeSQLUpdate></soap:Body></soap:Envelope>
    2009-05-27 11:22:22,018 ERROR [http-8443-Processor15] axl.AXLRouter - com.cisco.ccm.axl.AXLRouter@70c52d
    java.sql.SQLException: Can't load driver java.lang.reflect.InvocationTargetException
     at com.informix.util.IfxErrMsg.getLocSQLException(IfxErrMsg.java:494)
     at com.informix.jdbc.IfxDriver.connect(IfxDriver.java:271)
     at java.sql.DriverManager.getConnection(DriverManager.java:525)
     at java.sql.DriverManager.getConnection(DriverManager.java:193)
     at com.cisco.ccm.dbl.Connector.getConn(Connector.java:663)
     at com.cisco.ccm.dbl.Connector.connect(Connector.java:580)
     at com.cisco.ccm.dbl.Connector.connect(Connector.java:510)
     at com.cisco.ccm.dbl.Connector.createStatement(Connector.java:751)
     at com.cisco.ccm.dbl.Connector.createStatement(Connector.java:733)
     at com.cisco.ccm.axl.AXLThrottler.processDBLCNQueue(AXLThrottler.java:315)
     at com.cisco.ccm.axl.AXLThrottler.getThrottlingCount(AXLThrottler.java:175)
     at com.cisco.ccm.axl.AXLRouter.checkThrottleStatus(AXLRouter.java:515)
     at com.cisco.ccm.axl.AXLRouter.doPost(AXLRouter.java:188)
     at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
     at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
     at sun.reflect.GeneratedMethodAccessor244.invoke(Unknown Source)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
     at java.lang.reflect.Method.invoke(Method.java:585)
     at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:243)
     at java.security.AccessController.doPrivileged(Native Method)
     at javax.security.auth.Subject.doAsPrivileged(Subject.java:517)
     at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:275)
     at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:161)
     at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:245)
     at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:50)
     at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:156)
     at java.security.AccessController.doPrivileged(Native Method)
     at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:152)
     at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
     at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
     at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:524)
     at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
     at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
     at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:541)
     at org.apache.catalina.authenticator.SingleSignOn.invoke(SingleSignOn.java:392)
     at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
     at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
     at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:869)
     at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:664)
     at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
     at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
     at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
     at java.lang.Thread.run(Thread.java:595)
    Caused by: java.lang.reflect.InvocationTargetException
     at sun.reflect.GeneratedConstructorAccessor546.newInstance(Unknown Source)
     at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
     at java.lang.reflect.Constructor.newInstance(Constructor.java:494)
     at com.informix.jdbc.IfxDriver.connect(IfxDriver.java:254)
     ... 41 more
    Caused by: java.sql.SQLException: com.informix.asf.IfxASFException: Attempt to connect to database server (dscmsub_ccm6_1_3_1000_16) failed.
     at com.informix.jdbc.IfxSqliConnect.<init>(IfxSqliConnect.java:1042)
     ... 45 more
    Caused by: com.informix.asf.IfxASFException: Attempt to connect to database server (dscmsub_ccm6_1_3_1000_16) failed.
     at com.informix.util.IfxErrMsg.getLocIfxASFException(IfxErrMsg.java:797)
     at com.informix.asf.Connection.openSocket(Connection.java:1664)
     at com.informix.asf.Connection.<init>(Connection.java:259)
     at com.informix.jdbc.IfxSqliConnect.<init>(IfxSqliConnect.java:906)
     ... 45 more
    Caused by: java.net.ConnectException: Connection timed out
     at java.net.PlainSocketImpl.socketConnect(Native Method)
     at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333)
     at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:195)
     at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:182)
     at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
     at java.net.Socket.connect(Socket.java:520)
     at java.net.Socket.connect(Socket.java:470)
     at java.net.Socket.<init>(Socket.java:367)
     at java.net.Socket.<init>(Socket.java:180)
     at com.informix.asf.Connection.openSocket(Connection.java:1615)
     ... 47 more
    2009-05-27 11:22:22,019 INFO  [http-8443-Processor15] axl6_1.Handler - Handler initializing
    2009-05-27 11:22:22,054 INFO  [http-8443-Processor15] axl.AXLRouter - <?xml version="1.0" encoding="UTF-8"?><SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/" SOAP-ENV:encodingStyle="[url=http://schemas.xmlsoap.org/soap/encoding/"><SOAP-ENV:Header/><SOAP-ENV:Body><axl:executeSQLUpdateResponse]http://schemas.xmlsoap.org/soap/encoding/"><SOAP-ENV:Header/><SOAP-ENV:Body><axl:executeSQLUpdateResponse xmlns:axl="http://www.cisco.com/AXL/API/6.1" xmlns:xsi="[url=http://www.cisco.com/AXL/API/6.1"><return><rowsUpdated>1</rowsUpdated></return></axl:executeSQLUpdateResponse></SOAP-ENV:Body></SOAP-ENV:Envelope]http://www.cisco.com/AXL/API/6.1"><return><rowsUpdated>1</rowsUpdated></return></axl:executeSQLUpdateResponse></SOAP-ENV:Body></SOAP-ENV:Envelope>
    2009-05-27 11:22:22,055 INFO  [http-8443-Processor15] axl.AXLRouter - Request 1240610422419 was process in 189066ms

    Subject: RE: Exception: The operation has timed out
    Replied by: David Staudt on 28-05-2009 06:41:29 PM
    The SOAP request with the SQL UPDATE statement seems to work fine on my UCM 7.0(1) system.  I don't think there is anything wrong with the request.

    Based on the symptoms described and the AXL service error message in the logs, my guess would be that there is a connectivity/configuration/clustering type problem going on.  Some possible items to check:

    - Which version of UCM are you working with
    - You are making the request against the cluster Publisher (not Subscribers)
    - Cluster configuration is correct and all nodes are connected/responding
    - Cluster database replication is working correctly (http://www.cisco.com/en/US/products/sw/voicesw/ps556/products_tech_note09186a00809643e8.shtml, please work with Cisco TAC for assistance)
    - LDAP synchronization is not enabled (I think this has already been covered)

    If you are still unable to resolve the issue, I would recommend joining the Cisco Developer Services support program and opening a case: http://developer.cisco.com/web/devservices

    Subject: RE: Exception: The operation has timed out
    Replied by: Mayank Sharma on 29-05-2009 12:07:30 PM
     You are making the request against the cluster Publisher (not Subscribers)

     
    Yes, the UPDATE statement works fine, if you notice at the end of the error response, it says that 1 record updated.
     
    By the above statement in quotes, you mean I should make the request to the Publisher and not Subscriber, right?

    Subject: RE: Exception: The operation has timed out
    Replied by: David Staudt on 29-05-2009 01:53:03 PM
    Any kind of AXL update should be done on the Publisher, due to cluster DB replication.  Two other observations from the logs:

    - "Attempt to connect to database server (dscmsub_ccm6_1_3_1000_16) failed."  This seems to indicate some misconfiguration or communication probleml
    - Time the request was made:  11:19:12, time completed: 11:22:22
     
    This suggests to me that AXL is attempting to connect to the Pub to make the update (though dscmsub_cm6 looks like a Sub), times out and fails over to the local DB, which succeeds...