DSS boxcarring 跳过操作

DSS boxcarring skipping operation

我将 DSS 3.5.0 与 PostgreSQL 一起使用,请求框中的一组操作无法以非常特殊的方式运行。我在同一个项目中成功地使用了包含数千个操作的请求框,包括与失败的操作非常相似的操作。其中一个大型请求框失败了,在花了一些时间寻找导致问题的操作之后,我们能够将其减少到一组五个操作。

问题

查看 PostgreSQL 日志,其中一个操作发出的查询未执行,因为它从未到达数据库。

我将调用操作 O1O2O3O4O5 及其查询 Q1Q2Q3Q4Q5。处理请求并检查生成的数据库日志,我们最终得到:

所以,它看起来很奇怪,而且似乎没有遵循清晰可辨的模式。

如果单独发送到 DSS,或在两个不同的请求框中,所有操作都会正确执行。操作的确切性质似乎与问题没有直接联系,因为在其他场景中无数次使用相同的操作。查询不是特别长或复杂。

错误和日志

PostgreSQL 为操作 5 发出的实际错误信息是

ERROR:  null value in column "element_id" violates not-null constraint

这是预期的,因为操作 4(消失的那个)插入了一个值,该值稍后用于解析操作 5 的 element_id

PostgreSQL 日志报告:

LOG:  execute <unnamed>: BEGIN
LOG:  execute <unnamed>: UPDATE public.project_element SET element_uuid=,location_id=,from_revit=,name=,type=,model=NULLIF(,0),parent_element=(SELECT PE.ELEMENT_ID FROM PROJECT_ELEMENT PE WHERE PE.PROJECT_ID =  AND (PE.ELEMENT_ID =  OR (PE.ELEMENT_UUID =  AND PE.ELEMENT_UUID IS NOT NULL))) ,left_border=,right_border= WHERE element_id=
DETAIL:  parameters:  = '(element-uuid)',  = '85',  = '1',  = '(some-text)',  = '3',  = '0',  = '22',  = NULL,  = '(parent-uuid)',  = NULL,  = NULL,  = '9983'
LOG:  execute <unnamed>: DELETE FROM ELEMENT_PROPERTY WHERE ELEMENT_ID = (SELECT PE.ELEMENT_ID FROM PROJECT_ELEMENT PE WHERE PE.ELEMENT_ID =  AND PE.PROJECT_ID = ) AND NAME = 
DETAIL:  parameters:  = '9983',  = '22',  = 'num_ports'
LOG:  execute <unnamed>: INSERT INTO public.element_property(name,value,type,element_id) VALUES(,,,(^M  SELECT PE.ELEMENT_ID FROM PROJECT_ELEMENT PE WHERE PE.PROJECT_ID =  AND (PE.ELEMENT_ID =  OR (PE.ELEMENT_UUID =  AND PE.ELEMENT_UUID IS NOT NULL))))
DETAIL:  parameters:  = 'num_ports',  = '48',  = '0',  = '22',  = NULL,  = '(element-uuid)'
LOG:  execute <unnamed>: INSERT INTO public.element_property(name,value,type,element_id) VALUES(,,,(SELECT PE.ELEMENT_ID FROM PROJECT_ELEMENT PE WHERE PE.PROJECT_ID =  AND (PE.ELEMENT_ID =  OR (PE.ELEMENT_UUID =  AND PE.ELEMENT_UUID IS NOT NULL))))
DETAIL:  parameters:  = 'port_num',  = '6',  = '0',  = '22',  = NULL,  = '(other-uuid)'
ERROR:  null value in column "element_id" violates not-null constraint
DETAIL:  Failing row contains (port_num, 6, 0, null).
STATEMENT:  INSERT INTO public.element_property(name,value,type,element_id) VALUES(,,,(SELECT PE.ELEMENT_ID FROM PROJECT_ELEMENT PE WHERE PE.PROJECT_ID =  AND (PE.ELEMENT_ID =  OR (PE.ELEMENT_UUID =  AND PE.ELEMENT_UUID IS NOT NULL))))
LOG:  execute S_2: BEGIN
LOG:  execute S_1: ROLLBACK

DSS 日志启动异常,但我不确定它是否真的与此问题有关。以下日志从请求框开始到它第一次抱怨从 PostgreSQL 返回的错误消息。之后DSS多次投诉

DEBUG -   {org.apache.axis2.transport.http.AxisServlet}
java.lang.NullPointerException
    at javax.servlet.GenericServlet.getServletContext(GenericServlet.java:123)
    at org.apache.axis2.transport.http.AxisServlet.createMessageContext(AxisServlet.java:715)
    at org.apache.axis2.transport.http.AxisServlet$RestRequestProcessor.<init>(AxisServlet.java:819)
    at org.apache.axis2.transport.http.AxisServlet.doPost(AxisServlet.java:227)
    at org.wso2.carbon.core.transports.CarbonServlet.doPost(CarbonServlet.java:231)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:646)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
    at org.eclipse.equinox.http.servlet.internal.ServletRegistration.service(ServletRegistration.java:61)
    at org.eclipse.equinox.http.servlet.internal.ProxyServlet.processAlias(ProxyServlet.java:128)
    at org.eclipse.equinox.http.servlet.internal.ProxyServlet.service(ProxyServlet.java:68)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
    at org.wso2.carbon.tomcat.ext.servlet.DelegationServlet.service(DelegationServlet.java:68)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.wso2.carbon.ui.filters.CSRFPreventionFilter.doFilter(CSRFPreventionFilter.java:88)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.wso2.carbon.ui.filters.CRLFPreventionFilter.doFilter(CRLFPreventionFilter.java:59)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.wso2.carbon.tomcat.ext.filter.CharacterSetFilter.doFilter(CharacterSetFilter.java:61)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:504)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
    at org.wso2.carbon.tomcat.ext.valves.CompositeValve.continueInvocation(CompositeValve.java:99)
    at org.wso2.carbon.tomcat.ext.valves.CarbonTomcatValve.invoke(CarbonTomcatValve.java:47)
    at org.wso2.carbon.webapp.mgt.TenantLazyLoaderValve.invoke(TenantLazyLoaderValve.java:57)
    at org.wso2.carbon.tomcat.ext.valves.TomcatValveContainer.invokeValves(TomcatValveContainer.java:47)
    at org.wso2.carbon.tomcat.ext.valves.CompositeValve.invoke(CompositeValve.java:62)
    at org.wso2.carbon.tomcat.ext.valves.CarbonStuckThreadDetectionValve.invoke(CarbonStuckThreadDetectionValve.java:159)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
    at org.wso2.carbon.tomcat.ext.valves.CarbonContextCreatorValve.invoke(CarbonContextCreatorValve.java:57)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:421)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1074)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1739)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1698)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:744)
DEBUG -  Input contentType (application/json) {org.apache.axis2.builder.BuilderUtil}
DEBUG -  CharSetEncoding defaulted (UTF-8) {org.apache.axis2.builder.BuilderUtil}
DEBUG -  [MessageContext: logID=f9462531f982d008b3e2aacd88bfd07f4a7e4905c354170e] Checking for Service using target endpoint address : /services/iims {org.apache.axis2.dispatchers.RequestURIBasedServiceDispatcher}
DEBUG -  org.apache.axis2.i18n.resource::handleGetObject(servicefound) {org.apache.axis2.i18n.ProjectResourceBundle}
DEBUG -  [MessageContext: logID=f9462531f982d008b3e2aacd88bfd07f4a7e4905c354170e] Found AxisService : iims {org.apache.axis2.engine.AbstractDispatcher}
DEBUG -  Attempt to check for Operation using HTTP Location failed {org.apache.axis2.dispatchers.HTTPLocationBasedDispatcher}
DEBUG -  [MessageContext: logID=f9462531f982d008b3e2aacd88bfd07f4a7e4905c354170e] Attempted to check for Operation using target endpoint URI, but the operation fragment was missing {org.apache.axis2.dispatchers.RequestURIBasedOperationDispatcher}
DEBUG -  getAction (null) from org.apache.axis2.client.Options@279e70a {org.apache.axis2.client.Options}
DEBUG -  SoapAction is (null) {org.apache.axis2.context.MessageContext}
DEBUG -  createSOAPEnvelope using Builder (class org.apache.axis2.json.JSONOMBuilder) selected from type (application/json) {org.apache.axis2.transport.TransportUtils}
DEBUG -  getAction (null) from org.apache.axis2.client.Options@279e70a {org.apache.axis2.client.Options}
DEBUG -  SoapAction is (null) {org.apache.axis2.context.MessageContext}
DEBUG -  [MessageContext: logID=f9462531f982d008b3e2aacd88bfd07f4a7e4905c354170e] Checking for Operation using Action : null {org.apache.axis2.dispatchers.ActionBasedOperationDispatcher}
DEBUG -  [MessageContext: logID=f9462531f982d008b3e2aacd88bfd07f4a7e4905c354170e] Attempted to check for Operation using target endpoint URI, but the operation fragment was missing {org.apache.axis2.dispatchers.RequestURIBasedOperationDispatcher}
DEBUG -  Axis operation is null {org.apache.axis2.json.gson.JSONMessageHandler}
DEBUG -  No headers present corresponding to http://www.w3.org/2005/08/addressing {org.apache.axis2.handlers.addressing.AddressingInHandler}
DEBUG -  No headers present corresponding to http://schemas.xmlsoap.org/ws/2004/08/addressing {org.apache.axis2.handlers.addressing.AddressingInHandler}
DEBUG -  getAction (null) from org.apache.axis2.client.Options@279e70a {org.apache.axis2.client.Options}
DEBUG -  SoapAction is (null) {org.apache.axis2.context.MessageContext}
DEBUG -  [MessageContext: logID=f9462531f982d008b3e2aacd88bfd07f4a7e4905c354170e] Checking for Operation using Action : null {org.apache.axis2.dispatchers.ActionBasedOperationDispatcher}
DEBUG -  getAction (null) from org.apache.axis2.client.Options@279e70a {org.apache.axis2.client.Options}
DEBUG -  SoapAction is (null) {org.apache.axis2.context.MessageContext}
DEBUG -  [MessageContext: logID=f9462531f982d008b3e2aacd88bfd07f4a7e4905c354170e] Checking for Operation using Action : null {org.apache.axis2.dispatchers.ActionBasedOperationDispatcher}
DEBUG -  Get operation for request_box {org.apache.axis2.description.AxisService}
DEBUG -  Found axis operation:  org.apache.axis2.description.InOutAxisOperation@682d0c2c {org.apache.axis2.description.AxisService}
DEBUG -  org.apache.axis2.i18n.resource::handleGetObject(operationfound) {org.apache.axis2.i18n.ProjectResourceBundle}
DEBUG -  [MessageContext: logID=f9462531f982d008b3e2aacd88bfd07f4a7e4905c354170e] Found AxisOperation : request_box {org.apache.axis2.engine.AbstractDispatcher}
DEBUG -  getAddressingRequirementParemeterValue: value: 'null' {org.apache.axis2.addressing.AddressingHelper}
DEBUG -  [MessageContext: logID=f9462531f982d008b3e2aacd88bfd07f4a7e4905c354170e] isReplyRedirected: ReplyTo is null. Returning false {org.apache.axis2.addressing.AddressingHelper}
DEBUG -  getAction (null) from org.apache.axis2.client.Options@112f42cb {org.apache.axis2.client.Options}
DEBUG -  Old WSAAction is (null) {org.apache.axis2.context.MessageContext}
DEBUG -  New WSAAction is (urn:request_boxResponse) {org.apache.axis2.context.MessageContext}
DEBUG -  setAction Old action is (null) {org.apache.axis2.client.Options}
DEBUG -  setAction New action is (urn:request_boxResponse) {org.apache.axis2.client.Options}
DEBUG -  messageID is null. {org.apache.axis2.context.ConfigurationContext}
DEBUG -  forceExpand: changing prefix from  to  {org.apache.axiom.om.impl.llom.OMSourcedElementImpl}
DEBUG -  DXXATransactionManager.begin() {org.wso2.carbon.dataservices.core.description.xa.DSSXATransactionManager}
DEBUG -  Creating data source connection {org.wso2.carbon.dataservices.core.description.config.SQLConfig}
ERROR -  ERROR: null value in column "element_id" violates not-null constraint_  Detalhe: Failing row contains (port_num, 6, 0, null). (Sanitized) {org.wso2.carbon.dataservices.core.description.query.SQLQuery}
org.postgresql.util.PSQLException: ERROR: null value in column "element_id" violates not-null constraint

执行

这是实际失败的请求框(替换了一些字段内容以减少噪音):

{
  "request_box":{
    "update_project_element_operation":{
      "name":"(some-text)",
      "element_id":9983,
      "element_uuid":"(element-uuid)",
      "from_revit":1,
      "project_id":22,
      "parent_element_uuid":"(parent-uuid)",
      "type":3,
      "location_id":85,
      "model":0
    },
    "delete_element_property_operation":{
      "name":"num_ports",
      "element_id":9983,
      "project_id":22
    },
    "insert_element_property_operation":{
      "project_id":22,
      "element_uuid":"(element-uuid)",
      "name":"num_ports",
      "value":"48"
    },
    "insert_project_element_operation":{
      "name":"(this operation disappears)",
      "element_id":0,
      "element_uuid":"(other-uuid)",
      "from_revit":1,
      "project_id":22,
      "parent_element_uuid":"(element-uuid)",
      "type":10,
      "location_id":85,
      "model":0
    },
    "insert_element_property_operation":{
      "project_id":22,
      "element_uuid":"(other-uuid)",
      "name":"port_num",
      "value":"6"
    }
  }
}

如有必要,我可以提供详细的table、查询和操作定义。以前使用过所有操作,如果单独发出或在两个不同的请求框中,它们中的每一个都有效。这似乎是一个与 DSS boxcarring 直接相关的问题。

有什么想法吗?

经过几周的调查,包括直接联系 WSO2 支持,我们得出结论,这个异常问题是由 DSS 内部的 JSON 到 XML 转换引起的。这可能与以下事实有关:JSON 格式的请求框表示可以包含 non-unique 名称(根据 RFC 7159,这种情况下的行为是不可预测的 implementation-defined)。应该注意的是,我们还使用了一个包含数千个相同名称重复的请求框,没有任何明显的问题,因此这并不是所有 non-unique 个名称未被正确处理的直接结果。

当我们在XML中尝试相同的请求框时,所有操作都正确执行。为了避免更改应用程序,我们听从了 WSO2 的建议,让 ESB 将 application-generated JSON 转换为 XML。初步测试表明,在这种情况下 XML 已正确生成,但是我们决定稍微调整 JSON 生成器以发出操作对象数组而不是包含具有 non-unique 名称的成员的对象, 以避免未定义的行为和 JSON 解析中出现新的、不可预测的问题的可能性。

WSO2 已经意识到这个问题,它可能会或可能不会被即将发布的 DSS 修复。在此之前,避免请求框意外的更安全方法似乎是在使用请求框向 DSS 发送交易时使用 XML 而不是 JSON。