AnsweredAssumed Answered

Default auditing causes web script to fail

Question asked by lnfalandino on May 6, 2008
Latest reply on Jul 23, 2008 by andy
Update: I'm using Alfresco 2.9B.

I recently enabled the default auditing capabilities in Alfresco (according to this guide: http://wiki.alfresco.com/wiki/Audit#Configuration_Guide) and it is causing a simple web script I created to fail in a strange way. I've verified that disabling the auditing causes the problem to go away, so something it is doing is causing the web script to behave this way.

The web script was for a simple proof of concept. It takes content that was posted to it and updates a specific file in an AVM store. Here's the code for it (it isn't pretty but it's just throw away code that I was using to test some things).


script:
{
   var content = args["content"];
   
    // extract avm store id and path
    var fullpath = url.extension.split("/");
    if (fullpath.length == 0)
    {
      status.code = 400;
      status.message = "Store id has not been provided.";
      status.redirect = true;
      break script;
    }
    var storeid = fullpath[0];
    var state   = args["state"];
    if(state == null || state == "active")
    {
        //storeid += "live";
    }   
    else if(state == "wip")
    {
        //storeid += "–" + person.properties.userName;
    }
    else if(state == "staging")
    {
        // Do nothing
    }
   
    var path = "/www/avm_webapps/ROOT/content.html";
   
    // locate avm node from path
    var store = avm.lookupStore(storeid);
    if (store == undefined)
    {
      status.code = 404;
      status.message = "Store " + storeid + " not found.";
      status.redirect = true;
      break script;
    }
   
   var document = avm.lookupNode(storeid + ":" + path);

   if (document != null)
   {
      document.setContent(content);
      document.save();
     
      // setup model for response template
     model.result = 'success'
      status.code = 200;
    }
    else
    {
     model.result = 'failure'
      status.code = 400;
      status.message = "Error: File for update does not exist";
      status.redirect = true;
    }
}

Pretty straight forward: it verifies that the store and document exist and if so, saves the posted content to it, returning a simple one word "success" or "failure" in the response.

When I enable the default auditing (specifically, this auditConfig.xml file: https://svn.alfresco.com/repos/alfresco-open-mirror/alfresco/HEAD/root/projects/repository/config/alfresco/auditConfig.xml) this is the response text that is returned:


successsuccesssuccesssuccesssuccesssuccesssuccesssuccesssuccesssuccesssuccesssuccesssuccesssuccesssuccesssuccesssuccesssuccesssuccesssuccess<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Strict//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd">
<html xmlns="http://www.w3.org/1999/xhtml">
  <head>
    <title>Web Script Status 500 - Internal Error</title>
    <link rel="stylesheet" href="/alfresco/css/main.css" TYPE="text/css">
  </head>
  <body>
    <table>
     <tr>
        <td><img src="/alfresco/images/logo/AlfrescoLogo32.png" alt="Alfresco" /></td>
        <td><nobr><span class="mainTitle">Web Script Status 500 - Internal Error</span></nobr></td>
     </tr>
    </table>
    <br>
    <table>
     <tr><td>The Web Script <a href="/alfresco/service/company/wcm/avmsave/customerlive/content.html">/alfresco/service/company/wcm/avmsave/customerlive/content.html</a> has responded with a status of 500 - Internal Error.
    </table>
    <br>
    <table>
     <tr><td><b>500 Description:</b><td> An error inside the HTTP server which prevented it from fulfilling the request.
     <tr><td> 
     <tr><td><b>Message:</b><td>Could not execute JDBC batch update
       <tr><td>     
   <tr><td><b>Exception:</b><td>java.sql.BatchUpdateException - ORA-01401: inserted value too large for column

   <tr><td><td> 
         <tr><td><td>oracle.jdbc.driver.DatabaseError.throwBatchUpdateException(DatabaseError.java:343)
         <tr><td><td>oracle.jdbc.driver.OraclePreparedStatement.executeBatch(OraclePreparedStatement.java:10720)
         <tr><td><td>org.apache.commons.dbcp.DelegatingStatement.executeBatch(DelegatingStatement.java:294)
         <tr><td><td>org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:48)
         <tr><td><td>org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:242)
         <tr><td><td>org.hibernate.jdbc.AbstractBatcher.prepareStatement(AbstractBatcher.java:92)
         <tr><td><td>org.hibernate.jdbc.AbstractBatcher.prepareStatement(AbstractBatcher.java:87)
         <tr><td><td>org.hibernate.jdbc.AbstractBatcher.prepareBatchStatement(AbstractBatcher.java:218)
         <tr><td><td>org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2174)
         <tr><td><td>org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2610)
         <tr><td><td>org.hibernate.action.EntityInsertAction.execute(EntityInsertAction.java:52)
         <tr><td><td>org.hibernate.engine.ActionQueue.execute(ActionQueue.java:248)
         <tr><td><td>org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:232)
         <tr><td><td>org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:139)
         <tr><td><td>org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
         <tr><td><td>org.hibernate.event.def.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:41)
         <tr><td><td>org.hibernate.impl.SessionImpl.autoFlushIfRequired(SessionImpl.java:969)
         <tr><td><td>org.hibernate.impl.SessionImpl.list(SessionImpl.java:1114)
         <tr><td><td>org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)
         <tr><td><td>org.alfresco.repo.attributes.hibernate.MapEntryDAOHibernate.get(MapEntryDAOHibernate.java:79)
         <tr><td><td>org.alfresco.repo.attributes.MapAttributeImpl.entrySet(MapAttributeImpl.java:152)
         <tr><td><td>org.alfresco.service.cmr.repository.datatype.DefaultTypeConverter$23.convert(DefaultTypeConverter.java:311)
         <tr><td><td>org.alfresco.service.cmr.repository.datatype.DefaultTypeConverter$23.convert(DefaultTypeConverter.java:308)
         <tr><td><td>org.alfresco.service.cmr.repository.datatype.TypeConverter.convert(TypeConverter.java:120)
         <tr><td><td>org.alfresco.repo.domain.PropertyValue$ValueType$11.convert(PropertyValue.java:199)
         <tr><td><td>org.alfresco.repo.domain.PropertyValue.getValue(PropertyValue.java:836)
         <tr><td><td>org.alfresco.repo.node.AbstractNodeServiceImpl.makeSerializableValue(AbstractNodeServiceImpl.java:691)
         <tr><td><td>org.alfresco.repo.avm.AVMNodeService.getProperties(AVMNodeService.java:975)
         <tr><td><td>sun.reflect.GeneratedMethodAccessor324.invoke(Unknown Source)
         <tr><td><td>sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
         <tr><td><td>java.lang.reflect.Method.invoke(Method.java:585)
         <tr><td><td>org.alfresco.repo.service.StoreRedirectorProxyFactory$RedirectorInvocationHandler.invoke(StoreRedirectorProxyFactory.java:221)
         <tr><td><td>$Proxy73.getProperties(Unknown Source)
         <tr><td><td>sun.reflect.GeneratedMethodAccessor324.invoke(Unknown Source)
         <tr><td><td>sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
         <tr><td><td>java.lang.reflect.Method.invoke(Method.java:585)
         <tr><td><td>org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:281)
         <tr><td><td>org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:187)
         <tr><td><td>org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:154)
         <tr><td><td>org.alfresco.repo.node.MLPropertyInterceptor.invoke(MLPropertyInterceptor.java:175)
         <tr><td><td>org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:176)
         <tr><td><td>org.alfresco.repo.node.MLPropertyInterceptor.invoke(MLPropertyInterceptor.java:175)
         <tr><td><td>org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:176)
         <tr><td><td>org.alfresco.repo.node.NodeRefPropertyMethodInterceptor.invoke(NodeRefPropertyMethodInterceptor.java:204)
         <tr><td><td>org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:176)
         <tr><td><td>org.alfresco.repo.node.NodeRefPropertyMethodInterceptor.invoke(NodeRefPropertyMethodInterceptor.java:204)
         <tr><td><td>org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:176)
         <tr><td><td>org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:210)
         <tr><td><td>$Proxy72.getProperties(Unknown Source)
         <tr><td><td>org.alfresco.repo.node.integrity.IncompleteNodeTagger.processNode(IncompleteNodeTagger.java:354)
         <tr><td><td>org.alfresco.repo.node.integrity.IncompleteNodeTagger.beforeCommit(IncompleteNodeTagger.java:343)
         <tr><td><td>org.alfresco.repo.transaction.AlfrescoTransactionSupport$TransactionSynchronizationImpl.doBeforeCommit(AlfrescoTransactionSupport.java:638)
         <tr><td><td>org.alfresco.repo.transaction.AlfrescoTransactionSupport$TransactionSynchronizationImpl.doBeforeCommit(AlfrescoTransactionSupport.java:620)
         <tr><td><td>org.alfresco.repo.transaction.AlfrescoTransactionSupport$TransactionSynchronizationImpl.beforeCommit(AlfrescoTransactionSupport.java:592)
         <tr><td><td>org.springframework.transaction.support.TransactionSynchronizationUtils.triggerBeforeCommit(TransactionSynchronizationUtils.java:48)
         <tr><td><td>org.springframework.transaction.support.AbstractPlatformTransactionManager.triggerBeforeCommit(AbstractPlatformTransactionManager.java:821)
         <tr><td><td>org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:637)
         <tr><td><td>org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:624)
         <tr><td><td>org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:307)
         <tr><td><td>org.alfresco.util.transaction.SpringAwareUserTransaction.commit(SpringAwareUserTransaction.java:420)
         <tr><td><td>org.alfresco.repo.transaction.RetryingTransactionHelper.doInTransaction(RetryingTransactionHelper.java:250)
         <tr><td><td>org.alfresco.repo.transaction.RetryingTransactionHelper.doInTransaction(RetryingTransactionHelper.java:166)
         <tr><td><td>org.alfresco.repo.web.scripts.RepositoryContainer.transactionedExecute(RepositoryContainer.java:286)
         <tr><td><td>org.alfresco.repo.web.scripts.RepositoryContainer.executeScript(RepositoryContainer.java:230)
         <tr><td><td>org.alfresco.web.scripts.AbstractRuntime.executeScript(AbstractRuntime.java:227)
         <tr><td><td>org.alfresco.web.scripts.AbstractRuntime.executeScript(AbstractRuntime.java:130)
         <tr><td><td>org.alfresco.web.scripts.servlet.WebScriptServlet.service(WebScriptServlet.java:108)
         <tr><td><td>javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
         <tr><td><td>org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
         <tr><td><td>org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
         <tr><td><td>org.alfresco.web.app.servlet.AuthenticationFilter.doFilter(AuthenticationFilter.java:81)
         <tr><td><td>com.covisint.content.alfresco.ext.security.authentication.servlet.AuthenticationFilter.doFilter(AuthenticationFilter.java:110)
         <tr><td><td>org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
         <tr><td><td>org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
         <tr><td><td>org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
         <tr><td><td>org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
         <tr><td><td>org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
         <tr><td><td>org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230)
         <tr><td><td>org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175)
         <tr><td><td>org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:179)
         <tr><td><td>org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:524)
         <tr><td><td>org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:84)
         <tr><td><td>org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
         <tr><td><td>org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
         <tr><td><td>org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:157)
         <tr><td><td>org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
         <tr><td><td>org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:262)
         <tr><td><td>org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:844)
         <tr><td><td>org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
         <tr><td><td>org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:446)
         <tr><td><td>java.lang.Thread.run(Thread.java:595)
   <tr><td><td> 
   <tr><td><b>Exception:</b><td>org.hibernate.exception.ConstraintViolationException -

Interesting things to note: It writes "success" twenty times before giving the "ORA-01401: inserted value too large for column" error. This behavior can be seen when using the javascript debugger; it actually calls the web script over and over again. Additionally, the file is never actually updated. It's as if when it tries to do the document.save() it runs into an issue attempting to audit the change and somehow the request is reposted many times. I'm not sure what field it is unhappy about, but I suspect it's something in the AUDIT_FACT table (perhaps trying to audit the actual content of the node).

I'm looking to hopefully figure out what is causing this and what can be changed about either my web script or my audit configuration to prevent this issue, while still being able to audit these kinds of changes posted by web scripts.

Thanks in advance for any help on this interesting issue.

Naim

Outcomes