SoapUI DocQuery Test Yields EMPTY AdhocQueryResponse? CONNECT 4.7

classic Classic list List threaded Threaded
2 messages Options
Reply | Threaded
Open this post in threaded view
|

SoapUI DocQuery Test Yields EMPTY AdhocQueryResponse? CONNECT 4.7

johnhd_at_zen
As background, I've been working with CONNECT 4.7 and I'm using the SOAP UI tests that ship with CONNECT. I've found that the DQ tests fails out of the box complaining about not finding a patient correlation for the prepopulated information.

<ns2:RegistryError codeContext="No patient correlations found." errorCode="XDSUnknownPatientId" severity="urn:oasis:names:tc:ebxml-regrep:ErrorSeverityType:Error"/>

I had to insert a correlation myself in the DB to get a proper DQ response for initial testing.

 insert into correlatedidentifiers values ('1234','1.1','D123401','2.2','D123401','2027-10-10');

(It still failed the test, complaining that the DOCID doesn't match the SOAP UI assertion, but I manually vetted that the document returned was associated to the patient D123401. I haven't drilled too much further into it, but as a side note I think this tests' variables and/or assertions are incorrect)

Here's the response I was able to get:

<soap:Envelope xmlns:soap="http://www.w3.org/2003/05/soap-envelope">
   <soap:Header/>
   <soap:Body>
      <ns3:AdhocQueryResponse startIndex="0" status="urn:oasis:names:tc:ebxml-regrep:ResponseStatusType:Success" totalResultCount="1" xmlns:ns10="http://docs.oasis-open.org/wsn/b-2" xmlns:ns11="http://docs.oasis-open.org/wsn/t-1" xmlns:ns12="http://docs.oasis-open.org/wsrf/bf-2" xmlns:ns13="urn:gov:hhs:fha:nhinc:common:subscriptionb2overridefordocuments" xmlns:ns14="http://www.hhs.gov/healthit/nhin/cdc" xmlns:ns15="urn:gov:hhs:fha:nhinc:common:subscriptionb2overrideforcdc" xmlns:ns16="urn:oasis:names:tc:emergency:EDXL:DE:1.0" xmlns:ns17="urn:oasis:names:tc:ebxml-regrep:xsd:rim:3.0" xmlns:ns18="http://www.caqh.org/SOAP/WSDL/CORERule2.2.0.xsd" xmlns:ns2="urn:oasis:names:tc:ebxml-regrep:xsd:rs:3.0" xmlns:ns3="urn:oasis:names:tc:ebxml-regrep:xsd:query:3.0" xmlns:ns4="urn:gov:hhs:fha:nhinc:common:nhinccommon" xmlns:ns5="urn:gov:hhs:fha:nhinc:common:nhinccommonentity" xmlns:ns6="urn:oasis:names:tc:ebxml-regrep:xsd:lcm:3.0" xmlns:ns7="http://www.w3.org/2005/08/addressing" xmlns:ns8="urn:ihe:iti:xds-b:2007" xmlns:ns9="http://nhinc.services.com/schema/auditmessage">
         <ns2:ResponseSlotList/>
         <ns17:RegistryObjectList>
            <ns17:ExtrinsicObject home="urn:oid:1.1" id="urn:uuid:191be86b-762c-40fc-943f-7821020bacae" isOpaque="false" mimeType="text/xml" objectType="urn:uuid:7edca82f-054d-47f2-a032-9b2a5b5186c1" status="Active">
               <ns17:Slot name="creationTime">
                  <ns17:ValueList>
                     <ns17:Value>20080627184924</ns17:Value>
                  </ns117:ValueList>
                  </ns17:Slot>
                  <ns17:Slot name="authorSpecialty">
                     <ns17:ValueList>
                        <ns17:Value>General</ns17:Value>
                     </ns17:ValueList>
  ............
               <ns17:ExternalIdentifier id="" identificationScheme="urn:uuid:58a6f841-87b3-4a3e-92fd-a8ffeff98427" registryObject="urn:uuid:6c44586d-424c-48f1-a1cc-ac158ffdc60f" value="D123401^^^&amp;2.2&amp;ISO">
                  <ns17:Name>
                     <ns17:LocalizedString value="XDSDocumentEntry.patientId"/>
                  </ns17:Name>
               </ns17:ExternalIdentifier>
            </ns17:ExtrinsicObject>
         </ns17:RegistryObjectList>
      </ns3:AdhocQueryResponse>
   </soap:Body>
</soap:Envelope>


Since this initial testing, I have been working on configuring passthrough mode for the main transactions. I had initial success with MPI and XCPD transactions.

Working with XCA DQ I'm encountering some strange behaviour now, where the same inbound DQ elicits a very short "stub" of a response instead of the previously successful message:

<soap:Envelope xmlns:soap="http://www.w3.org/2003/05/soap-envelope">
   <soap:Header/>
   <soap:Body>
      <ns3:AdhocQueryResponse status="urn:oasis:names:tc:ebxml-regrep:ResponseStatusType:Success" xmlns:ns10="http://docs.oasis-open.org/wsn/b-2" xmlns:ns11="http://docs.oasis-open.org/wsn/t-1" xmlns:ns12="http://docs.oasis-open.org/wsrf/bf-2" xmlns:ns13="urn:gov:hhs:fha:nhinc:common:subscriptionb2overridefordocuments" xmlns:ns14="http://www.hhs.gov/healthit/nhin/cdc" xmlns:ns15="urn:gov:hhs:fha:nhinc:common:subscriptionb2overrideforcdc" xmlns:ns16="urn:oasis:names:tc:emergency:EDXL:DE:1.0" xmlns:ns17="urn:oasis:names:tc:ebxml-regrep:xsd:rim:3.0" xmlns:ns18="http://www.caqh.org/SOAP/WSDL/CORERule2.2.0.xsd" xmlns:ns2="urn:oasis:names:tc:ebxml-regrep:xsd:rs:3.0" xmlns:ns3="urn:oasis:names:tc:ebxml-regrep:xsd:query:3.0" xmlns:ns4="urn:gov:hhs:fha:nhinc:common:nhinccommon" xmlns:ns5="urn:gov:hhs:fha:nhinc:common:nhinccommonentity" xmlns:ns6="urn:oasis:names:tc:ebxml-regrep:xsd:lcm:3.0" xmlns:ns7="urn:ihe:iti:xds-b:2007" xmlns:ns8="http://nhinc.services.com/schema/auditmessage" xmlns:ns9="http://www.w3.org/2005/08/addressing"/>
   </soap:Body>
</soap:Envelope>

I've reset all the relevant config files (internalConnectionInfo.xml, DocumentQueryProxyConfig.xml, gateway.properties) to their default (stock) versions and tried again to no effect. It's like it suddenly gave up on me.

There are no errors in the logs for this message.

2017-10-27 12:14:43,106 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE DefaultListableBeanFactory:527 - No bean named '' found in org.springframework.beans.factory.support.DefaultListableBeanFactory@bbd775e: defining beans [securityConfigInInterceptor,timestampInInterceptor,attachmentFaultOutInterceptor,eventfactory,txHibernateUtil,eventHibernateUtil,asyncmsgsHibernateUtil,connManHibernateUtil,docRepoHibernateUtil,patientCorrHibernateUtil,msgMonitorHibernateUtil,directConfigHibernateUtil,org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,org.springframework.context.annotation.internalPersistenceAnnotationProcessor,eventmanager,messageRoutingAccessor,inboundMessageAdviceDelegate,inboundProcessingAdviceDelegate,adapterDelegationAdviceDelegate,outboundMessageAdviceDelegate,outboundProcessingAdviceDelegate,nwhinInvocationAdviceDelegate,eventAspectAdvice,org.springframework.aop.config.internalAutoProxyCreator,org.springframework.beans.factory.config.PropertyPlaceholderConfigurer#0,nhinDQ,entityDQUnsecured,entityDQSecured,stdDQOutbound,ptDQOutbound,stdDQInbound,ptDQInbound,SOAPHeaderHandler,TransactionHandler,org.apache.cxf.bus.spring.BusWiringBeanFactoryPostProcessor,cxf.config0,NhinDocumentQuery30,EntityDocumentQuery_a1,EntityDocumentQuerySecured_a1,EntityDocQueryUnsecuredProxy,cxf]; root of factory hierarchy
2017-10-27 12:14:43,138 DEBUG [gov.hhs.fha.nhinc.logging.transaction.TransactionHandler] (default task-5) TransactionHandler handleMessage() START 
2017-10-27 12:14:43,138 DEBUG [gov.hhs.fha.nhinc.logging.transaction.TransactionHandler] (default task-5) TransactionHandler handleMessage() WSA namespace = http://www.w3.org/2004/08/addressing
2017-10-27 12:14:43,146 WARN  [org.apache.cxf.ws.addressing.ContextUtils] (default task-5) WS-Addressing - failed to retrieve Message Addressing Properties from context
2017-10-27 12:14:43,147 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Trying to get lock for ApplicationContext file:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/TransactionLoggingProxyConfig.xml
2017-10-27 12:14:43,147 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) ApplicationContext for: TransactionLoggingProxyConfig.xml was not null - checking to see if it is stale.
2017-10-27 12:14:43,147 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Releasing lock for ApplicationContextfile:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/TransactionLoggingProxyConfig.xml
2017-10-27 12:14:43,148 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 DEBUG DefaultListableBeanFactory:244 - Returning cached instance of singleton bean 'transactionstoredatabase'
2017-10-27 12:14:43,148 DEBUG [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) TransactionDAO.getTransactinId() - Begin
2017-10-27 12:14:43,148 INFO  [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) -- MessageId Parameter is required for Transaction Query --
2017-10-27 12:14:43,148 DEBUG [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) TransactionDAO.getTransactinId() - End
2017-10-27 12:14:43,148 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Trying to get lock for ApplicationContext file:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/TransactionLoggingProxyConfig.xml
2017-10-27 12:14:43,148 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) ApplicationContext for: TransactionLoggingProxyConfig.xml was not null - checking to see if it is stale.
2017-10-27 12:14:43,148 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Releasing lock for ApplicationContextfile:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/TransactionLoggingProxyConfig.xml
2017-10-27 12:14:43,149 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 DEBUG DefaultListableBeanFactory:244 - Returning cached instance of singleton bean 'transactionstoredatabase'
2017-10-27 12:14:43,149 DEBUG [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) TransactionDAO.getTransactinId() - Begin
2017-10-27 12:14:43,149 INFO  [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) -- MessageId Parameter is required for Transaction Query --
2017-10-27 12:14:43,149 DEBUG [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) TransactionDAO.getTransactinId() - End
2017-10-27 12:14:43,149 DEBUG [gov.hhs.fha.nhinc.persistence.HibernateUtilFactory] (default task-5) Memory address eventHibernateUtil org.springframework.context.support.ClassPathXmlApplicationContext@56e2f983
2017-10-27 12:14:43,151 ERROR [stderr] (default task-5) Fri Oct 27 12:14:43 CDT 2017 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.
2017-10-27 12:14:43,155 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:249 - No transaction, no need to enlist: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7987bef5[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110 connection handles=0 lastUse=1509124483154 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@78f9587e mcp=SemaphoreArrayListManagedConnectionPool@20c9ebba[pool=eventdb_pool] xaResource=LocalXAResourceImpl@579e53f3[connectionListener=7987bef5 connectionManager=a5d6a62 warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/eventdb_datasource] txSync=null]
2017-10-27 12:14:43,155 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:267 - [TxConnectionListener@7987bef5] registerConnection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@39fdd217 [size=1] ([org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@39fdd217])
2017-10-27 12:14:43,160 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:615 - connectionClosed called mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110
2017-10-27 12:14:43,161 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@7987bef5] isManagedConnectionFree: false
2017-10-27 12:14:43,161 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:326 - [TxConnectionListener@7987bef5] unregisterConnection: 0 handles left ([])
2017-10-27 12:14:43,162 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@7987bef5] isManagedConnectionFree: true
2017-10-27 12:14:43,162 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:394 - delisting org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7987bef5[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110 connection handles=0 lastUse=1509124483154 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@78f9587e mcp=SemaphoreArrayListManagedConnectionPool@20c9ebba[pool=eventdb_pool] xaResource=LocalXAResourceImpl@579e53f3[connectionListener=7987bef5 connectionManager=a5d6a62 warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/eventdb_datasource] txSync=null]
2017-10-27 12:14:43,162 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@7987bef5] isManagedConnectionFree: true
2017-10-27 12:14:43,163 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:501 - delisted org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7987bef5[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110 connection handles=0 lastUse=1509124483154 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@78f9587e mcp=SemaphoreArrayListManagedConnectionPool@20c9ebba[pool=eventdb_pool] xaResource=LocalXAResourceImpl@579e53f3[connectionListener=7987bef5 connectionManager=a5d6a62 warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/eventdb_datasource] txSync=null]
2017-10-27 12:14:43,163 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:639 - isManagedConnectionFree=true mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110
2017-10-27 12:14:43,164 INFO  [gov.hhs.fha.nhinc.event.Log4jEventLogger] (default task-5) BEGIN_OUTBOUND_MESSAGE has triggered. It has messageID null, transactionID null and description {"service_type":"Document Query","payload_types":["AdhocQueryRequest"],"responding_hcids":["urn:oid:2.2"],"action":"3.0","initiating_hcid":"urn:oid:1.1"}
2017-10-27 12:14:43,164 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Trying to get lock for ApplicationContext file:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/TransactionLoggingProxyConfig.xml
2017-10-27 12:14:43,164 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) ApplicationContext for: TransactionLoggingProxyConfig.xml was not null - checking to see if it is stale.
2017-10-27 12:14:43,164 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Releasing lock for ApplicationContextfile:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/TransactionLoggingProxyConfig.xml
2017-10-27 12:14:43,165 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 DEBUG DefaultListableBeanFactory:244 - Returning cached instance of singleton bean 'transactionstoredatabase'
2017-10-27 12:14:43,165 DEBUG [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) TransactionDAO.getTransactinId() - Begin
2017-10-27 12:14:43,165 INFO  [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) -- MessageId Parameter is required for Transaction Query --
2017-10-27 12:14:43,165 DEBUG [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) TransactionDAO.getTransactinId() - End
2017-10-27 12:14:43,165 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Trying to get lock for ApplicationContext file:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/TransactionLoggingProxyConfig.xml
2017-10-27 12:14:43,165 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) ApplicationContext for: TransactionLoggingProxyConfig.xml was not null - checking to see if it is stale.
2017-10-27 12:14:43,165 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Releasing lock for ApplicationContextfile:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/TransactionLoggingProxyConfig.xml
2017-10-27 12:14:43,165 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 DEBUG DefaultListableBeanFactory:244 - Returning cached instance of singleton bean 'transactionstoredatabase'
2017-10-27 12:14:43,165 DEBUG [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) TransactionDAO.getTransactinId() - Begin
2017-10-27 12:14:43,166 INFO  [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) -- MessageId Parameter is required for Transaction Query --
2017-10-27 12:14:43,166 DEBUG [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) TransactionDAO.getTransactinId() - End
2017-10-27 12:14:43,166 DEBUG [gov.hhs.fha.nhinc.persistence.HibernateUtilFactory] (default task-5) Memory address eventHibernateUtil org.springframework.context.support.ClassPathXmlApplicationContext@56e2f983
2017-10-27 12:14:43,166 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:249 - No transaction, no need to enlist: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7987bef5[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110 connection handles=0 lastUse=1509124483164 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@78f9587e mcp=SemaphoreArrayListManagedConnectionPool@20c9ebba[pool=eventdb_pool] xaResource=LocalXAResourceImpl@579e53f3[connectionListener=7987bef5 connectionManager=a5d6a62 warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/eventdb_datasource] txSync=null]
2017-10-27 12:14:43,167 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:267 - [TxConnectionListener@7987bef5] registerConnection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@640ca53f [size=1] ([org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@640ca53f])
2017-10-27 12:14:43,179 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:615 - connectionClosed called mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110
2017-10-27 12:14:43,180 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@7987bef5] isManagedConnectionFree: false
2017-10-27 12:14:43,180 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:326 - [TxConnectionListener@7987bef5] unregisterConnection: 0 handles left ([])
2017-10-27 12:14:43,181 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@7987bef5] isManagedConnectionFree: true
2017-10-27 12:14:43,181 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:394 - delisting org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7987bef5[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110 connection handles=0 lastUse=1509124483164 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@78f9587e mcp=SemaphoreArrayListManagedConnectionPool@20c9ebba[pool=eventdb_pool] xaResource=LocalXAResourceImpl@579e53f3[connectionListener=7987bef5 connectionManager=a5d6a62 warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/eventdb_datasource] txSync=null]
2017-10-27 12:14:43,182 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@7987bef5] isManagedConnectionFree: true
2017-10-27 12:14:43,182 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:501 - delisted org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7987bef5[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110 connection handles=0 lastUse=1509124483164 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@78f9587e mcp=SemaphoreArrayListManagedConnectionPool@20c9ebba[pool=eventdb_pool] xaResource=LocalXAResourceImpl@579e53f3[connectionListener=7987bef5 connectionManager=a5d6a62 warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/eventdb_datasource] txSync=null]
2017-10-27 12:14:43,183 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:639 - isManagedConnectionFree=true mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110
2017-10-27 12:14:43,183 INFO  [gov.hhs.fha.nhinc.event.Log4jEventLogger] (default task-5) BEGIN_OUTBOUND_PROCESSING has triggered. It has messageID null, transactionID null and description {"service_type":"Document Query","payload_types":["AdhocQueryRequest"],"responding_hcids":["urn:oid:2.2"],"action":"","initiating_hcid":"urn:oid:1.1"}
2017-10-27 12:14:43,184 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) Parsing community id: 'D123401^^^&1.1&ISO'
2017-10-27 12:14:43,184 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) stripQuotesFromPatientId - Parsing patient id: 'D123401^^^&1.1&ISO'
2017-10-27 12:14:43,184 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) stripQuotesFromPatientId - Parsed patient id: D123401^^^&1.1&ISO
2017-10-27 12:14:43,184 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) Index: 9
2017-10-27 12:14:43,184 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) Working community id after first components removed: &1.1&ISO
2017-10-27 12:14:43,184 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) Parsing patient id: 'D123401^^^&1.1&ISO'
2017-10-27 12:14:43,184 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) stripQuotesFromPatientId - Parsing patient id: 'D123401^^^&1.1&ISO'
2017-10-27 12:14:43,184 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) stripQuotesFromPatientId - Parsed patient id: D123401^^^&1.1&ISO
2017-10-27 12:14:43,184 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) Index: 7
2017-10-27 12:14:43,184 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) Parsed patient id: D123401
2017-10-27 12:14:43,184 DEBUG [gov.hhs.fha.nhinc.docquery.entity.AggregationService] (default task-5) EntityDocQueryOrchImpl uniquePatientId: D123401 and localAA=1.1
2017-10-27 12:14:43,184 DEBUG [gov.hhs.fha.nhinc.connectmgr.ConnectionManagerCache] (default task-5) Looking up URL by home community id
2017-10-27 12:14:43,185 DEBUG [gov.hhs.fha.nhinc.connectmgr.ConnectionManagerCache] (default task-5) Attempting to find binding template with spec version (3.0).
2017-10-27 12:14:43,185 DEBUG [gov.hhs.fha.nhinc.connectmgr.ConnectionManagerCache] (default task-5) getEndpointURLByServiceName for home community (urn:oid:2.2) and service name (QueryForDocuments) returned endpoint address: https://172.24.32.231:8181/Gateway/DocumentQuery/3_0/NhinService/RespondingGateway_Query_Service/DocQuery
2017-10-27 12:14:43,185 DEBUG [gov.hhs.fha.nhinc.connectmgr.ConnectionManagerCache] (default task-5) end getEndpointURLByServiceName url = https://172.24.32.231:8181/Gateway/DocumentQuery/3_0/NhinService/RespondingGateway_Query_Service/DocQuery
2017-10-27 12:14:43,185 DEBUG [gov.hhs.fha.nhinc.connectmgr.ConnectionManagerCache] (default task-5) Connection Management URL Info List:
2017-10-27 12:14:43,185 DEBUG [gov.hhs.fha.nhinc.connectmgr.ConnectionManagerCache] (default task-5)    HCID: urn:oid:2.2 URL #0: https://172.24.32.231:8181/Gateway/DocumentQuery/3_0/NhinService/RespondingGateway_Query_Service/DocQuery
2017-10-27 12:14:43,185 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Trying to get lock for ApplicationContext file:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/PatientCorrelationConfig.xml
2017-10-27 12:14:43,185 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) ApplicationContext for: PatientCorrelationConfig.xml was not null - checking to see if it is stale.
2017-10-27 12:14:43,185 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Releasing lock for ApplicationContextfile:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/PatientCorrelationConfig.xml
2017-10-27 12:14:43,185 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 DEBUG DefaultListableBeanFactory:244 - Returning cached instance of singleton bean 'patientcorrelationwssecured'
2017-10-27 12:14:43,185 INFO  [gov.hhs.fha.nhinc.common.connectionmanager.dao.AssigningAuthorityHomeCommunityMappingDAO] (default task-5) converting homeCommunityIds [count=1] to assigning authorities
2017-10-27 12:14:43,185 DEBUG [gov.hhs.fha.nhinc.persistence.HibernateUtilFactory] (default task-5) Memory address getConnManHibernateUtil org.springframework.context.support.ClassPathXmlApplicationContext@56e2f983
2017-10-27 12:14:43,187 ERROR [stderr] (default task-5) Fri Oct 27 12:14:43 CDT 2017 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.
2017-10-27 12:14:43,192 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:249 - No transaction, no need to enlist: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@27fafcb[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@26b705c6 connection handles=0 lastUse=1509124483191 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@7f5fd54c mcp=SemaphoreArrayListManagedConnectionPool@730b011[pool=assigningauthoritydb_pool] xaResource=LocalXAResourceImpl@4e0a53c2[connectionListener=27fafcb connectionManager=1693094d warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/assigningauthoritydb_datasource] txSync=null]
2017-10-27 12:14:43,192 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:267 - [TxConnectionListener@27fafcb] registerConnection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@42c8cdd8 [size=1] ([org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@42c8cdd8])
2017-10-27 12:14:43,193 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:615 - connectionClosed called mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@26b705c6
2017-10-27 12:14:43,194 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@27fafcb] isManagedConnectionFree: false
2017-10-27 12:14:43,194 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:326 - [TxConnectionListener@27fafcb] unregisterConnection: 0 handles left ([])
2017-10-27 12:14:43,195 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@27fafcb] isManagedConnectionFree: true
2017-10-27 12:14:43,202 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:394 - delisting org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@27fafcb[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@26b705c6 connection handles=0 lastUse=1509124483191 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@7f5fd54c mcp=SemaphoreArrayListManagedConnectionPool@730b011[pool=assigningauthoritydb_pool] xaResource=LocalXAResourceImpl@4e0a53c2[connectionListener=27fafcb connectionManager=1693094d warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/assigningauthoritydb_datasource] txSync=null]
2017-10-27 12:14:43,203 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@27fafcb] isManagedConnectionFree: true
2017-10-27 12:14:43,203 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:501 - delisted org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@27fafcb[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@26b705c6 connection handles=0 lastUse=1509124483191 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@7f5fd54c mcp=SemaphoreArrayListManagedConnectionPool@730b011[pool=assigningauthoritydb_pool] xaResource=LocalXAResourceImpl@4e0a53c2[connectionListener=27fafcb connectionManager=1693094d warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/assigningauthoritydb_datasource] txSync=null]
2017-10-27 12:14:43,203 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:639 - isManagedConnectionFree=true mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@26b705c6
2017-10-27 12:14:43,204 INFO  [gov.hhs.fha.nhinc.common.connectionmanager.dao.AssigningAuthorityHomeCommunityMappingDAO] (default task-5) converted homeCommunityIds [count=1] to assigning authorities [count=0]
2017-10-27 12:14:43,204 DEBUG [gov.hhs.fha.nhinc.patientcorrelation.nhinc.proxy.PatientCorrelationProxyWebServiceSecuredImpl] (default task-5) Begin retrievePatientCorrelations
2017-10-27 12:14:43,204 DEBUG [gov.hhs.fha.nhinc.connectmgr.ConnectionManagerCache] (default task-5) Attempting to find binding template with spec version (2.0).
2017-10-27 12:14:43,204 DEBUG [gov.hhs.fha.nhinc.connectmgr.ConnectionManagerCache] (default task-5) getEndpointURLByServiceName for home community (urn:oid:1.1) and service name (patientcorrelationsecured) returned endpoint address: https://172.24.32.231:8181/CONNECTGateway/GatewayService/PatientCorrelationServiceSecured
2017-10-27 12:14:43,204 DEBUG [gov.hhs.fha.nhinc.connectmgr.ConnectionManagerCache] (default task-5) end getEndpointURLByServiceName url = https://172.24.32.231:8181/CONNECTGateway/GatewayService/PatientCorrelationServiceSecured
2017-10-27 12:14:43,206 DEBUG [gov.hhs.fha.nhinc.webserviceproxy.WebServiceProxyHelper] (default task-5) Begin invokePort
2017-10-27 12:14:43,206 DEBUG [gov.hhs.fha.nhinc.webserviceproxy.WebServiceProxyHelper] (default task-5) Invoking gov.hhs.fha.nhinc.nhinccomponentpatientcorrelation.PatientCorrelationSecuredPortType.retrievePatientCorrelations: Try #1
2017-10-27 12:14:43,206 DEBUG [gov.hhs.fha.nhinc.webserviceproxy.WebServiceProxyHelper] (default task-5) with parameters: org.hl7.v3.RetrievePatientCorrelationsSecuredRequestType
2017-10-27 12:14:43,218 DEBUG [gov.hhs.fha.nhinc.saml.extraction.SamlTokenCreator] (default task-5) Entering SamlTokenCreator.CreateRequestContext...
2017-10-27 12:14:43,218 DEBUG [gov.hhs.fha.nhinc.saml.extraction.SamlTokenCreator] (default task-5) samlSendOperation input assertion Saml Issuer is null
2017-10-27 12:14:43,218 DEBUG [gov.hhs.fha.nhinc.saml.extraction.SamlTokenCreator] (default task-5) Exiting SamlTokenCreator.CreateRequestContext...
2017-10-27 12:14:43,218 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.HOKSAMLAssertionBuilder] (default task-5) SamlCallbackHandler.createHOKSAMLAssertion20() -- Begin
2017-10-27 12:14:43,219 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.HOKSAMLAssertionBuilder] (default task-5) Assertion ID: _74fb20fc41ce48cd8f868985b40ea3ec
2017-10-27 12:14:43,219 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.HOKSAMLAssertionBuilder] (default task-5) Assertion issuer not defined: Using default issuer
2017-10-27 12:14:43,219 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.CertificateManagerImpl] (default task-5) SamlCallbackHandler.getDefaultPrivKeyCert() -- Begin
2017-10-27 12:14:43,219 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.CertificateManagerImpl] (default task-5) SamlCallbackHandler.getDefaultPrivKeyCert() -- End
2017-10-27 12:14:43,219 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.CertificateManagerImpl] (default task-5) SamlCallbackHandler.getDefaultPrivKeyCert() -- Begin
2017-10-27 12:14:43,219 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.CertificateManagerImpl] (default task-5) SamlCallbackHandler.getDefaultPrivKeyCert() -- End
2017-10-27 12:14:43,219 WARN  [gov.hhs.fha.nhinc.callback.openSAML.HOKSAMLAssertionBuilder] (default task-5) Not a Valid Distinguished Name, setting the value from Certificate: Invalid name: kskagerberg
2017-10-27 12:14:43,220 WARN  [gov.hhs.fha.nhinc.callback.openSAML.HOKSAMLAssertionBuilder] (default task-5) Not a Valid Distinguished Name, setting the value from Certificate: Invalid name: kskagerberg
2017-10-27 12:14:43,221 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.HOKSAMLAssertionBuilder] (default task-5) Setting Authentication session index to: 987
2017-10-27 12:14:43,221 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.HOKSAMLAssertionBuilder] (default task-5) UserName: Karl S Skagerberg
2017-10-27 12:14:43,221 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.HOKSAMLAssertionBuilder] (default task-5) SamlCallbackHandler.addAssertStatements() -- Begin
2017-10-27 12:14:43,222 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.HOKSAMLAssertionBuilder] (default task-5) SamlCallbackHandler.addAssertStatements() -- End
2017-10-27 12:14:43,222 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.HOKSAMLAssertionBuilder] (default task-5) SamlCallbackHandler.createOrganizationIdAttributeStatements() -- Begin
2017-10-27 12:14:43,222 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.HOKSAMLAssertionBuilder] (default task-5) SamlCallbackHandler.addAssertStatements() -- Begin
2017-10-27 12:14:43,222 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.HOKSAMLAssertionBuilder] (default task-5) patient id is missing
2017-10-27 12:14:43,223 WARN  [gov.hhs.fha.nhinc.callback.PurposeOfForDecider] (default task-5) Could not read purpose of / for action: No enum constant null
2017-10-27 12:14:43,223 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.HOKSAMLAssertionBuilder] (default task-5) npi is missing
2017-10-27 12:14:43,223 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.HOKSAMLAssertionBuilder] (default task-5) SamlCallbackHandler.createEvidence() -- Begin
2017-10-27 12:14:43,223 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.HOKSAMLAssertionBuilder] (default task-5) SamlCallbackHandler.createEvidenceStatements() -- Begin
2017-10-27 12:14:43,224 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.HOKSAMLAssertionBuilder] (default task-5) SamlCallbackHandler.createEvidenceStatements() -- End
2017-10-27 12:14:43,224 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.HOKSAMLAssertionBuilder] (default task-5) SamlCallbackHandler.createEvidence() -- End
2017-10-27 12:14:43,224 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.CertificateManagerImpl] (default task-5) SamlCallbackHandler.getDefaultPrivKeyCert() -- Begin
2017-10-27 12:14:43,224 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.CertificateManagerImpl] (default task-5) SamlCallbackHandler.getDefaultPrivKeyCert() -- End
2017-10-27 12:14:43,230 DEBUG [gov.hhs.fha.nhinc.callback.openSAML.HOKSAMLAssertionBuilder] (default task-5) SamlCallbackHandler.createHOKSAMLAssertion20() -- End
2017-10-27 12:14:43,275 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE DefaultListableBeanFactory:527 - No bean named '' found in org.springframework.beans.factory.support.DefaultListableBeanFactory@6f859a32: defining beans [cxf,org.apache.cxf.bus.spring.BusWiringBeanFactoryPostProcessor,org.apache.cxf.bus.spring.Jsr250BeanPostProcessor,org.apache.cxf.bus.spring.BusExtensionPostProcessor,securityConfigInInterceptor,timestampInInterceptor,attachmentFaultOutInterceptor,org.springframework.beans.factory.config.PropertyPlaceholderConfigurer#0,cxf.config11,AuditRepositoryManagerUnsecured,AuditRepositoryManagerSecured,AuditQueryLogUnsecured,PatientCorrelationUnsecured,PatientCorrelationSecured,SOAPHeaderHandler,TransactionHandler]; root of factory hierarchy
2017-10-27 12:14:43,297 DEBUG [gov.hhs.fha.nhinc.cxf.extraction.SAML2AssertionExtractor] (default task-6) Executing Saml2AssertionExtractor.extractSamlAssertion()...
2017-10-27 12:14:43,297 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) Executing Saml2AssertionExtractor.extractSamlAssertion()...
2017-10-27 12:14:43,300 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) Initializing Assertion to Default: 
2017-10-27 12:14:43,300 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) Executing Saml2AssertionExtractor.populateSubject()...
2017-10-27 12:14:43,300 WARN  [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) Subject name format is not X509!
2017-10-27 12:14:43,300 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) end populateSubject()
2017-10-27 12:14:43,300 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) Executing Saml2AssertionExtractor.populateAuthenticationStatement()...
2017-10-27 12:14:43,301 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) end populateAuthenticationStatement()
2017-10-27 12:14:43,301 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) Executing Saml2AssertionExtractor.populateAttributeStatement()...
2017-10-27 12:14:43,301 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.AttributeHelper] (default task-6) Entering AttributeHelper.extractNameParts...
2017-10-27 12:14:43,301 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.AttributeHelper] (default task-6) AttributeHelper.extractNameParts() -- End
2017-10-27 12:14:43,301 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) Assertion.userInfo.org.Name = InternalTest1
2017-10-27 12:14:43,301 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) Assertion.userInfo.org.homeCommunityId = urn:oid:1.1
2017-10-27 12:14:43,301 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) Assertion.homeCommunity.homeCommunityId = urn:oid:1.1
2017-10-27 12:14:43,301 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) Extracting Assertion.userInfo.roleCoded:
2017-10-27 12:14:43,301 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) Executing Saml2AssertionExtractor.populateSubjectRole...
2017-10-27 12:14:43,301 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) end populateSubjectRole()
2017-10-27 12:14:43,301 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) Extracting Assertion.purposeOfDisclosure:
2017-10-27 12:14:43,301 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) Executing Saml2AssertionExtractor.populatePurposeOfUseAttribute...
2017-10-27 12:14:43,301 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) end populatePurposeOfUseAttribute()
2017-10-27 12:14:43,301 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) end populateAttributeStatement()
2017-10-27 12:14:43,301 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) Executing Saml2AssertionExtractor.populateAuthzDecisionStatement()...
2017-10-27 12:14:43,301 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) end populateAuthzDecisionStatement()
2017-10-27 12:14:43,303 DEBUG [gov.hhs.fha.nhinc.openSAML.extraction.OpenSAMLAssertionExtractorImpl] (default task-6) end extractSamlAssertion()
2017-10-27 12:14:43,303 INFO  [gov.hhs.fha.nhinc.patientcorrelation.nhinc.PatientCorrelationServiceSecuredServiceImpl] (default task-6) Calling the Patient Correlation Retrieve Correlations Orch Impl
2017-10-27 12:14:43,303 DEBUG [gov.hhs.fha.nhinc.patientcorrelation.nhinc.parsers.PRPAIN201309UV.PRPAIN201309UVParser] (default task-6) ---- Begin PRPAIN201309UVParser.parseHL7PatientPersonFrom201309Message()----
2017-10-27 12:14:43,303 DEBUG [gov.hhs.fha.nhinc.patientcorrelation.nhinc.parsers.PRPAIN201309UV.PRPAIN201309UVParser] (default task-6) ---- End PRPAIN201309UVParser.parseHL7PatientPersonFrom201309Message()----
2017-10-27 12:14:43,303 DEBUG [gov.hhs.fha.nhinc.patientcorrelation.nhinc.dao.Retriever] (default task-6) -- Begin CorrelatedIdentifiersDao.retrieveAllPatientCorrelation() ---
2017-10-27 12:14:43,303 DEBUG [gov.hhs.fha.nhinc.persistence.HibernateUtilFactory] (default task-6) Memory address getPatientCorrHibernateUtil org.springframework.context.support.ClassPathXmlApplicationContext@56e2f983
2017-10-27 12:14:43,303 DEBUG [gov.hhs.fha.nhinc.patientcorrelation.nhinc.dao.Retriever] (default task-6) Retrieving by patientAssigningAuthorityId=1.1
2017-10-27 12:14:43,303 DEBUG [gov.hhs.fha.nhinc.patientcorrelation.nhinc.dao.Retriever] (default task-6) Retrieving by patientId=D123401
2017-10-27 12:14:43,305 ERROR [stderr] (default task-6) Fri Oct 27 12:14:43 CDT 2017 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.
2017-10-27 12:14:43,311 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:249 - No transaction, no need to enlist: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@1409b2de[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@5dfc804f connection handles=0 lastUse=1509124483311 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@47d53a6c mcp=SemaphoreArrayListManagedConnectionPool@3a15f0cd[pool=patientcorrelationdb_pool] xaResource=LocalXAResourceImpl@61778546[connectionListener=1409b2de connectionManager=13819fec warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/patientcorrelationdb_datasource] txSync=null]
2017-10-27 12:14:43,312 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:267 - [TxConnectionListener@1409b2de] registerConnection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@3d52040c [size=1] ([org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@3d52040c])
2017-10-27 12:14:43,314 DEBUG [gov.hhs.fha.nhinc.patientcorrelation.nhinc.dao.Retriever] (default task-6) patient correlation record has not expired
2017-10-27 12:14:43,314 DEBUG [gov.hhs.fha.nhinc.patientcorrelation.nhinc.dao.Retriever] (default task-6) Found 1 record(s)
2017-10-27 12:14:43,314 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:615 - connectionClosed called mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@5dfc804f
2017-10-27 12:14:43,315 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@1409b2de] isManagedConnectionFree: false
2017-10-27 12:14:43,315 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:326 - [TxConnectionListener@1409b2de] unregisterConnection: 0 handles left ([])
2017-10-27 12:14:43,316 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@1409b2de] isManagedConnectionFree: true
2017-10-27 12:14:43,316 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:394 - delisting org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@1409b2de[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@5dfc804f connection handles=0 lastUse=1509124483311 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@47d53a6c mcp=SemaphoreArrayListManagedConnectionPool@3a15f0cd[pool=patientcorrelationdb_pool] xaResource=LocalXAResourceImpl@61778546[connectionListener=1409b2de connectionManager=13819fec warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/patientcorrelationdb_datasource] txSync=null]
2017-10-27 12:14:43,317 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@1409b2de] isManagedConnectionFree: true
2017-10-27 12:14:43,317 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:501 - delisted org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@1409b2de[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@5dfc804f connection handles=0 lastUse=1509124483311 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@47d53a6c mcp=SemaphoreArrayListManagedConnectionPool@3a15f0cd[pool=patientcorrelationdb_pool] xaResource=LocalXAResourceImpl@61778546[connectionListener=1409b2de connectionManager=13819fec warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/patientcorrelationdb_datasource] txSync=null]
2017-10-27 12:14:43,318 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:639 - isManagedConnectionFree=true mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@5dfc804f
2017-10-27 12:14:43,319 DEBUG [gov.hhs.fha.nhinc.persistence.HibernateUtilFactory] (default task-6) Memory address getPatientCorrHibernateUtil org.springframework.context.support.ClassPathXmlApplicationContext@56e2f983
2017-10-27 12:14:43,319 DEBUG [gov.hhs.fha.nhinc.patientcorrelation.nhinc.dao.Retriever] (default task-6) Retrieving by correlatedPatientAssigningAuthorityId=1.1
2017-10-27 12:14:43,319 DEBUG [gov.hhs.fha.nhinc.patientcorrelation.nhinc.dao.Retriever] (default task-6) Retrieving by correlatedPatientId=D123401
2017-10-27 12:14:43,319 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:249 - No transaction, no need to enlist: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@1409b2de[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@5dfc804f connection handles=0 lastUse=1509124483319 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@47d53a6c mcp=SemaphoreArrayListManagedConnectionPool@3a15f0cd[pool=patientcorrelationdb_pool] xaResource=LocalXAResourceImpl@61778546[connectionListener=1409b2de connectionManager=13819fec warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/patientcorrelationdb_datasource] txSync=null]
2017-10-27 12:14:43,320 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:267 - [TxConnectionListener@1409b2de] registerConnection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@2c9b9d67 [size=1] ([org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@2c9b9d67])
2017-10-27 12:14:43,322 DEBUG [gov.hhs.fha.nhinc.patientcorrelation.nhinc.dao.Retriever] (default task-6) Found 0 record(s)
2017-10-27 12:14:43,322 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:615 - connectionClosed called mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@5dfc804f
2017-10-27 12:14:43,323 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@1409b2de] isManagedConnectionFree: false
2017-10-27 12:14:43,323 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:326 - [TxConnectionListener@1409b2de] unregisterConnection: 0 handles left ([])
2017-10-27 12:14:43,324 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@1409b2de] isManagedConnectionFree: true
2017-10-27 12:14:43,326 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:394 - delisting org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@1409b2de[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@5dfc804f connection handles=0 lastUse=1509124483319 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@47d53a6c mcp=SemaphoreArrayListManagedConnectionPool@3a15f0cd[pool=patientcorrelationdb_pool] xaResource=LocalXAResourceImpl@61778546[connectionListener=1409b2de connectionManager=13819fec warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/patientcorrelationdb_datasource] txSync=null]
2017-10-27 12:14:43,326 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@1409b2de] isManagedConnectionFree: true
2017-10-27 12:14:43,327 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:501 - delisted org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@1409b2de[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@5dfc804f connection handles=0 lastUse=1509124483319 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@47d53a6c mcp=SemaphoreArrayListManagedConnectionPool@3a15f0cd[pool=patientcorrelationdb_pool] xaResource=LocalXAResourceImpl@61778546[connectionListener=1409b2de connectionManager=13819fec warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/patientcorrelationdb_datasource] txSync=null]
2017-10-27 12:14:43,327 INFO  [stdout] (default task-6) 2017-10-27 12:14:43 TRACE TxConnectionListener:639 - isManagedConnectionFree=true mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@5dfc804f
2017-10-27 12:14:43,327 DEBUG [gov.hhs.fha.nhinc.patientcorrelation.nhinc.dao.Retriever] (default task-6) Checking Expirations
2017-10-27 12:14:43,327 INFO  [gov.hhs.fha.nhinc.patientcorrelation.nhinc.dao.Retriever] (default task-6) resultQualifiedPatientIdentifiers=1 record(s)
2017-10-27 12:14:43,327 DEBUG [gov.hhs.fha.nhinc.patientcorrelation.nhinc.dao.Retriever] (default task-6) -- End CorrelatedIdentifiersDao.retrieveAllPatientCorrelation() ---
2017-10-27 12:14:43,327 INFO  [gov.hhs.fha.nhinc.patientcorrelation.nhinc.dao.Retriever] (default task-6) unfiltered list = 1 record(s)
2017-10-27 12:14:43,328 INFO  [gov.hhs.fha.nhinc.patientcorrelation.nhinc.dao.Retriever] (default task-6) filtered list = 1 record(s)
2017-10-27 12:14:43,340 INFO  [io.undertow.request.dump] (default task-6) 
----------------------------REQUEST---------------------------
               URI=/CONNECTGateway/GatewayService/PatientCorrelationServiceSecured
 characterEncoding=null
     contentLength=-1
       contentType=[application/soap+xml; charset=UTF-8]
            header=Accept=*/*
            header=Connection=keep-alive
            header=Cache-Control=no-cache
            header=Pragma=no-cache
            header=Transfer-Encoding=chunked
            header=Content-Type=application/soap+xml; charset=UTF-8
            header=User-Agent=Apache CXF 2.7.3
            header=Host=172.24.32.231:8181
            locale=[]
            method=POST
          protocol=HTTP/1.1
       queryString=
        remoteAddr=/172.24.32.231:42672
        remoteHost=172.24.32.231
            scheme=https
              host=172.24.32.231:8181
        serverPort=8181
--------------------------RESPONSE--------------------------
     contentLength=3228
       contentType=application/soap+xml;charset=UTF-8
            header=Connection=keep-alive
            header=X-Powered-By=Undertow/1
            header=Server=WildFly/8
            header=Content-Type=application/soap+xml;charset=UTF-8
            header=Content-Length=3228
            header=Date=Fri, 27 Oct 2017 17:14:43 GMT
            status=200
==============================================================
2017-10-27 12:14:43,347 DEBUG [gov.hhs.fha.nhinc.webserviceproxy.WebServiceProxyHelper] (default task-5) End invokePort
2017-10-27 12:14:43,347 DEBUG [gov.hhs.fha.nhinc.patientcorrelation.nhinc.proxy.PatientCorrelationProxyWebServiceSecuredImpl] (default task-5) End retrievePatientCorrelations
2017-10-27 12:14:43,347 DEBUG [gov.hhs.fha.nhinc.common.connectionmanager.dao.AssigningAuthorityHomeCommunityMappingDAO] (default task-5) --Begin AssigningAuthorityHomeCommunityMappingDAO.getAllCommunityIdsForAllAssigningAuthorities() ---
2017-10-27 12:14:43,347 DEBUG [gov.hhs.fha.nhinc.persistence.HibernateUtilFactory] (default task-5) Memory address getConnManHibernateUtil org.springframework.context.support.ClassPathXmlApplicationContext@56e2f983
2017-10-27 12:14:43,348 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:249 - No transaction, no need to enlist: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@27fafcb[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@26b705c6 connection handles=0 lastUse=1509124483203 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@7f5fd54c mcp=SemaphoreArrayListManagedConnectionPool@730b011[pool=assigningauthoritydb_pool] xaResource=LocalXAResourceImpl@4e0a53c2[connectionListener=27fafcb connectionManager=1693094d warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/assigningauthoritydb_datasource] txSync=null]
2017-10-27 12:14:43,348 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:267 - [TxConnectionListener@27fafcb] registerConnection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@29b84ff9 [size=1] ([org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@29b84ff9])
2017-10-27 12:14:43,349 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:615 - connectionClosed called mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@26b705c6
2017-10-27 12:14:43,350 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@27fafcb] isManagedConnectionFree: false
2017-10-27 12:14:43,350 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:326 - [TxConnectionListener@27fafcb] unregisterConnection: 0 handles left ([])
2017-10-27 12:14:43,350 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@27fafcb] isManagedConnectionFree: true
2017-10-27 12:14:43,351 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:394 - delisting org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@27fafcb[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@26b705c6 connection handles=0 lastUse=1509124483203 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@7f5fd54c mcp=SemaphoreArrayListManagedConnectionPool@730b011[pool=assigningauthoritydb_pool] xaResource=LocalXAResourceImpl@4e0a53c2[connectionListener=27fafcb connectionManager=1693094d warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/assigningauthoritydb_datasource] txSync=null]
2017-10-27 12:14:43,351 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@27fafcb] isManagedConnectionFree: true
2017-10-27 12:14:43,354 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:501 - delisted org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@27fafcb[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@26b705c6 connection handles=0 lastUse=1509124483203 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@7f5fd54c mcp=SemaphoreArrayListManagedConnectionPool@730b011[pool=assigningauthoritydb_pool] xaResource=LocalXAResourceImpl@4e0a53c2[connectionListener=27fafcb connectionManager=1693094d warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/assigningauthoritydb_datasource] txSync=null]
2017-10-27 12:14:43,355 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:639 - isManagedConnectionFree=true mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@26b705c6
2017-10-27 12:14:43,355 DEBUG [gov.hhs.fha.nhinc.common.connectionmanager.dao.AssigningAuthorityHomeCommunityMappingDAO] (default task-5) --End AssigningAuthorityHomeCommunityMappingDAO.getAllCommunityIdsForAllAssigningAuthorities() ---
2017-10-27 12:14:43,355 DEBUG [gov.hhs.fha.nhinc.transform.marshallers.JAXBContextHandler] (default task-5) Reusing JAXB Context for 'oasis.names.tc.ebxml_regrep.xsd.query._3'.
2017-10-27 12:14:43,359 DEBUG [gov.hhs.fha.nhinc.transform.marshallers.Marshaller] (default task-5) begin unmarshal
2017-10-27 12:14:43,359 DEBUG [gov.hhs.fha.nhinc.transform.marshallers.Marshaller] (default task-5) desializing element
2017-10-27 12:14:43,361 DEBUG [gov.hhs.fha.nhinc.transform.marshallers.Marshaller] (default task-5) serializedElement=[<?xml version="1.0" encoding="UTF-8"?><ns3:AdhocQueryRequest xmlns:ns3="urn:oasis:names:tc:ebxml-regrep:xsd:query:3.0" xmlns="urn:oasis:names:tc:ebxml-regrep:xsd:rim:3.0" xmlns:ns2="urn:oasis:names:tc:ebxml-regrep:xsd:rs:3.0" xmlns:ns4="urn:oasis:names:tc:ebxml-regrep:xsd:lcm:3.0" federated="false" maxResults="-1" startIndex="0"><ns3:ResponseOption returnComposedObjects="false" returnType="LeafClass"/><AdhocQuery home="urn:oid:1.1" id="urn:uuid:14d4debf-8f97-4251-9a74-a90016b0af0d"><Slot name="$XDSDocumentEntryPatientId"><ValueList><Value>'D123401^^^&amp;1.1&amp;ISO'</Value></ValueList></Slot><Slot name="$XDSDocumentEntryStatus"><ValueList><Value>('urn:oasis:names:tc:ebxml-regrep:StatusType:Approved')</Value></ValueList></Slot><Slot name="$XDSDocumentEntryClassCode"><ValueList><Value>34133-9</Value></ValueList></Slot><Slot name="$XDSDocumentEntryClassCodeScheme"><ValueList><Value>2.16.840.1.113883.6.1</Value></ValueList></Slot></AdhocQuery></ns3:AdhocQueryRequest>]
2017-10-27 12:14:43,361 DEBUG [gov.hhs.fha.nhinc.transform.marshallers.Marshaller] (default task-5) get instance of JAXBContext [contextPath='oasis.names.tc.ebxml_regrep.xsd.query._3']
2017-10-27 12:14:43,361 DEBUG [gov.hhs.fha.nhinc.transform.marshallers.JAXBContextHandler] (default task-5) Reusing JAXB Context for 'oasis.names.tc.ebxml_regrep.xsd.query._3'.
2017-10-27 12:14:43,361 DEBUG [gov.hhs.fha.nhinc.transform.marshallers.Marshaller] (default task-5) get instance of unmarshaller
2017-10-27 12:14:43,361 DEBUG [gov.hhs.fha.nhinc.transform.marshallers.Marshaller] (default task-5) Calling unmarshal
2017-10-27 12:14:43,362 DEBUG [gov.hhs.fha.nhinc.transform.marshallers.Marshaller] (default task-5) end unmarshal
2017-10-27 12:14:43,362 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) Creating HL7 encoded patient id for patient id: D123401, home community id: 2.2
2017-10-27 12:14:43,362 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) HL7 encoded patient id: 'D123401^^^&2.2&ISO'
2017-10-27 12:14:43,362 DEBUG [gov.hhs.fha.nhinc.transform.marshallers.JAXBContextHandler] (default task-5) Reusing JAXB Context for 'gov.hhs.fha.nhinc.common.nhinccommon'.
2017-10-27 12:14:43,363 DEBUG [gov.hhs.fha.nhinc.transform.marshallers.Marshaller] (default task-5) begin unmarshal
2017-10-27 12:14:43,363 DEBUG [gov.hhs.fha.nhinc.transform.marshallers.Marshaller] (default task-5) desializing element
2017-10-27 12:14:43,364 DEBUG [gov.hhs.fha.nhinc.transform.marshallers.Marshaller] (default task-5) serializedElement=[<?xml version="1.0" encoding="UTF-8"?><Assertion xmlns="urn:gov:hhs:fha:nhinc:common:nhinccommon" xmlns:ns2="http://www.w3.org/2005/08/addressing"><haveSecondWitnessSignature>false</haveSecondWitnessSignature><haveSignature>false</haveSignature><haveWitnessSignature>false</haveWitnessSignature><homeCommunity><description>InternalTest1</description><homeCommunityId>urn:oid:1.1</homeCommunityId><name>InternalTest1</name></homeCommunity><userInfo><personName><familyName>Skagerberg</familyName><givenName>Karl</givenName><nameType><code>nameCode</code><codeSystem>nameCodeSyst</codeSystem><codeSystemName>nameCodeSystName</codeSystemName><codeSystemVersion>1.0</codeSystemVersion><displayName>nameCode</displayName><originalText>nameCode</originalText></nameType><secondNameOrInitials>S</secondNameOrInitials><fullName>Kasrl S. Skagerberg</fullName></personName><userName>kskagerberg</userName><org><description>InternalTest1</description><homeCommunityId>urn:oid:1.1</homeCommunityId><name>InternalTest1</name></org><roleCoded><code>307969004</code><codeSystemVersion>1.0</codeSystemVersion><displayName>Public Health</displayName><originalText>Public Health</originalText></roleCoded></userInfo><authorized>true</authorized><purposeOfDisclosureCoded><code>PUBLICHEALTH</code><codeSystemVersion>1.0</codeSystemVersion><displayName>Use or disclosure of Psychotherapy Notes</displayName><originalText>Use or disclosure of Psychotherapy Notes</originalText></purposeOfDisclosureCoded><samlAuthnStatement><authInstant>2009-04-16T13:15:39Z</authInstant><sessionIndex>987</sessionIndex><authContextClassRef>urn:oasis:names:tc:SAML:2.0:ac:classes:X509</authContextClassRef><subjectLocalityAddress>1.1.1.1</subjectLocalityAddress><subjectLocalityDNSName>connectopensource.org</subjectLocalityDNSName></samlAuthnStatement><samlAuthzDecisionStatement><decision>Permit</decision><resource>https://1.1.1.1:8181/SamlReceiveService/SamlProcessWS</resource><action>TestSaml</action><evidence><assertion><id>40df7c0a-ff3e-4b26-baeb-f2910f6d05a9</id><issueInstant>2009-04-16T13:10:39.093Z</issueInstant><version>2.0</version><issuer>CN=SAML User,OU=connect,O=FHA,L=Melbourne,ST=FL,C=US</issuer><issuerFormat>urn:oasis:names:tc:SAML:1.1:nameid-format:X509SubjectName</issuerFormat><conditions><notBefore>2009-04-16T13:10:39.093Z</notBefore><notOnOrAfter>2009-12-31T12:00:00.000Z</notOnOrAfter></conditions><accessConsentPolicy>urn:oid:1.2.3.4</accessConsentPolicy><instanceAccessConsentPolicy>urn:oid:1.2.3.4.123456789</instanceAccessConsentPolicy></assertion></evidence></samlAuthzDecisionStatement><messageId>urn:uuid:80b6d2e8-b932-4b4a-8259-e8d94ae62628</messageId></Assertion>]
2017-10-27 12:14:43,364 DEBUG [gov.hhs.fha.nhinc.transform.marshallers.Marshaller] (default task-5) get instance of JAXBContext [contextPath='gov.hhs.fha.nhinc.common.nhinccommon']
2017-10-27 12:14:43,364 DEBUG [gov.hhs.fha.nhinc.transform.marshallers.JAXBContextHandler] (default task-5) Reusing JAXB Context for 'gov.hhs.fha.nhinc.common.nhinccommon'.
2017-10-27 12:14:43,364 DEBUG [gov.hhs.fha.nhinc.transform.marshallers.Marshaller] (default task-5) get instance of unmarshaller
2017-10-27 12:14:43,364 DEBUG [gov.hhs.fha.nhinc.transform.marshallers.Marshaller] (default task-5) Calling unmarshal
2017-10-27 12:14:43,365 DEBUG [gov.hhs.fha.nhinc.transform.marshallers.Marshaller] (default task-5) end unmarshal
2017-10-27 12:14:43,365 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Trying to get lock for ApplicationContext file:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/TransactionLoggingProxyConfig.xml
2017-10-27 12:14:43,365 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) ApplicationContext for: TransactionLoggingProxyConfig.xml was not null - checking to see if it is stale.
2017-10-27 12:14:43,365 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Releasing lock for ApplicationContextfile:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/TransactionLoggingProxyConfig.xml
2017-10-27 12:14:43,365 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 DEBUG DefaultListableBeanFactory:244 - Returning cached instance of singleton bean 'transactionstoredatabase'
2017-10-27 12:14:43,365 DEBUG [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) TransactionDAO.getTransactinId() - Begin
2017-10-27 12:14:43,366 DEBUG [gov.hhs.fha.nhinc.persistence.HibernateUtilFactory] (default task-5) Memory address transactionHibernateUtil org.springframework.context.support.ClassPathXmlApplicationContext@56e2f983
2017-10-27 12:14:43,370 INFO  [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) Getting Records
2017-10-27 12:14:43,374 ERROR [stderr] (default task-5) Fri Oct 27 12:14:43 CDT 2017 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.
2017-10-27 12:14:43,376 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:249 - No transaction, no need to enlist: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@15cd9e16[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@62194ba0 connection handles=0 lastUse=1509124483376 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@5340fa68 mcp=SemaphoreArrayListManagedConnectionPool@10b6a2a6[pool=transrepo_pool] xaResource=LocalXAResourceImpl@235c7218[connectionListener=15cd9e16 connectionManager=3a68a783 warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/transrepo_datasource] txSync=null]
2017-10-27 12:14:43,377 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:267 - [TxConnectionListener@15cd9e16] registerConnection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@2f504ac8 [size=1] ([org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@2f504ac8])
2017-10-27 12:14:43,378 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:615 - connectionClosed called mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@62194ba0
2017-10-27 12:14:43,378 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@15cd9e16] isManagedConnectionFree: false
2017-10-27 12:14:43,379 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:326 - [TxConnectionListener@15cd9e16] unregisterConnection: 0 handles left ([])
2017-10-27 12:14:43,379 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@15cd9e16] isManagedConnectionFree: true
2017-10-27 12:14:43,379 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:394 - delisting org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@15cd9e16[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@62194ba0 connection handles=0 lastUse=1509124483376 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@5340fa68 mcp=SemaphoreArrayListManagedConnectionPool@10b6a2a6[pool=transrepo_pool] xaResource=LocalXAResourceImpl@235c7218[connectionListener=15cd9e16 connectionManager=3a68a783 warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/transrepo_datasource] txSync=null]
2017-10-27 12:14:43,380 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@15cd9e16] isManagedConnectionFree: true
2017-10-27 12:14:43,380 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:501 - delisted org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@15cd9e16[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@62194ba0 connection handles=0 lastUse=1509124483376 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@5340fa68 mcp=SemaphoreArrayListManagedConnectionPool@10b6a2a6[pool=transrepo_pool] xaResource=LocalXAResourceImpl@235c7218[connectionListener=15cd9e16 connectionManager=3a68a783 warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/transrepo_datasource] txSync=null]
2017-10-27 12:14:43,380 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:639 - isManagedConnectionFree=true mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@62194ba0
2017-10-27 12:14:43,381 INFO  [gov.hhs.fha.nhinc.logging.transaction.TransactionLogger] (default task-5) pass in transaction-id is null for message id: urn:uuid:80b6d2e8-b932-4b4a-8259-e8d94ae62628
2017-10-27 12:14:43,381 DEBUG [gov.hhs.fha.nhinc.transform.policy.AdhocQueryTransformHelper] (default task-5) begin transformAdhocQueryToCheckPolicy
2017-10-27 12:14:43,381 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) Parsing community id: 'D123401^^^&2.2&ISO'
2017-10-27 12:14:43,381 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) stripQuotesFromPatientId - Parsing patient id: 'D123401^^^&2.2&ISO'
2017-10-27 12:14:43,381 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) stripQuotesFromPatientId - Parsed patient id: D123401^^^&2.2&ISO
2017-10-27 12:14:43,381 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) Index: 9
2017-10-27 12:14:43,381 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) Working community id after first components removed: &2.2&ISO
2017-10-27 12:14:43,381 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) Parsing patient id: 'D123401^^^&2.2&ISO'
2017-10-27 12:14:43,381 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) stripQuotesFromPatientId - Parsing patient id: 'D123401^^^&2.2&ISO'
2017-10-27 12:14:43,381 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) stripQuotesFromPatientId - Parsed patient id: D123401^^^&2.2&ISO
2017-10-27 12:14:43,381 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) Index: 7
2017-10-27 12:14:43,381 DEBUG [gov.hhs.fha.nhinc.util.format.PatientIdFormatUtil] (default task-5) Parsed patient id: D123401
2017-10-27 12:14:43,381 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:oasis:names:tc:xacml:1.0:action:action-id'; value='DocumentQueryOut'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,382 INFO  [gov.hhs.fha.nhinc.transform.policy.AdhocQueryTransformHelper] (default task-5) Unique patientid is null in the assertion.
2017-10-27 12:14:43,382 DEBUG [gov.hhs.fha.nhinc.transform.policy.AdhocQueryTransformHelper] (default task-5) transformAdhocQueryToCheckPolicyBase: event direction: Outbound
2017-10-27 12:14:43,382 DEBUG [gov.hhs.fha.nhinc.transform.policy.AdhocQueryTransformHelper] (default task-5) transformAdhocQueryToCheckPolicyBase: aaId: 2.2
2017-10-27 12:14:43,382 DEBUG [gov.hhs.fha.nhinc.transform.policy.AdhocQueryTransformHelper] (default task-5) transformAdhocQueryToCheckPolicyBase: PatientId: D123401
2017-10-27 12:14:43,382 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:assigning-authority-id'; value='2.2'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,382 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:oasis:names:tc:xacml:1.0:resource:resource-id'; value='D123401'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,382 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:home-community-id'; value='urn:oid:1.1'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,382 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending assertion data to xacml request
2017-10-27 12:14:43,382 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending AuthnStatementAuthnInstant
2017-10-27 12:14:43,382 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting AuthInstant
2017-10-27 12:14:43,382 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted AuthInstant value=2009-04-16T13:15:39Z
2017-10-27 12:14:43,382 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:saml-authn-statement:auth-instant'; value='2009-04-16T13:15:39Z'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,382 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending AuthnStatementAuthnInstant
2017-10-27 12:14:43,382 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending AuthnStatementSessionIndex
2017-10-27 12:14:43,382 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting SessionIndex
2017-10-27 12:14:43,382 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted SessionIndex value=987
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:saml-authn-statement:session-index'; value='987'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending AuthnStatementSessionIndex
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending AuthnStatementAthnContextClassRef
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting AuthnStatementAthnContextClassRef
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted AuthnStatementAthnContextClassRef value=urn:oasis:names:tc:SAML:2.0:ac:classes:X509
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:saml-authn-statement:auth-context-class-ref'; value='urn:oasis:names:tc:SAML:2.0:ac:classes:X509'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending AuthnStatementAthnContextClassRef
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending AuthnStatementSubjectLocalityAddress
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting AuthnStatementSubjectLocalityAddress
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted AuthnStatementSubjectLocalityAddress value=1.1.1.1
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:oasis:names:tc:xacml:1.0:subject:authn-locality:ip-address'; value='1.1.1.1'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending AuthnStatementSubjectLocalityAddress
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending AuthnStatementDNSName
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting SubjectLocalityDNSName
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted SubjectLocalityDNSName value=connectopensource.org
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:oasis:names:tc:xacml:1.0:subject:authn-locality:dns-name'; value='connectopensource.org'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending AuthnStatementDNSName
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending UserPersonName
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting UserPersonName
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted UserPersonName value=kskagerberg
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:oasis:names:tc:xacml:1.0:subject:subject-id'; value='kskagerberg'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending UserPersonName
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending UserOrganizationName
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting UserOrganizationName
2017-10-27 12:14:43,383 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted UserOrganizationName value=InternalTest1
2017-10-27 12:14:43,386 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:user-organization-name'; value='InternalTest1'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,386 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending UserOrganizationName
2017-10-27 12:14:43,386 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending UserOrganizationId
2017-10-27 12:14:43,386 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting UserOrganizationId
2017-10-27 12:14:43,386 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted UserOrganizationId value=urn:oid:1.1
2017-10-27 12:14:43,386 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:oasis:names:tc:xspa:1.0:subject:organization-id'; value='urn:oid:1.1'; datatype='http://www.w3.org/2001/XMLSchema#anyURI']
2017-10-27 12:14:43,386 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending UserOrganizationId
2017-10-27 12:14:43,386 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending HomeCommunityName
2017-10-27 12:14:43,386 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting HomeCommunityName
2017-10-27 12:14:43,386 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted HomeCommunityName value=urn:oid:1.1
2017-10-27 12:14:43,386 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='http://www.hhs.gov/healthit/nhin#HomeCommunityId'; value='urn:oid:1.1'; datatype='http://www.w3.org/2001/XMLSchema#anyURI']
2017-10-27 12:14:43,386 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending HomeCommunityName
2017-10-27 12:14:43,386 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending UniquePatientId
2017-10-27 12:14:43,386 WARN  [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Unable to find Unique Patient in SAML, will not be included in message to policy engine
2017-10-27 12:14:43,386 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending UniquePatientId
2017-10-27 12:14:43,386 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending UserRoleCode
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:oasis:names:tc:xacml:2.0:subject:role'; value='307969004'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending UserRoleCode
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending UserRoleCodeSystem
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending UserRoleCodeSystem
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending UserRoleCodeSystemName
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending UserRoleCodeSystemName
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending UserRoleCodeDiplayName
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:user-role-description'; value='Public Health'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending UserRoleCodeDiplayName
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending PurposeOfUseCode
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:oasis:names:tc:xspa:1.0:subject:purposeofuse'; value='PUBLICHEALTH'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending PurposeOfUseCode
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending PurposeOfUseCodeSystem
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending PurposeOfUseCodeSystem
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending PurposeOfUseCodeSystemName
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending PurposeOfUseCodeSystemName
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending PurposeOfUseCodeDisplayName
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:purpose-of-use-display-name'; value='Use or disclosure of Psychotherapy Notes'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending PurposeOfUseCodeDisplayName
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending AuthzDecisionStatementDecision
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting AuthzDecisionStatementDecision
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted AuthzDecisionStatementDecision value=Permit
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:saml-authz-decision-statement-decision'; value='Permit'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending AuthzDecisionStatementDecision
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending AuthzDecisionStatementResource
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting AuthzDecisionStatementResource
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted AuthzDecisionStatementResource value=https://1.1.1.1:8181/SamlReceiveService/SamlProcessWS
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:saml-authz-decision-statement-resource'; value='https://1.1.1.1:8181/SamlReceiveService/SamlProcessWS'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending AuthzDecisionStatementResource
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending AuthzDecisionStatementAction
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting AuthzDecisionStatementAction
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted AuthzDecisionStatementAction value=TestSaml
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:saml-authz-decision-statement-action'; value='TestSaml'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending AuthzDecisionStatementAction
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending AuthzDecisionStatementEvidenceAssertionID
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting AuthzDecisionStatementEvidenceAssertionID
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted AuthzDecisionStatementEvidenceAssertionID value=40df7c0a-ff3e-4b26-baeb-f2910f6d05a9
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:saml-authz-decision-statement-evidence-assertion-id'; value='40df7c0a-ff3e-4b26-baeb-f2910f6d05a9'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending AuthzDecisionStatementEvidenceAssertionID
2017-10-27 12:14:43,387 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending AuthzDecisionStatementEvidenceAssertionIssueInstant
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting AuthzDecisionStatementEvidenceAssertionIssueInstant
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted AuthzDecisionStatementEvidenceAssertionIssueInstant value=2009-04-16T13:10:39.093Z
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:saml-authz-decision-statement-evidence-assertion-issue-instant'; value='2009-04-16T13:10:39.093Z'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending AuthzDecisionStatementEvidenceAssertionIssueInstant
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending AuthzDecisionStatementEvidenceAssertionVersion
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting AuthzDecisionStatementEvidenceAssertionVersion
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted AuthzDecisionStatementEvidenceAssertionVersion value=2.0
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:saml-authz-decision-statement-evidence-assertion-version'; value='2.0'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending AuthzDecisionStatementEvidenceAssertionVersion
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending AuthzDecisionStatementEvidenceAssertionIssuer
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting AuthzDecisionStatementEvidenceAssertionIssuer
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted AuthzDecisionStatementEvidenceAssertionIssuer value=CN=SAML User,OU=connect,O=FHA,L=Melbourne,ST=FL,C=US
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:saml-authz-decision-statement-evidence-assertion-issuer'; value='CN=SAML User,OU=connect,O=FHA,L=Melbourne,ST=FL,C=US'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending AuthzDecisionStatementEvidenceAssertionIssuer
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending AuthzDecisionStatementEvidenceAssertionConditionsNotBefore
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting AuthzDecisionStatementEvidenceAssertionConditionsNotBefore
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted AuthzDecisionStatementEvidenceAssertionConditionsNotBefore value=2009-04-16T13:10:39.093Z
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:saml-authz-decision-statement-evidence-assertion-not-before'; value='2009-04-16T13:10:39.093Z'; datatype='http://www.w3.org/2001/XMLSchema#date']
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending AuthzDecisionStatementEvidenceAssertionConditionsNotBefore
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending AuthzDecisionStatementEvidenceAssertionConditionsNotOnOrAfter
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting AuthzDecisionStatementEvidenceAssertionConditionsNotOnOrAfter
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted AuthzDecisionStatementEvidenceAssertionConditionsNotOnOrAfter value=2009-12-31T12:00:00.000Z
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:saml-authz-decision-statement-evidence-assertion-not-on-or-after'; value='2009-12-31T12:00:00.000Z'; datatype='http://www.w3.org/2001/XMLSchema#date']
2017-10-27 12:14:43,388 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending AuthzDecisionStatementEvidenceAssertionConditionsNotOnOrAfter
2017-10-27 12:14:43,389 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending AuthzDecisionStatementEvidenceAssertionAccessConsentPolicy
2017-10-27 12:14:43,389 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting AuthzDecisionStatementEvidenceAssertionAccessConsentPolicy
2017-10-27 12:14:43,389 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted AuthzDecisionStatementEvidenceAssertionAccessConsentPolicy value=[urn:oid:1.2.3.4]
2017-10-27 12:14:43,389 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:saml-authz-decision-statement-evidence-assertion-access-consent'; value='[urn:oid:1.2.3.4]'; datatype='http://www.w3.org/2001/XMLSchema#anyURI']
2017-10-27 12:14:43,389 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending AuthzDecisionStatementEvidenceAssertionAccessConsentPolicy
2017-10-27 12:14:43,389 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) begin appending AuthzDecisionStatementEvidenceAssertionInstanceAccessConsentPolicy
2017-10-27 12:14:43,389 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracting AuthzDecisionStatementEvidenceAssertionInstanceAccessConsentPolicy
2017-10-27 12:14:43,389 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) Extracted AuthzDecisionStatementEvidenceAssertionInstanceAccessConsentPolicy value=[urn:oid:1.2.3.4.123456789]
2017-10-27 12:14:43,389 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:saml-authz-decision-statement-evidence-assertion-instance-access-consent'; value='[urn:oid:1.2.3.4.123456789]'; datatype='http://www.w3.org/2001/XMLSchema#anyURI']
2017-10-27 12:14:43,389 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending AuthzDecisionStatementEvidenceAssertionInstanceAccessConsentPolicy
2017-10-27 12:14:43,389 DEBUG [gov.hhs.fha.nhinc.transform.policy.AssertionHelper] (default task-5) end appending assertion data to xacml request
2017-10-27 12:14:43,389 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) creating XACML attribute [id='urn:gov:hhs:fha:nhinc:home-community-id'; value='null'; datatype='http://www.w3.org/2001/XMLSchema#string']
2017-10-27 12:14:43,389 DEBUG [gov.hhs.fha.nhinc.transform.policy.AttributeHelper] (default task-5) XACML attribute [id='urn:gov:hhs:fha:nhinc:home-community-id' was null - returning null - no atribute will be added.
2017-10-27 12:14:43,389 DEBUG [gov.hhs.fha.nhinc.transform.policy.AdhocQueryTransformHelper] (default task-5) end transformAdhocQueryToCheckPolicy
2017-10-27 12:14:43,389 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Trying to get lock for ApplicationContext file:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/PolicyEngineProxyConfig.xml
2017-10-27 12:14:43,389 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) ApplicationContext for: PolicyEngineProxyConfig.xml was not null - checking to see if it is stale.
2017-10-27 12:14:43,389 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Releasing lock for ApplicationContextfile:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/PolicyEngineProxyConfig.xml
2017-10-27 12:14:43,389 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 DEBUG DefaultListableBeanFactory:244 - Returning cached instance of singleton bean 'policyenginewsunsecured'
2017-10-27 12:14:43,395 DEBUG [gov.hhs.fha.nhinc.webserviceproxy.WebServiceProxyHelper] (default task-5) Begin invokePort
2017-10-27 12:14:43,395 DEBUG [gov.hhs.fha.nhinc.webserviceproxy.WebServiceProxyHelper] (default task-5) Invoking gov.hhs.fha.nhinc.adapterpolicyengine.AdapterPolicyEnginePortType.checkPolicy: Try #1
2017-10-27 12:14:43,395 DEBUG [gov.hhs.fha.nhinc.webserviceproxy.WebServiceProxyHelper] (default task-5) with parameters: gov.hhs.fha.nhinc.common.nhinccommonadapter.CheckPolicyRequestType
2017-10-27 12:14:43,407 INFO  [stdout] (default task-7) 2017-10-27 12:14:43 TRACE DefaultListableBeanFactory:527 - No bean named '' found in org.springframework.beans.factory.support.DefaultListableBeanFactory@4aea5571: defining beans [cxf,org.apache.cxf.bus.spring.BusWiringBeanFactoryPostProcessor,org.apache.cxf.bus.spring.Jsr250BeanPostProcessor,org.apache.cxf.bus.spring.BusExtensionPostProcessor,securityConfigInInterceptor,timestampInInterceptor,attachmentFaultOutInterceptor,org.springframework.beans.factory.config.PropertyPlaceholderConfigurer#0,AdapterPolicyEngineSecured,AdapterPolicyEngine,AdapterPolicyEngineOrchestrator,AdapterPEPService,AdapterPIPService,AdapterDocumentRegistry,AdapterDocumentRepository,AdapterComponentRedactionEngine,DeferredQueueManager,AdapterAuthenticationService]; root of factory hierarchy
2017-10-27 12:14:43,409 DEBUG [gov.hhs.fha.nhinc.policyengine.adapter.AdapterPolicyEngineImpl] (default task-7) Begin AdapterPolicyEngineImpl.checkPolicy (unsecure)
2017-10-27 12:14:43,409 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-7) Trying to get lock for ApplicationContext file:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/PolicyEngineProxyConfig.xml
2017-10-27 12:14:43,409 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-7) ApplicationContext for: PolicyEngineProxyConfig.xml was not null - checking to see if it is stale.
2017-10-27 12:14:43,410 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-7) Releasing lock for ApplicationContextfile:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/PolicyEngineProxyConfig.xml
2017-10-27 12:14:43,410 INFO  [stdout] (default task-7) 2017-10-27 12:14:43 DEBUG DefaultListableBeanFactory:244 - Returning cached instance of singleton bean 'adapterpolicyengineorchestratorsamljava'
2017-10-27 12:14:43,412 DEBUG [gov.hhs.fha.nhinc.policyengine.adapter.AdapterPolicyEngineProcessorImpl] (default task-7) AdapterPolicyEngineOrchProxy selected: class gov.hhs.fha.nhinc.policyengine.adapter.orchestrator.proxy.AdapterPolicyEngineOrchProxySAMLJavaImpl
2017-10-27 12:14:43,412 DEBUG [gov.hhs.fha.nhinc.policyengine.adapter.orchestrator.util.policyEngineUtil] (default task-7) Person Type Check Passed
2017-10-27 12:14:43,412 DEBUG [gov.hhs.fha.nhinc.policyengine.adapter.orchestrator.util.policyEngineUtil] (default task-7) assertion.getUserInfo().getRoleCoded().getCodeSystem() Check Failed
2017-10-27 12:14:43,412 DEBUG [gov.hhs.fha.nhinc.policyengine.adapter.AdapterPolicyEngineImpl] (default task-7) End AdapterPolicyEngineImpl.checkPolicy (unsecure)
2017-10-27 12:14:43,413 DEBUG [gov.hhs.fha.nhinc.webserviceproxy.WebServiceProxyHelper] (default task-5) End invokePort
2017-10-27 12:14:43,413 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Trying to get lock for ApplicationContext file:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/TransactionLoggingProxyConfig.xml
2017-10-27 12:14:43,413 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) ApplicationContext for: TransactionLoggingProxyConfig.xml was not null - checking to see if it is stale.
2017-10-27 12:14:43,413 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Releasing lock for ApplicationContextfile:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/TransactionLoggingProxyConfig.xml
2017-10-27 12:14:43,414 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 DEBUG DefaultListableBeanFactory:244 - Returning cached instance of singleton bean 'transactionstoredatabase'
2017-10-27 12:14:43,414 DEBUG [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) TransactionDAO.getTransactinId() - Begin
2017-10-27 12:14:43,414 INFO  [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) -- MessageId Parameter is required for Transaction Query --
2017-10-27 12:14:43,414 DEBUG [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) TransactionDAO.getTransactinId() - End
2017-10-27 12:14:43,414 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Trying to get lock for ApplicationContext file:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/TransactionLoggingProxyConfig.xml
2017-10-27 12:14:43,414 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) ApplicationContext for: TransactionLoggingProxyConfig.xml was not null - checking to see if it is stale.
2017-10-27 12:14:43,414 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Releasing lock for ApplicationContextfile:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/TransactionLoggingProxyConfig.xml
2017-10-27 12:14:43,414 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 DEBUG DefaultListableBeanFactory:244 - Returning cached instance of singleton bean 'transactionstoredatabase'
2017-10-27 12:14:43,414 DEBUG [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) TransactionDAO.getTransactinId() - Begin
2017-10-27 12:14:43,414 INFO  [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) -- MessageId Parameter is required for Transaction Query --
2017-10-27 12:14:43,415 DEBUG [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) TransactionDAO.getTransactinId() - End
2017-10-27 12:14:43,415 DEBUG [gov.hhs.fha.nhinc.persistence.HibernateUtilFactory] (default task-5) Memory address eventHibernateUtil org.springframework.context.support.ClassPathXmlApplicationContext@56e2f983
2017-10-27 12:14:43,415 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:249 - No transaction, no need to enlist: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7987bef5[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110 connection handles=0 lastUse=1509124483183 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@78f9587e mcp=SemaphoreArrayListManagedConnectionPool@20c9ebba[pool=eventdb_pool] xaResource=LocalXAResourceImpl@579e53f3[connectionListener=7987bef5 connectionManager=a5d6a62 warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/eventdb_datasource] txSync=null]
2017-10-27 12:14:43,416 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:267 - [TxConnectionListener@7987bef5] registerConnection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@4df6d21a [size=1] ([org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@4df6d21a])
2017-10-27 12:14:43,419 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:615 - connectionClosed called mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110
2017-10-27 12:14:43,420 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@7987bef5] isManagedConnectionFree: false
2017-10-27 12:14:43,420 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:326 - [TxConnectionListener@7987bef5] unregisterConnection: 0 handles left ([])
2017-10-27 12:14:43,421 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@7987bef5] isManagedConnectionFree: true
2017-10-27 12:14:43,421 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:394 - delisting org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7987bef5[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110 connection handles=0 lastUse=1509124483183 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@78f9587e mcp=SemaphoreArrayListManagedConnectionPool@20c9ebba[pool=eventdb_pool] xaResource=LocalXAResourceImpl@579e53f3[connectionListener=7987bef5 connectionManager=a5d6a62 warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/eventdb_datasource] txSync=null]
2017-10-27 12:14:43,422 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@7987bef5] isManagedConnectionFree: true
2017-10-27 12:14:43,422 INFO  [io.undertow.request.dump] (default task-7) 
----------------------------REQUEST---------------------------
               URI=/CONNECTAdapter/AdapterProxyService/AdapterPolicyEngine
 characterEncoding=null
     contentLength=-1
       contentType=[application/soap+xml; action="urn:CheckPolicy"; charset=UTF-8]
            header=Accept=*/*
            header=Connection=keep-alive
            header=Cache-Control=no-cache
            header=Pragma=no-cache
            header=Transfer-Encoding=chunked
            header=Content-Type=application/soap+xml; action="urn:CheckPolicy"; charset=UTF-8
            header=User-Agent=Apache CXF 2.7.3
            header=Host=172.24.32.231:8080
            locale=[]
            method=POST
          protocol=HTTP/1.1
       queryString=
        remoteAddr=/172.24.32.231:52578
        remoteHost=172.24.32.231
            scheme=http
              host=172.24.32.231:8080
        serverPort=8080
--------------------------RESPONSE--------------------------
     contentLength=1304
       contentType=application/soap+xml;charset=UTF-8
            header=Connection=keep-alive
            header=X-Powered-By=Undertow/1
            header=Server=WildFly/8
            header=Content-Type=application/soap+xml;charset=UTF-8
            header=Content-Length=1304
            header=Date=Fri, 27 Oct 2017 17:14:43 GMT
            status=200
==============================================================
2017-10-27 12:14:43,423 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:501 - delisted org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7987bef5[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110 connection handles=0 lastUse=1509124483183 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@78f9587e mcp=SemaphoreArrayListManagedConnectionPool@20c9ebba[pool=eventdb_pool] xaResource=LocalXAResourceImpl@579e53f3[connectionListener=7987bef5 connectionManager=a5d6a62 warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/eventdb_datasource] txSync=null]
2017-10-27 12:14:43,423 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:639 - isManagedConnectionFree=true mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110
2017-10-27 12:14:43,424 INFO  [gov.hhs.fha.nhinc.event.Log4jEventLogger] (default task-5) END_OUTBOUND_PROCESSING has triggered. It has messageID urn:uuid:80b6d2e8-b932-4b4a-8259-e8d94ae62628, transactionID null and description {"service_type":"Document Query","responding_hcids":["urn:oid:1.1"],"response_ids":["urn:uuid:e0a9666b-2c7e-411a-a884-26f3b17c2479"],"action":"","statuses":["urn:oasis:names:tc:ebxml-regrep:ResponseStatusType:Success"],"message_id":"urn:uuid:80b6d2e8-b932-4b4a-8259-e8d94ae62628","initiating_hcid":"urn:oid:1.1"}
2017-10-27 12:14:43,424 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Trying to get lock for ApplicationContext file:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/TransactionLoggingProxyConfig.xml
2017-10-27 12:14:43,424 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) ApplicationContext for: TransactionLoggingProxyConfig.xml was not null - checking to see if it is stale.
2017-10-27 12:14:43,424 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Releasing lock for ApplicationContextfile:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/TransactionLoggingProxyConfig.xml
2017-10-27 12:14:43,424 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 DEBUG DefaultListableBeanFactory:244 - Returning cached instance of singleton bean 'transactionstoredatabase'
2017-10-27 12:14:43,424 DEBUG [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) TransactionDAO.getTransactinId() - Begin
2017-10-27 12:14:43,424 INFO  [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) -- MessageId Parameter is required for Transaction Query --
2017-10-27 12:14:43,424 DEBUG [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) TransactionDAO.getTransactinId() - End
2017-10-27 12:14:43,425 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Trying to get lock for ApplicationContext file:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/TransactionLoggingProxyConfig.xml
2017-10-27 12:14:43,425 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) ApplicationContext for: TransactionLoggingProxyConfig.xml was not null - checking to see if it is stale.
2017-10-27 12:14:43,425 DEBUG [gov.hhs.fha.nhinc.proxy.ComponentProxyObjectFactory] (default task-5) Releasing lock for ApplicationContextfile:////opt/wildfly/modules/system/layers/base/org/connectopensource/configuration/main/TransactionLoggingProxyConfig.xml
2017-10-27 12:14:43,425 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 DEBUG DefaultListableBeanFactory:244 - Returning cached instance of singleton bean 'transactionstoredatabase'
2017-10-27 12:14:43,425 DEBUG [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) TransactionDAO.getTransactinId() - Begin
2017-10-27 12:14:43,425 INFO  [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) -- MessageId Parameter is required for Transaction Query --
2017-10-27 12:14:43,425 DEBUG [gov.hhs.fha.nhinc.logging.transaction.dao.TransactionDAO] (default task-5) TransactionDAO.getTransactinId() - End
2017-10-27 12:14:43,425 DEBUG [gov.hhs.fha.nhinc.persistence.HibernateUtilFactory] (default task-5) Memory address eventHibernateUtil org.springframework.context.support.ClassPathXmlApplicationContext@56e2f983
2017-10-27 12:14:43,426 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:249 - No transaction, no need to enlist: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7987bef5[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110 connection handles=0 lastUse=1509124483424 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@78f9587e mcp=SemaphoreArrayListManagedConnectionPool@20c9ebba[pool=eventdb_pool] xaResource=LocalXAResourceImpl@579e53f3[connectionListener=7987bef5 connectionManager=a5d6a62 warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/eventdb_datasource] txSync=null]
2017-10-27 12:14:43,426 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:267 - [TxConnectionListener@7987bef5] registerConnection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@6903732c [size=1] ([org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@6903732c])
2017-10-27 12:14:43,433 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:615 - connectionClosed called mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110
2017-10-27 12:14:43,433 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@7987bef5] isManagedConnectionFree: false
2017-10-27 12:14:43,433 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:326 - [TxConnectionListener@7987bef5] unregisterConnection: 0 handles left ([])
2017-10-27 12:14:43,434 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@7987bef5] isManagedConnectionFree: true
2017-10-27 12:14:43,434 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:394 - delisting org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7987bef5[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110 connection handles=0 lastUse=1509124483424 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@78f9587e mcp=SemaphoreArrayListManagedConnectionPool@20c9ebba[pool=eventdb_pool] xaResource=LocalXAResourceImpl@579e53f3[connectionListener=7987bef5 connectionManager=a5d6a62 warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/eventdb_datasource] txSync=null]
2017-10-27 12:14:43,435 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:236 - [TxConnectionListener@7987bef5] isManagedConnectionFree: true
2017-10-27 12:14:43,435 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:501 - delisted org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7987bef5[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110 connection handles=0 lastUse=1509124483424 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@78f9587e mcp=SemaphoreArrayListManagedConnectionPool@20c9ebba[pool=eventdb_pool] xaResource=LocalXAResourceImpl@579e53f3[connectionListener=7987bef5 connectionManager=a5d6a62 warned=false currentXid=null productName=MySQL productVersion=5.7.20-0ubuntu0.16.04.1-log jndiName=java:/jdbc/eventdb_datasource] txSync=null]
2017-10-27 12:14:43,435 INFO  [stdout] (default task-5) 2017-10-27 12:14:43 TRACE TxConnectionListener:639 - isManagedConnectionFree=true mc=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@27ef8110
2017-10-27 12:14:43,435 INFO  [gov.hhs.fha.nhinc.event.Log4jEventLogger] (default task-5) END_OUTBOUND_MESSAGE has triggered. It has messageID urn:uuid:80b6d2e8-b932-4b4a-8259-e8d94ae62628, transactionID null and description {"service_type":"Document Query","responding_hcids":["urn:oid:1.1"],"response_ids":["urn:uuid:e0a9666b-2c7e-411a-a884-26f3b17c2479"],"action":"3.0","statuses":["urn:oasis:names:tc:ebxml-regrep:ResponseStatusType:Success"],"message_id":"urn:uuid:80b6d2e8-b932-4b4a-8259-e8d94ae62628","initiating_hcid":"urn:oid:1.1"}
2017-10-27 12:14:43,436 WARN  [org.apache.cxf.ws.addressing.ContextUtils] (default task-5) WS-Addressing - failed to retrieve Message Addressing Properties from context
2017-10-27 12:14:43,436 WARN  [org.apache.cxf.ws.addressing.ContextUtils] (default task-5) WS-Addressing - failed to retrieve Message Addressing Properties from context
2017-10-27 12:14:43,436 WARN  [org.apache.cxf.ws.addressing.ContextUtils] (default task-5) WS-Addressing - failed to retrieve Message Addressing Properties from context
2017-10-27 12:14:43,437 DEBUG [gov.hhs.fha.nhinc.logging.transaction.TransactionHandler] (default task-5) TransactionHandler handleMessage() START 
2017-10-27 12:14:43,437 DEBUG [gov.hhs.fha.nhinc.logging.transaction.TransactionHandler] (default task-5) TransactionHandler handleMessage() WSA namespace = http://www.w3.org/2004/08/addressing
2017-10-27 12:14:43,437 DEBUG [gov.hhs.fha.nhinc.logging.transaction.TransactionHandler] (default task-5) TransactionHandler.close
2017-10-27 12:14:43,438 INFO  [io.undertow.request.dump] (default task-5) 
----------------------------REQUEST---------------------------
               URI=/Gateway/DocumentQuery/3_0/EntityService/EntityDocQueryUnsecured
 characterEncoding=null
     contentLength=6617
       contentType=[application/soap+xml;charset=UTF-8;action="urn:gov:hhs:fha:nhinc:entitydocquery:RespondingGateway_CrossGatewayQueryRequest"]
            header=Connection=Keep-Alive
            header=Accept-Encoding=gzip,deflate
            header=Content-Type=application/soap+xml;charset=UTF-8;action="urn:gov:hhs:fha:nhinc:entitydocquery:RespondingGateway_CrossGatewayQueryRequest"
            header=Content-Length=6617
            header=User-Agent=Apache-HttpClient/4.1.1 (java 1.5)
            header=Host=172.24.32.231:8080
            locale=[]
            method=POST
          protocol=HTTP/1.1
       queryString=
        remoteAddr=/192.168.237.25:61539
        remoteHost=192.168.237.25
            scheme=http
              host=172.24.32.231:8080
        serverPort=8080
--------------------------RESPONSE--------------------------
     contentLength=1153
       contentType=application/soap+xml;charset=UTF-8
            header=Connection=keep-alive
            header=X-Powered-By=Undertow/1
            header=Server=WildFly/8
            header=Content-Type=application/soap+xml;charset=UTF-8
            header=Content-Length=1153
            header=Date=Fri, 27 Oct 2017 17:14:43 GMT
            status=200
==============================================================

I have logging turned WAY up as you can tell.

So I'm hoping I can get a trained eye to look through these and help me figure out why my DQ suddenly stopped working!
Ask The Experts: http://consultzen.com/
Reply | Threaded
Open this post in threaded view
|

Re: SoapUI DocQuery Test Yields EMPTY AdhocQueryResponse? CONNECT 4.7

johnhd_at_zen
I wound up reinstalling from scratch on a rolled-back server and seemed to get past this.

My intuition is that I may actually have been using the CONNECT 5.0 SOAP UI tests on CONNECT 4.7 at the end of the day.
Ask The Experts: http://consultzen.com/