Turning Off Debug Log In EDIS
13 views
Skip to first unread message
Sree
Jan 31, 2012, 5:19:03 AM1/31/12
to VistA Emergency Room
Dear All,
While loading the EDIS application, its writing multiple lines of
debug statements in the console because of that the EDIS page is
taking more time to load.
I have tried commenting the debug level in logback.xml (tracking-
server-main\src\jetty\logback.xml) but it has no impact on debug logs.
Kindly suggest me the changes so that the debug logs can be turned
off.
Regards,
Srikant
While loading the EDIS application, its writing multiple lines of
debug statements in the console because of that the EDIS page is
taking more time to load.
I have tried commenting the debug level in logback.xml (tracking-
server-main\src\jetty\logback.xml) but it has no impact on debug logs.
Kindly suggest me the changes so that the debug logs can be turned
off.
Regards,
Srikant
Wasim Naffar
Feb 5, 2012, 3:40:07 AM2/5/12
to vista-emer...@googlegroups.com
Hi Srikant,
I guess the debug working on VistALink 1.6, already i run EDIS on VistALink 1.5 and i never seen the debug item on the EDIS viewer, and i have never use it, just i found it on the screenshots and EDIS manuals.
Anyway, i will try to find if there is a key or an option given to the user!! maybe that is the case!!
Regards,
Wasim
I guess the debug working on VistALink 1.6, already i run EDIS on VistALink 1.5 and i never seen the debug item on the EDIS viewer, and i have never use it, just i found it on the screenshots and EDIS manuals.
Anyway, i will try to find if there is a key or an option given to the user!! maybe that is the case!!
Regards,
Wasim
--
You received this message because you are subscribed to the Google Groups "VistA Emergency Room" group.
To post to this group, send email to vista-emer...@googlegroups.com.
To unsubscribe from this group, send email to vista-emergency-...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/vista-emergency-room?hl=en.
Wasim Naffar
Feb 5, 2012, 3:43:07 AM2/5/12
to vista-emer...@googlegroups.com
oohh, do you mean only the application server's console or the Debug item on the EDIS??!!
Nancy Anthracite
Feb 5, 2012, 8:12:45 AM2/5/12
to vista-emer...@googlegroups.com, Wasim Naffar
I dread even thinking about it, but has anyone gotten VistALink 1.6 going that
might have some easy instructions for getting it to work? The easy to install
version of 1.5 I have was my response to a lot of pain as it took me a LONG
time to get it going, mainly because I had no clue what I was doing. You
could put the Java I know in a thimble.
might have some easy instructions for getting it to work? The easy to install
version of 1.5 I have was my response to a lot of pain as it took me a LONG
time to get it going, mainly because I had no clue what I was doing. You
could put the Java I know in a thimble.
--
Nancy Anthracite
Sree
Feb 6, 2012, 12:15:53 AM2/6/12
to VistA Emergency Room
Dear Wasim,
Yes, the Debug logger are there in the Application Server console.
Some sample debug lines are as follows:
10:28:52.269 [http-apr-8080-exec-5] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionEventListener -
VistaLinkManagedConnection destroyed via close() event and
VistaLinkManagedConnectionEventListener
10:28:52.270 [http-apr-8080-exec-5] DEBUG
o.s.web.servlet.DispatcherServlet - Rendering view
[gov.va.med.edp.web.view.XmlView: name 'xmlView'] in DispatcherServlet
with name 'dispatcher'
10:28:52.271 [http-apr-8080-exec-5] DEBUG
gov.va.med.edp.web.view.XmlView - Rendering view with name 'xmlView'
with model {xmlFragment=<params clinics="0" codedDiag="1"
emptyIEN="46" errorIEN="7" evalIEN="44" leftIEN="37" minDelay="300"
reqDelay="1" reqDiag="1" reqDisp="1" residents="1" />
<logEntries status='new' token='62490,44198' >
<log bed="CT" id="1" last4="T6123" name="TEST,ONE" same="0" seq="50"
ssn="856456123" />
<log bed="CATH" id="2" last4="T6124" name="TESTING,TESTING M M"
same="0" seq="70" ssn="445566124" />
<log bed="SCLIN" id="3" name="ZZ PATIENT,TEST TWO" same="0" seq="100" /
>
</logEntries>
} and static attributes {}
10:28:52.273 [http-apr-8080-exec-5] DEBUG
o.s.web.servlet.DispatcherServlet - Cleared thread-bound request
context:
org.springframework.security.wrapper.SavedRequestAwareWrapper@4da3dc1d
10:28:52.276 [http-apr-8080-exec-5] DEBUG
o.s.web.servlet.DispatcherServlet - Successfully completed request
10:28:52.277 [http-apr-8080-exec-5] DEBUG
o.s.w.c.s.XmlWebApplicationContext - Publishing event in context
[org.springframework.web.context.support.XmlWebApplicationContext@414128f7]:
ServletRequestHandledEvent: url=[/main/tracking.xml];
client=[127.0.0.1]; method=[POST]; servlet=[dispatcher];
session=[6705BD29FA9A6170465037EE2BEB1CAE]; user=[93@999];
time=[4942ms]; status=[OK]
10:28:52.277 [http-apr-8080-exec-5] DEBUG
o.s.w.c.s.XmlWebApplicationContext - Publishing event in context
[org.springframework.web.context.support.XmlWebApplicationContext@282c1f9d]:
ServletRequestHandledEvent: url=[/main/tracking.xml];
client=[127.0.0.1]; method=[POST]; servlet=[dispatcher];
session=[6705BD29FA9A6170465037EE2BEB1CAE]; user=[93@999];
time=[4942ms]; status=[OK]
10:28:52.278 [http-apr-8080-exec-5] DEBUG
o.s.s.ui.ExceptionTranslationFilter - Chain processed normally
10:28:52.279 [http-apr-8080-exec-5] DEBUG
o.s.s.c.HttpSessionContextIntegrationFilter - SecurityContextHolder
now cleared, as request processing completed
10:29:17.340 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - Converted URL to lowercase, from:
'/tracking.xml'; to: '/tracking.xml'
10:29:17.341 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - Candidate is: '/tracking.xml';
pattern is /logout.html*; matched=false
10:29:17.341 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - Converted URL to lowercase, from:
'/tracking.xml'; to: '/tracking.xml'
10:29:17.342 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - Candidate is: '/tracking.xml';
pattern is /**; matched=true
10:29:17.343 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 1 of 7
in additional filter chain; firing Filter:
'org.springframework.security.context.HttpSessionContextIntegrationFilter[ order=200; ]'
10:29:17.343 [http-apr-8080-exec-6] DEBUG
o.s.s.c.HttpSessionContextIntegrationFilter - Obtained a valid
SecurityContext from SPRING_SECURITY_CONTEXT to associate with
SecurityContextHolder:
'org.springframework.security.context.SecurityContextImpl@46e50923:
Authentication:
gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER'
10:29:17.343 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 2 of 7
in additional filter chain; firing Filter:
'gov.va.med.edp.springframework.security.ui.vistalink.VistaAuthenticationProcessingFilter[ order=700; ]'
10:29:17.344 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 3 of 7
in additional filter chain; firing Filter:
'org.springframework.security.wrapper.SecurityContextHolderAwareRequestFilter[ order=1100; ]'
10:29:17.344 [http-apr-8080-exec-6] DEBUG
o.s.s.ui.savedrequest.SavedRequest - pathInfo: both null (property
equals)
10:29:17.345 [http-apr-8080-exec-6] DEBUG
o.s.s.ui.savedrequest.SavedRequest - queryString: both null (property
equals)
10:29:17.345 [http-apr-8080-exec-6] DEBUG
o.s.s.ui.savedrequest.SavedRequest - requestURI: arg1=/main/
tracking.html;jsessionid=6705BD29FA9A6170465037EE2BEB1CAE; arg2=/main/
tracking.xml (property not equals)
10:29:17.346 [http-apr-8080-exec-6] DEBUG
o.s.s.w.SavedRequestAwareWrapper - Wrapper not replaced; SavedRequest
was: SavedRequest[http://localhost:8080/main/tracking.html]
10:29:17.346 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 4 of 7
in additional filter chain; firing Filter:
'org.springframework.security.providers.anonymous.AnonymousProcessingFilter[ order=1300; ]'
10:29:17.347 [http-apr-8080-exec-6] DEBUG
o.s.s.p.a.AnonymousProcessingFilter - SecurityContextHolder not
populated with anonymous token, as it already contained:
'gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER'
10:29:17.347 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 5 of 7
in additional filter chain; firing Filter:
'org.springframework.security.ui.ExceptionTranslationFilter[ order=1400; ]'
10:29:17.348 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 6 of 7
in additional filter chain; firing Filter:
'org.springframework.security.ui.SessionFixationProtectionFilter[ order=1600; ]'
10:29:17.348 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 7 of 7
in additional filter chain; firing Filter:
'org.springframework.security.intercept.web.FilterSecurityInterceptor@a45ed31'
10:29:17.349 [http-apr-8080-exec-6] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Converted URL to
lowercase, from: '/tracking.xml'; to: '/tracking.xml'
10:29:17.349 [http-apr-8080-exec-6] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
tracking.xml'; pattern is /about.html; matched=false
10:29:17.350 [http-apr-8080-exec-6] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
tracking.xml'; pattern is /login.html*; matched=false
10:29:17.350 [http-apr-8080-exec-6] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
tracking.xml'; pattern is /**/*.swf; matched=false
10:29:17.351 [http-apr-8080-exec-6] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
tracking.xml'; pattern is /**/*.xml; matched=true
10:29:17.351 [http-apr-8080-exec-6] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Secure object: FilterInvocation:
URL: /tracking.xml; ConfigAttributes: [ROLE_USER]
10:29:17.352 [http-apr-8080-exec-6] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Previously Authenticated:
gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER
10:29:17.352 [http-apr-8080-exec-6] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Authorization successful
10:29:17.353 [http-apr-8080-exec-6] DEBUG
o.s.w.c.s.XmlWebApplicationContext - Publishing event in context
[org.springframework.web.context.support.XmlWebApplicationContext@282c1f9d]:
org.springframework.security.event.authorization.AuthorizedEvent[source=FilterInvocation:
URL: /tracking.xml]
10:29:17.353 [http-apr-8080-exec-6] DEBUG
o.s.s.i.AbstractSecurityInterceptor - RunAsManager did not change
Authentication object
10:29:17.354 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml reached end of
additional filter chain; proceeding with original chain
10:29:17.354 [http-apr-8080-exec-6] DEBUG
o.s.web.servlet.DispatcherServlet - DispatcherServlet with name
'dispatcher' received request for [/main/tracking.xml]
10:29:17.354 [http-apr-8080-exec-6] DEBUG
o.s.web.servlet.DispatcherServlet - Bound request context to thread:
org.springframework.security.wrapper.SavedRequestAwareWrapper@38cf0a88
10:29:17.355 [http-apr-8080-exec-6] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler map
[org.springframework.web.servlet.handler.BeanNameUrlHandlerMapping@20d37520]
in DispatcherServlet with name 'dispatcher'
10:29:17.355 [http-apr-8080-exec-6] DEBUG
o.s.w.s.h.BeanNameUrlHandlerMapping - Looking up handler for [/
tracking.xml]
10:29:17.355 [http-apr-8080-exec-6] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler adapter
[org.springframework.web.servlet.mvc.HttpRequestHandlerAdapter@1aae98b6]
10:29:17.355 [http-apr-8080-exec-6] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler adapter
[org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter@6d84f7a0]
10:29:17.356 [http-apr-8080-exec-6] DEBUG
o.s.b.f.s.DefaultListableBeanFactory - Returning cached instance of
singleton bean 'vljConnector999'
10:29:17.356 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkConnectionRequestInfo - Constructing request info
10:29:17.356 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkConnectionManager - allocating connection
10:29:17.356 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionFactory -
gov.va.med.edp.vistalink.adapter.spi.VistaLinkManagedConnectionFactory[]10.10.0.124[]8011[]1[adapterversion]1.5.0.026[]J2EE[fdi]1
Creating Managed connection->6
10:29:17.356 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=[Not Set]
Constructing
10:29:17.357 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkConnectionEventNotifier - Constructing
10:29:17.359 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=[Not Set]
Executing Init Socket interaction
10:29:17.359 [http-apr-8080-exec-6] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@20bc83db
10:29:17.360 [http-apr-8080-exec-6] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilder implementation:
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderImpl
10:29:17.361 [http-apr-8080-exec-6] DEBUG gov.va.med.xml.XmlUtilities
- XPath /VistaLink/Request returned 1nodes.
10:29:17.361 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=[Not Set]
Executing interaction
10:29:17.361 [http-apr-8080-exec-6] DEBUG gov.va.med.xml.XmlUtilities
- Using Transformer implementation:
com.sun.org.apache.xalan.internal.xsltc.trax.TransformerImpl
10:29:17.362 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=[Not Set]
Executing transfer with time out of 5000
10:29:18.398 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->234
10:29:18.600 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->121
10:29:18.600 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->Got EOT->121
10:29:18.601 [http-apr-8080-exec-6] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1239
10:29:18.602 [http-apr-8080-exec-6] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@3874afa7
10:29:18.604 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponseFactory - got response
attributes
10:29:18.605 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponseFactory - Retrieved Initial
Socket Response:
heartbeat rate = 604800000
M $JOB = 12646
Reauth session Timeout = 3600000
10:29:18.605 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponse - initSocket response
constructed[]604800000
10:29:18.606 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=[Not Set]
Heartbeat rate set successfully[]604800000
10:29:18.606 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
M $JOB set successfully[]12646
10:29:18.607 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Setting up authentication
10:29:18.610 [http-apr-8080-exec-6] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - -> sending AV.SetupAndIntroText
10:29:18.611 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Executing interaction
10:29:18.612 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Executing transfer with time out of 5000
10:29:19.624 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->231
10:29:19.626 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->512
10:29:19.626 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->512
10:29:19.627 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->512
10:29:19.628 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->512
10:29:19.629 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->512
10:29:19.629 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->512
10:29:19.631 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->512
10:29:19.631 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->512
10:29:19.632 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->430
10:29:19.632 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->Got EOT->430
10:29:19.633 [http-apr-8080-exec-6] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1020
10:29:19.633 [http-apr-8080-exec-6] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@62ac4540
10:29:19.638 [http-apr-8080-exec-6] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - Result: 1
10:29:19.639 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
executing first phase logon
10:29:19.642 [http-apr-8080-exec-6] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - -> sending AV.Logon
10:29:19.642 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Executing interaction
10:29:19.644 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Executing transfer with time out of 5000
10:29:20.664 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->226
10:29:20.865 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->130
10:29:20.866 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->Got EOT->130
10:29:20.867 [http-apr-8080-exec-6] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1222
10:29:20.868 [http-apr-8080-exec-6] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@36cdc2b3
10:29:20.872 [http-apr-8080-exec-6] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - Result: 1
10:29:20.873 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Added managedconnection to Heartbeat TimerTask
10:29:20.874 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionFactory -
gov.va.med.edp.vistalink.adapter.spi.VistaLinkManagedConnectionFactory[]10.10.0.124[]8011[]1[adapterversion]1.5.0.026[]J2EE[fdi]1
Created Managed connection->6
10:29:20.882 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
addConnectionEventListener
10:29:20.882 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkConnectionEventNotifier -
addConnectionEventListener
10:29:20.883 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Getting connection handle
10:29:20.884 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Connection handle available
10:29:20.884 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Connection re-authentication status: 'notauthenticated'. cri =
Con Req Info is null
10:29:20.885 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
addConHandle
10:29:20.885 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionFactory - elapsedMillis to add:
2
10:29:20.886 [http-apr-8080-exec-6] INFO
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
getConnection(...) processing time = 2
10:29:20.886 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection - About to execute RPC:
'EDPCTRL RPC', on connector configured with JNDI name: '',
primaryStation: '999', reauthentication type: 'duz', credentials:
'93'.
10:29:20.887 [http-apr-8080-exec-6] DEBUG
gov.va.med.vistalink.rpc.RpcRequest - Setting re-authentication
information
10:29:20.888 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Executing interaction
10:29:20.889 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Executing transfer with time out of 10000
10:29:20.898 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->216
10:29:21.097 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->512
10:29:21.097 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->405
10:29:21.098 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->Got EOT->405
10:29:21.098 [http-apr-8080-exec-6] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 208
10:29:21.099 [http-apr-8080-exec-6] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@38be7bc0
10:29:21.101 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection - Completed execution of RPC:
EDPCTRL RPC
10:29:21.101 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Closing handle
10:29:21.102 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
removeConHandle
10:29:21.102 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkConnectionEventNotifier - Connection closed
10:29:21.104 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Destroying managed connection
10:29:21.105 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
removed managedconnection to Heartbeat TimerTask
10:29:21.106 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Executing logout
10:29:21.109 [http-apr-8080-exec-6] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - -> sending AV.Logout
10:29:21.110 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Executing interaction
10:29:21.111 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Executing transfer with time out of 5000
10:29:22.124 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->227
10:29:22.333 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->98
10:29:22.334 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->Got EOT->98
10:29:22.334 [http-apr-8080-exec-6] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1222
10:29:22.335 [http-apr-8080-exec-6] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@35bc2f85
10:29:22.338 [http-apr-8080-exec-6] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - Result: 1
10:29:22.339 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Socket has been successfully closed
10:29:22.340 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionEventListener -
VistaLinkManagedConnection destroyed via close() event and
VistaLinkManagedConnectionEventListener
10:29:22.341 [http-apr-8080-exec-6] DEBUG
o.s.web.servlet.DispatcherServlet - Rendering view
[gov.va.med.edp.web.view.XmlView: name 'xmlView'] in DispatcherServlet
with name 'dispatcher'
10:29:22.341 [http-apr-8080-exec-6] DEBUG
gov.va.med.edp.web.view.XmlView - Rendering view with name 'xmlView'
with model {xmlFragment=<logEntries status='new' token='62490,44198' >
<log bed="CT" id="1" last4="T6123" name="TEST,ONE" same="0" seq="50"
ssn="856456123" />
<log bed="CATH" id="2" last4="T6124" name="TESTING,TESTING M M"
same="0" seq="70" ssn="445566124" />
<log bed="SCLIN" id="3" name="ZZ PATIENT,TEST TWO" same="0" seq="100" /
>
</logEntries>
} and static attributes {}
10:29:22.346 [http-apr-8080-exec-6] DEBUG
o.s.web.servlet.DispatcherServlet - Cleared thread-bound request
context:
org.springframework.security.wrapper.SavedRequestAwareWrapper@38cf0a88
10:29:22.347 [http-apr-8080-exec-6] DEBUG
o.s.web.servlet.DispatcherServlet - Successfully completed request
10:29:22.348 [http-apr-8080-exec-6] DEBUG
o.s.w.c.s.XmlWebApplicationContext - Publishing event in context
[org.springframework.web.context.support.XmlWebApplicationContext@414128f7]:
ServletRequestHandledEvent: url=[/main/tracking.xml];
client=[127.0.0.1]; method=[POST]; servlet=[dispatcher];
session=[6705BD29FA9A6170465037EE2BEB1CAE]; user=[93@999];
time=[4994ms]; status=[OK]
10:29:22.349 [http-apr-8080-exec-6] DEBUG
o.s.w.c.s.XmlWebApplicationContext - Publishing event in context
[org.springframework.web.context.support.XmlWebApplicationContext@282c1f9d]:
ServletRequestHandledEvent: url=[/main/tracking.xml];
client=[127.0.0.1]; method=[POST]; servlet=[dispatcher];
session=[6705BD29FA9A6170465037EE2BEB1CAE]; user=[93@999];
time=[4994ms]; status=[OK]
10:29:22.350 [http-apr-8080-exec-6] DEBUG
o.s.s.ui.ExceptionTranslationFilter - Chain processed normally
10:29:22.351 [http-apr-8080-exec-6] DEBUG
o.s.s.c.HttpSessionContextIntegrationFilter - SecurityContextHolder
now cleared, as request processing completed
10:29:47.658 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - Converted URL to lowercase, from:
'/tracking.xml'; to: '/tracking.xml'
10:29:47.659 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - Candidate is: '/tracking.xml';
pattern is /logout.html*; matched=false
10:29:47.660 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - Converted URL to lowercase, from:
'/tracking.xml'; to: '/tracking.xml'
10:29:47.660 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - Candidate is: '/tracking.xml';
pattern is /**; matched=true
10:29:47.661 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 1 of 7
in additional filter chain; firing Filter:
'org.springframework.security.context.HttpSessionContextIntegrationFilter[ order=200; ]'
10:29:47.662 [http-apr-8080-exec-8] DEBUG
o.s.s.c.HttpSessionContextIntegrationFilter - Obtained a valid
SecurityContext from SPRING_SECURITY_CONTEXT to associate with
SecurityContextHolder:
'org.springframework.security.context.SecurityContextImpl@46e50923:
Authentication:
gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER'
10:29:47.662 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 2 of 7
in additional filter chain; firing Filter:
'gov.va.med.edp.springframework.security.ui.vistalink.VistaAuthenticationProcessingFilter[ order=700; ]'
10:29:47.663 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 3 of 7
in additional filter chain; firing Filter:
'org.springframework.security.wrapper.SecurityContextHolderAwareRequestFilter[ order=1100; ]'
10:29:47.663 [http-apr-8080-exec-8] DEBUG
o.s.s.ui.savedrequest.SavedRequest - pathInfo: both null (property
equals)
10:29:47.665 [http-apr-8080-exec-8] DEBUG
o.s.s.ui.savedrequest.SavedRequest - queryString: both null (property
equals)
10:29:47.667 [http-apr-8080-exec-8] DEBUG
o.s.s.ui.savedrequest.SavedRequest - requestURI: arg1=/main/
tracking.html;jsessionid=6705BD29FA9A6170465037EE2BEB1CAE; arg2=/main/
tracking.xml (property not equals)
10:29:47.668 [http-apr-8080-exec-8] DEBUG
o.s.s.w.SavedRequestAwareWrapper - Wrapper not replaced; SavedRequest
was: SavedRequest[http://localhost:8080/main/tracking.html]
10:29:47.670 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 4 of 7
in additional filter chain; firing Filter:
'org.springframework.security.providers.anonymous.AnonymousProcessingFilter[ order=1300; ]'
10:29:47.672 [http-apr-8080-exec-8] DEBUG
o.s.s.p.a.AnonymousProcessingFilter - SecurityContextHolder not
populated with anonymous token, as it already contained:
'gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER'
10:29:47.673 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 5 of 7
in additional filter chain; firing Filter:
'org.springframework.security.ui.ExceptionTranslationFilter[ order=1400; ]'
10:29:47.678 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 6 of 7
in additional filter chain; firing Filter:
'org.springframework.security.ui.SessionFixationProtectionFilter[ order=1600; ]'
10:29:47.679 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 7 of 7
in additional filter chain; firing Filter:
'org.springframework.security.intercept.web.FilterSecurityInterceptor@a45ed31'
10:29:47.680 [http-apr-8080-exec-8] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Converted URL to
lowercase, from: '/tracking.xml'; to: '/tracking.xml'
10:29:47.682 [http-apr-8080-exec-8] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
tracking.xml'; pattern is /about.html; matched=false
10:29:47.683 [http-apr-8080-exec-8] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
tracking.xml'; pattern is /login.html*; matched=false
10:29:47.684 [http-apr-8080-exec-8] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
tracking.xml'; pattern is /**/*.swf; matched=false
10:29:47.685 [http-apr-8080-exec-8] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
tracking.xml'; pattern is /**/*.xml; matched=true
10:29:47.686 [http-apr-8080-exec-8] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Secure object: FilterInvocation:
URL: /tracking.xml; ConfigAttributes: [ROLE_USER]
10:29:47.686 [http-apr-8080-exec-8] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Previously Authenticated:
gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER
10:29:47.687 [http-apr-8080-exec-8] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Authorization successful
10:29:47.688 [http-apr-8080-exec-8] DEBUG
o.s.w.c.s.XmlWebApplicationContext - Publishing event in context
[org.springframework.web.context.support.XmlWebApplicationContext@282c1f9d]:
org.springframework.security.event.authorization.AuthorizedEvent[source=FilterInvocation:
URL: /tracking.xml]
10:29:47.688 [http-apr-8080-exec-8] DEBUG
o.s.s.i.AbstractSecurityInterceptor - RunAsManager did not change
Authentication object
10:29:47.689 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml reached end of
additional filter chain; proceeding with original chain
10:29:47.690 [http-apr-8080-exec-8] DEBUG
o.s.web.servlet.DispatcherServlet - DispatcherServlet with name
'dispatcher' received request for [/main/tracking.xml]
10:29:47.691 [http-apr-8080-exec-8] DEBUG
o.s.web.servlet.DispatcherServlet - Bound request context to thread:
org.springframework.security.wrapper.SavedRequestAwareWrapper@7d1ee2fc
10:29:47.691 [http-apr-8080-exec-8] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler map
[org.springframework.web.servlet.handler.BeanNameUrlHandlerMapping@20d37520]
in DispatcherServlet with name 'dispatcher'
10:29:47.692 [http-apr-8080-exec-8] DEBUG
o.s.w.s.h.BeanNameUrlHandlerMapping - Looking up handler for [/
tracking.xml]
10:29:47.693 [http-apr-8080-exec-8] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler adapter
[org.springframework.web.servlet.mvc.HttpRequestHandlerAdapter@1aae98b6]
10:29:47.694 [http-apr-8080-exec-8] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler adapter
[org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter@6d84f7a0]
10:29:47.695 [http-apr-8080-exec-8] DEBUG
o.s.b.f.s.DefaultListableBeanFactory - Returning cached instance of
singleton bean 'vljConnector999'
10:29:47.696 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkConnectionRequestInfo - Constructing request info
10:29:47.696 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkConnectionManager - allocating connection
10:29:47.697 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionFactory -
gov.va.med.edp.vistalink.adapter.spi.VistaLinkManagedConnectionFactory[]10.10.0.124[]8011[]1[adapterversion]1.5.0.026[]J2EE[fdi]1
Creating Managed connection->7
10:29:47.698 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=[Not Set]
Constructing
10:29:47.699 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkConnectionEventNotifier - Constructing
10:29:47.701 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=[Not Set]
Executing Init Socket interaction
10:29:47.702 [http-apr-8080-exec-8] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@76c84e90
10:29:47.704 [http-apr-8080-exec-8] DEBUG gov.va.med.xml.XmlUtilities
- XPath /VistaLink/Request returned 1nodes.
10:29:47.704 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=[Not Set]
Executing interaction
10:29:47.705 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=[Not Set]
Executing transfer with time out of 5000
10:29:48.746 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->234
10:29:48.948 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->121
10:29:48.948 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->Got EOT->121
10:29:48.949 [http-apr-8080-exec-8] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1243
10:29:48.950 [http-apr-8080-exec-8] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@589e0cdc
10:29:48.951 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponseFactory - got response
attributes
10:29:48.952 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponseFactory - Retrieved Initial
Socket Response:
heartbeat rate = 604800000
M $JOB = 12719
Reauth session Timeout = 3600000
10:29:48.952 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponse - initSocket response
constructed[]604800000
10:29:48.953 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=[Not Set]
Heartbeat rate set successfully[]604800000
10:29:48.953 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
M $JOB set successfully[]12719
10:29:48.955 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Setting up authentication
10:29:48.956 [http-apr-8080-exec-8] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - -> sending AV.SetupAndIntroText
10:29:48.957 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Executing interaction
10:29:48.958 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Executing transfer with time out of 5000
10:29:49.978 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->231
10:29:49.979 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->512
10:29:49.980 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->512
10:29:49.982 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->512
10:29:49.982 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->512
10:29:49.983 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->512
10:29:49.984 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->512
10:29:49.985 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->512
10:29:49.987 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->512
10:29:49.987 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->430
10:29:49.988 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->Got EOT->430
10:29:49.990 [http-apr-8080-exec-8] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1032
10:29:49.991 [http-apr-8080-exec-8] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@474405c3
10:29:49.994 [http-apr-8080-exec-8] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - Result: 1
10:29:49.995 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
executing first phase logon
10:29:49.996 [http-apr-8080-exec-8] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - -> sending AV.Logon
10:29:49.997 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Executing interaction
10:29:49.998 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Executing transfer with time out of 5000
10:29:50.085 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - Converted URL to lowercase, from:
'/board.xml'; to: '/board.xml'
10:29:50.086 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - Candidate is: '/board.xml';
pattern is /logout.html*; matched=false
10:29:50.089 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - Converted URL to lowercase, from:
'/board.xml'; to: '/board.xml'
10:29:50.089 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - Candidate is: '/board.xml';
pattern is /**; matched=true
10:29:50.089 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 1 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.context.HttpSessionContextIntegrationFilter[ order=200; ]'
10:29:50.090 [http-apr-8080-exec-10] DEBUG
o.s.s.c.HttpSessionContextIntegrationFilter - Obtained a valid
SecurityContext from SPRING_SECURITY_CONTEXT to associate with
SecurityContextHolder:
'org.springframework.security.context.SecurityContextImpl@46e50923:
Authentication:
gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER'
10:29:50.091 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 2 of 7 in
additional filter chain; firing Filter:
'gov.va.med.edp.springframework.security.ui.vistalink.VistaAuthenticationProcessingFilter[ order=700; ]'
10:29:50.091 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 3 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.wrapper.SecurityContextHolderAwareRequestFilter[ order=1100; ]'
10:29:50.092 [http-apr-8080-exec-10] DEBUG
o.s.s.ui.savedrequest.SavedRequest - pathInfo: both null (property
equals)
10:29:50.092 [http-apr-8080-exec-10] DEBUG
o.s.s.ui.savedrequest.SavedRequest - queryString: both null (property
equals)
10:29:50.093 [http-apr-8080-exec-10] DEBUG
o.s.s.ui.savedrequest.SavedRequest - requestURI: arg1=/main/
tracking.html;jsessionid=6705BD29FA9A6170465037EE2BEB1CAE; arg2=/main/
board.xml (property not equals)
10:29:50.093 [http-apr-8080-exec-10] DEBUG
o.s.s.w.SavedRequestAwareWrapper - Wrapper not replaced; SavedRequest
was: SavedRequest[http://localhost:8080/main/tracking.html]
10:29:50.094 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 4 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.providers.anonymous.AnonymousProcessingFilter[ order=1300; ]'
10:29:50.094 [http-apr-8080-exec-10] DEBUG
o.s.s.p.a.AnonymousProcessingFilter - SecurityContextHolder not
populated with anonymous token, as it already contained:
'gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER'
10:29:50.095 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 5 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.ui.ExceptionTranslationFilter[ order=1400; ]'
10:29:50.095 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 6 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.ui.SessionFixationProtectionFilter[ order=1600; ]'
10:29:50.095 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 7 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.intercept.web.FilterSecurityInterceptor@a45ed31'
10:29:50.096 [http-apr-8080-exec-10] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Converted URL to
lowercase, from: '/board.xml'; to: '/board.xml'
10:29:50.096 [http-apr-8080-exec-10] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
board.xml'; pattern is /about.html; matched=false
10:29:50.097 [http-apr-8080-exec-10] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
board.xml'; pattern is /login.html*; matched=false
10:29:50.097 [http-apr-8080-exec-10] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
board.xml'; pattern is /**/*.swf; matched=false
10:29:50.097 [http-apr-8080-exec-10] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
board.xml'; pattern is /**/*.xml; matched=true
10:29:50.097 [http-apr-8080-exec-10] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Secure object: FilterInvocation:
URL: /board.xml; ConfigAttributes: [ROLE_USER]
10:29:50.097 [http-apr-8080-exec-10] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Previously Authenticated:
gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER
10:29:50.097 [http-apr-8080-exec-10] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Authorization successful
10:29:50.098 [http-apr-8080-exec-10] DEBUG
o.s.w.c.s.XmlWebApplicationContext - Publishing event in context
[org.springframework.web.context.support.XmlWebApplicationContext@282c1f9d]:
org.springframework.security.event.authorization.AuthorizedEvent[source=FilterInvocation:
URL: /board.xml]
10:29:50.098 [http-apr-8080-exec-10] DEBUG
o.s.s.i.AbstractSecurityInterceptor - RunAsManager did not change
Authentication object
10:29:50.098 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - /board.xml reached end of
additional filter chain; proceeding with original chain
10:29:50.098 [http-apr-8080-exec-10] DEBUG
o.s.web.servlet.DispatcherServlet - DispatcherServlet with name
'dispatcher' received request for [/main/board.xml]
10:29:50.103 [http-apr-8080-exec-10] DEBUG
o.s.web.servlet.DispatcherServlet - Bound request context to thread:
org.springframework.security.wrapper.SavedRequestAwareWrapper@42fcb590
10:29:50.103 [http-apr-8080-exec-10] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler map
[org.springframework.web.servlet.handler.BeanNameUrlHandlerMapping@20d37520]
in DispatcherServlet with name 'dispatcher'
10:29:50.104 [http-apr-8080-exec-10] DEBUG
o.s.w.s.h.BeanNameUrlHandlerMapping - Looking up handler for [/
board.xml]
10:29:50.105 [http-apr-8080-exec-10] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler adapter
[org.springframework.web.servlet.mvc.HttpRequestHandlerAdapter@1aae98b6]
10:29:50.105 [http-apr-8080-exec-10] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler adapter
[org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter@6d84f7a0]
10:29:50.106 [http-apr-8080-exec-10] DEBUG
o.s.b.f.s.DefaultListableBeanFactory - Returning cached instance of
singleton bean 'vljConnector999'
10:29:50.106 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkConnectionRequestInfo - Constructing request info
10:29:50.107 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkConnectionManager - allocating connection
10:29:50.107 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionFactory -
gov.va.med.edp.vistalink.adapter.spi.VistaLinkManagedConnectionFactory[]10.10.0.124[]8011[]1[adapterversion]1.5.0.026[]J2EE[fdi]1
Creating Managed connection->8
10:29:50.108 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=[Not Set]
Constructing
10:29:50.109 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkConnectionEventNotifier - Constructing
10:29:50.089 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - Converted URL to lowercase, from:
'/board.xml'; to: '/board.xml'
10:29:50.110 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - Candidate is: '/board.xml';
pattern is /logout.html*; matched=false
10:29:50.111 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - Converted URL to lowercase, from:
'/board.xml'; to: '/board.xml'
10:29:50.112 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - Candidate is: '/board.xml';
pattern is /**; matched=true
10:29:50.113 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=[Not Set]
Executing Init Socket interaction
10:29:50.116 [http-apr-8080-exec-10] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@5cf4234b
10:29:50.118 [http-apr-8080-exec-10] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilder implementation:
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderImpl
10:29:50.119 [http-apr-8080-exec-10] DEBUG gov.va.med.xml.XmlUtilities
- XPath /VistaLink/Request returned 1nodes.
10:29:50.120 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=[Not Set]
Executing interaction
10:29:50.124 [http-apr-8080-exec-10] DEBUG gov.va.med.xml.XmlUtilities
- Using Transformer implementation:
com.sun.org.apache.xalan.internal.xsltc.trax.TransformerImpl
10:29:50.129 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=[Not Set]
Executing transfer with time out of 5000
10:29:50.114 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 1 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.context.HttpSessionContextIntegrationFilter[ order=200; ]'
10:29:50.131 [http-apr-8080-exec-3] DEBUG
o.s.s.c.HttpSessionContextIntegrationFilter - Obtained a valid
SecurityContext from SPRING_SECURITY_CONTEXT to associate with
SecurityContextHolder:
'org.springframework.security.context.SecurityContextImpl@46e50923:
Authentication:
gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER'
10:29:50.132 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 2 of 7 in
additional filter chain; firing Filter:
'gov.va.med.edp.springframework.security.ui.vistalink.VistaAuthenticationProcessingFilter[ order=700; ]'
10:29:50.132 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 3 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.wrapper.SecurityContextHolderAwareRequestFilter[ order=1100; ]'
10:29:50.133 [http-apr-8080-exec-3] DEBUG
o.s.s.ui.savedrequest.SavedRequest - pathInfo: both null (property
equals)
10:29:50.133 [http-apr-8080-exec-3] DEBUG
o.s.s.ui.savedrequest.SavedRequest - queryString: both null (property
equals)
10:29:50.133 [http-apr-8080-exec-3] DEBUG
o.s.s.ui.savedrequest.SavedRequest - requestURI: arg1=/main/
tracking.html;jsessionid=6705BD29FA9A6170465037EE2BEB1CAE; arg2=/main/
board.xml (property not equals)
10:29:50.134 [http-apr-8080-exec-3] DEBUG
o.s.s.w.SavedRequestAwareWrapper - Wrapper not replaced; SavedRequest
was: SavedRequest[http://localhost:8080/main/tracking.html]
10:29:50.134 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 4 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.providers.anonymous.AnonymousProcessingFilter[ order=1300; ]'
10:29:50.135 [http-apr-8080-exec-3] DEBUG
o.s.s.p.a.AnonymousProcessingFilter - SecurityContextHolder not
populated with anonymous token, as it already contained:
'gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER'
10:29:50.135 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 5 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.ui.ExceptionTranslationFilter[ order=1400; ]'
10:29:50.136 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 6 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.ui.SessionFixationProtectionFilter[ order=1600; ]'
10:29:50.136 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 7 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.intercept.web.FilterSecurityInterceptor@a45ed31'
10:29:50.137 [http-apr-8080-exec-3] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Converted URL to
lowercase, from: '/board.xml'; to: '/board.xml'
10:29:50.137 [http-apr-8080-exec-3] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
board.xml'; pattern is /about.html; matched=false
10:29:50.137 [http-apr-8080-exec-3] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
board.xml'; pattern is /login.html*; matched=false
10:29:50.138 [http-apr-8080-exec-3] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
board.xml'; pattern is /**/*.swf; matched=false
10:29:50.138 [http-apr-8080-exec-3] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
board.xml'; pattern is /**/*.xml; matched=true
10:29:50.139 [http-apr-8080-exec-3] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Secure object: FilterInvocation:
URL: /board.xml; ConfigAttributes: [ROLE_USER]
10:29:50.139 [http-apr-8080-exec-3] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Previously Authenticated:
gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER
10:29:50.139 [http-apr-8080-exec-3] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Authorization successful
10:29:50.140 [http-apr-8080-exec-3] DEBUG
o.s.w.c.s.XmlWebApplicationContext - Publishing event in context
[org.springframework.web.context.support.XmlWebApplicationContext@282c1f9d]:
org.springframework.security.event.authorization.AuthorizedEvent[source=FilterInvocation:
URL: /board.xml]
10:29:50.140 [http-apr-8080-exec-3] DEBUG
o.s.s.i.AbstractSecurityInterceptor - RunAsManager did not change
Authentication object
10:29:50.141 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - /board.xml reached end of
additional filter chain; proceeding with original chain
10:29:50.141 [http-apr-8080-exec-3] DEBUG
o.s.web.servlet.DispatcherServlet - DispatcherServlet with name
'dispatcher' received request for [/main/board.xml]
10:29:50.142 [http-apr-8080-exec-3] DEBUG
o.s.web.servlet.DispatcherServlet - Bound request context to thread:
org.springframework.security.wrapper.SavedRequestAwareWrapper@2039409a
10:29:50.142 [http-apr-8080-exec-3] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler map
[org.springframework.web.servlet.handler.BeanNameUrlHandlerMapping@20d37520]
in DispatcherServlet with name 'dispatcher'
10:29:50.142 [http-apr-8080-exec-3] DEBUG
o.s.w.s.h.BeanNameUrlHandlerMapping - Looking up handler for [/
board.xml]
10:29:50.143 [http-apr-8080-exec-3] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler adapter
[org.springframework.web.servlet.mvc.HttpRequestHandlerAdapter@1aae98b6]
10:29:50.143 [http-apr-8080-exec-3] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler adapter
[org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter@6d84f7a0]
10:29:50.144 [http-apr-8080-exec-3] DEBUG
o.s.b.f.s.DefaultListableBeanFactory - Returning cached instance of
singleton bean 'vljConnector999'
10:29:50.144 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkConnectionRequestInfo - Constructing request info
10:29:50.145 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkConnectionManager - allocating connection
10:29:50.145 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionFactory -
gov.va.med.edp.vistalink.adapter.spi.VistaLinkManagedConnectionFactory[]10.10.0.124[]8011[]1[adapterversion]1.5.0.026[]J2EE[fdi]1
Creating Managed connection->9
10:29:50.146 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
M $JOB=[Not Set]
Constructing
10:29:50.146 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkConnectionEventNotifier - Constructing
10:29:50.648 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
M $JOB=[Not Set]
Executing Init Socket interaction
10:29:50.649 [http-apr-8080-exec-3] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@ec04efd
10:29:50.653 [http-apr-8080-exec-3] DEBUG gov.va.med.xml.XmlUtilities
- XPath /VistaLink/Request returned 1nodes.
10:29:50.653 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
M $JOB=[Not Set]
Executing interaction
10:29:50.656 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
M $JOB=[Not Set]
Executing transfer with time out of 5000
10:29:51.020 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->226
10:29:51.145 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->234
10:29:51.222 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->130
10:29:51.223 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->Got EOT->130
10:29:51.223 [http-apr-8080-exec-8] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1225
10:29:51.224 [http-apr-8080-exec-8] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@4e5e685b
10:29:51.226 [http-apr-8080-exec-8] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - Result: 1
10:29:51.226 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Added managedconnection to Heartbeat TimerTask
10:29:51.227 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionFactory -
gov.va.med.edp.vistalink.adapter.spi.VistaLinkManagedConnectionFactory[]10.10.0.124[]8011[]1[adapterversion]1.5.0.026[]J2EE[fdi]1
Created Managed connection->7
10:29:51.227 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
addConnectionEventListener
10:29:51.228 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkConnectionEventNotifier -
addConnectionEventListener
10:29:51.229 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Getting connection handle
10:29:51.229 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Connection handle available
10:29:51.230 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Connection re-authentication status: 'notauthenticated'. cri =
Con Req Info is null
10:29:51.230 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
addConHandle
10:29:51.231 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionFactory - elapsedMillis to add:
2
10:29:51.232 [http-apr-8080-exec-8] INFO
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
getConnection(...) processing time = 2
10:29:51.232 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection - About to execute RPC:
'EDPCTRL RPC', on connector configured with JNDI name: '',
primaryStation: '999', reauthentication type: 'duz', credentials:
'93'.
10:29:51.233 [http-apr-8080-exec-8] DEBUG
gov.va.med.vistalink.rpc.RpcRequest - Setting re-authentication
information
10:29:51.234 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Executing interaction
10:29:51.237 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Executing transfer with time out of 10000
10:29:51.245 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->216
10:29:51.346 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->121
10:29:51.347 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->Got EOT->121
10:29:51.349 [http-apr-8080-exec-10] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1219
10:29:51.352 [http-apr-8080-exec-10] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@17b5a325
10:29:51.355 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponseFactory - got response
attributes
10:29:51.355 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponseFactory - Retrieved Initial
Socket Response:
heartbeat rate = 604800000
M $JOB = 12749
Reauth session Timeout = 3600000
10:29:51.359 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponse - initSocket response
constructed[]604800000
10:29:51.360 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=[Not Set]
Heartbeat rate set successfully[]604800000
10:29:51.361 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=12749
M $JOB set successfully[]12749
10:29:51.363 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=12749
Setting up authentication
10:29:51.371 [http-apr-8080-exec-10] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - -> sending AV.SetupAndIntroText
10:29:51.372 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=12749
Executing interaction
10:29:51.374 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=12749
Executing transfer with time out of 5000
10:29:51.453 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->512
10:29:51.454 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->405
10:29:51.456 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->Got EOT->405
10:29:51.457 [http-apr-8080-exec-8] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 220
10:29:51.459 [http-apr-8080-exec-8] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@2d015ad1
10:29:51.462 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection - Completed execution of RPC:
EDPCTRL RPC
10:29:51.463 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Closing handle
10:29:51.465 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
removeConHandle
10:29:51.467 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkConnectionEventNotifier - Connection closed
10:29:51.468 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Destroying managed connection
10:29:51.470 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
removed managedconnection to Heartbeat TimerTask
10:29:51.471 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Executing logout
10:29:51.476 [http-apr-8080-exec-8] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - -> sending AV.Logout
10:29:51.477 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Executing interaction
10:29:51.480 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Executing transfer with time out of 5000
10:29:51.680 [http-apr-8080-exec-3] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
read data->234
10:29:51.884 [http-apr-8080-exec-3] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
read data->121
10:29:51.885 [http-apr-8080-exec-3] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
read data->Got EOT->121
10:29:51.887 [http-apr-8080-exec-3] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1230
10:29:51.889 [http-apr-8080-exec-3] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@2d7b5718
10:29:51.893 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponseFactory - got response
attributes
10:29:51.894 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponseFactory - Retrieved Initial
Socket Response:
heartbeat rate = 604800000
M $JOB = 12765
Reauth session Timeout = 3600000
10:29:51.895 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponse - initSocket response
constructed[]604800000
10:29:51.897 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
M $JOB=[Not Set]
Heartbeat rate set successfully[]604800000
10:29:51.898 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
M $JOB=12765
M $JOB set successfully[]12765
10:29:51.900 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
M $JOB=12765
Setting up authentication
10:29:51.905 [http-apr-8080-exec-3] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - -> sending AV.SetupAndIntroText
10:29:51.906 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
M $JOB=12765
Executing interaction
10:29:51.908 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
M $JOB=12765
Executing transfer with time out of 5000
10:29:52.392 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->231
10:29:52.393 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->512
10:29:52.395 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->512
10:29:52.397 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->512
10:29:52.398 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->512
10:29:52.402 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->512
10:29:52.405 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->512
10:29:52.405 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->512
10:29:52.407 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->512
10:29:52.409 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->430
10:29:52.410 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->Got EOT->430
10:29:52.412 [http-apr-8080-exec-10] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1038
10:29:52.413 [http-apr-8080-exec-10] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@16e3f7a2
10:29:52.419 [http-apr-8080-exec-10] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - Result: 1
10:29:52.422 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=12749
executing first phase logon
10:29:52.425 [http-apr-8080-exec-10] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - -> sending AV.Logon
10:29:52.425 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=12749
Executing interaction
10:29:52.427 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=12749
Executing transfer with time out of 5000
10:29:52.494 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->227
10:29:52.696 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->98
10:29:52.698 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->Got EOT->98
10:29:52.699 [http-apr-8080-exec-8] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1218
10:29:52.702 [http-apr-8080-exec-8] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@450be552
10:29:52.708 [http-apr-8080-exec-8] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - Result: 1
10:29:52.709 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Socket has been successfully closed
10:29:52.710 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionEventListener -
VistaLinkManagedConnection destroyed via close() event and
VistaLinkManagedConnectionEventListener
10:29:52.713 [http-apr-8080-exec-8] DEBUG
o.s.web.servlet.DispatcherServlet - Rendering view
[gov.va.med.edp.web.view.XmlView: name 'xmlView'] in DispatcherServlet
with name 'dispatcher'
10:29:52.715 [http-apr-8080-exec-8] DEBUG
gov.va.med.edp.web.view.XmlView - Rendering view with name 'xmlView'
with model {xmlFragment=<logEntries status='new' token='62490,44198' >
<log bed="CT" id="1" last4="T6123" name="TEST,ONE" same="0" seq="50"
ssn="856456123" />
<log bed="CATH" id="2" last4="T6124" name="TESTING,TESTING M M"
same="0" seq="70" ssn="445566124" />
<log bed="SCLIN" id="3" name="ZZ PATIENT,TEST TWO" same="0" seq="100" /
>
</logEntries>
} and static attributes {}
Regards,
Srikant
On Feb 5, 1:43 pm, Wasim Naffar <w0795930...@gmail.com> wrote:
> oohh, do you mean only the application server's console or the Debug item
> on the EDIS??!!
>
>
>
>
>
>
>
> On Sun, Feb 5, 2012 at 10:40 AM, Wasim Naffar <w0795930...@gmail.com> wrote:
> > Hi Srikant,
> > I guess the debug working on VistALink 1.6, already i run EDIS on
> > VistALink 1.5 and i never seen the debug item on the EDIS viewer, and i
> > have never use it, just i found it on the screenshots and EDIS manuals.
> > Anyway, i will try to find if there is a key or an option given to the
> > user!! maybe that is the case!!
>
> > Regards,
> > Wasim
>
Yes, the Debug logger are there in the Application Server console.
Some sample debug lines are as follows:
10:28:52.269 [http-apr-8080-exec-5] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionEventListener -
VistaLinkManagedConnection destroyed via close() event and
VistaLinkManagedConnectionEventListener
10:28:52.270 [http-apr-8080-exec-5] DEBUG
o.s.web.servlet.DispatcherServlet - Rendering view
[gov.va.med.edp.web.view.XmlView: name 'xmlView'] in DispatcherServlet
with name 'dispatcher'
10:28:52.271 [http-apr-8080-exec-5] DEBUG
gov.va.med.edp.web.view.XmlView - Rendering view with name 'xmlView'
with model {xmlFragment=<params clinics="0" codedDiag="1"
emptyIEN="46" errorIEN="7" evalIEN="44" leftIEN="37" minDelay="300"
reqDelay="1" reqDiag="1" reqDisp="1" residents="1" />
<logEntries status='new' token='62490,44198' >
<log bed="CT" id="1" last4="T6123" name="TEST,ONE" same="0" seq="50"
ssn="856456123" />
<log bed="CATH" id="2" last4="T6124" name="TESTING,TESTING M M"
same="0" seq="70" ssn="445566124" />
<log bed="SCLIN" id="3" name="ZZ PATIENT,TEST TWO" same="0" seq="100" /
>
</logEntries>
} and static attributes {}
10:28:52.273 [http-apr-8080-exec-5] DEBUG
o.s.web.servlet.DispatcherServlet - Cleared thread-bound request
context:
org.springframework.security.wrapper.SavedRequestAwareWrapper@4da3dc1d
10:28:52.276 [http-apr-8080-exec-5] DEBUG
o.s.web.servlet.DispatcherServlet - Successfully completed request
10:28:52.277 [http-apr-8080-exec-5] DEBUG
o.s.w.c.s.XmlWebApplicationContext - Publishing event in context
[org.springframework.web.context.support.XmlWebApplicationContext@414128f7]:
ServletRequestHandledEvent: url=[/main/tracking.xml];
client=[127.0.0.1]; method=[POST]; servlet=[dispatcher];
session=[6705BD29FA9A6170465037EE2BEB1CAE]; user=[93@999];
time=[4942ms]; status=[OK]
10:28:52.277 [http-apr-8080-exec-5] DEBUG
o.s.w.c.s.XmlWebApplicationContext - Publishing event in context
[org.springframework.web.context.support.XmlWebApplicationContext@282c1f9d]:
ServletRequestHandledEvent: url=[/main/tracking.xml];
client=[127.0.0.1]; method=[POST]; servlet=[dispatcher];
session=[6705BD29FA9A6170465037EE2BEB1CAE]; user=[93@999];
time=[4942ms]; status=[OK]
10:28:52.278 [http-apr-8080-exec-5] DEBUG
o.s.s.ui.ExceptionTranslationFilter - Chain processed normally
10:28:52.279 [http-apr-8080-exec-5] DEBUG
o.s.s.c.HttpSessionContextIntegrationFilter - SecurityContextHolder
now cleared, as request processing completed
10:29:17.340 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - Converted URL to lowercase, from:
'/tracking.xml'; to: '/tracking.xml'
10:29:17.341 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - Candidate is: '/tracking.xml';
pattern is /logout.html*; matched=false
10:29:17.341 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - Converted URL to lowercase, from:
'/tracking.xml'; to: '/tracking.xml'
10:29:17.342 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - Candidate is: '/tracking.xml';
pattern is /**; matched=true
10:29:17.343 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 1 of 7
in additional filter chain; firing Filter:
'org.springframework.security.context.HttpSessionContextIntegrationFilter[ order=200; ]'
10:29:17.343 [http-apr-8080-exec-6] DEBUG
o.s.s.c.HttpSessionContextIntegrationFilter - Obtained a valid
SecurityContext from SPRING_SECURITY_CONTEXT to associate with
SecurityContextHolder:
'org.springframework.security.context.SecurityContextImpl@46e50923:
Authentication:
gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER'
10:29:17.343 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 2 of 7
in additional filter chain; firing Filter:
'gov.va.med.edp.springframework.security.ui.vistalink.VistaAuthenticationProcessingFilter[ order=700; ]'
10:29:17.344 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 3 of 7
in additional filter chain; firing Filter:
'org.springframework.security.wrapper.SecurityContextHolderAwareRequestFilter[ order=1100; ]'
10:29:17.344 [http-apr-8080-exec-6] DEBUG
o.s.s.ui.savedrequest.SavedRequest - pathInfo: both null (property
equals)
10:29:17.345 [http-apr-8080-exec-6] DEBUG
o.s.s.ui.savedrequest.SavedRequest - queryString: both null (property
equals)
10:29:17.345 [http-apr-8080-exec-6] DEBUG
o.s.s.ui.savedrequest.SavedRequest - requestURI: arg1=/main/
tracking.html;jsessionid=6705BD29FA9A6170465037EE2BEB1CAE; arg2=/main/
tracking.xml (property not equals)
10:29:17.346 [http-apr-8080-exec-6] DEBUG
o.s.s.w.SavedRequestAwareWrapper - Wrapper not replaced; SavedRequest
was: SavedRequest[http://localhost:8080/main/tracking.html]
10:29:17.346 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 4 of 7
in additional filter chain; firing Filter:
'org.springframework.security.providers.anonymous.AnonymousProcessingFilter[ order=1300; ]'
10:29:17.347 [http-apr-8080-exec-6] DEBUG
o.s.s.p.a.AnonymousProcessingFilter - SecurityContextHolder not
populated with anonymous token, as it already contained:
'gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER'
10:29:17.347 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 5 of 7
in additional filter chain; firing Filter:
'org.springframework.security.ui.ExceptionTranslationFilter[ order=1400; ]'
10:29:17.348 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 6 of 7
in additional filter chain; firing Filter:
'org.springframework.security.ui.SessionFixationProtectionFilter[ order=1600; ]'
10:29:17.348 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 7 of 7
in additional filter chain; firing Filter:
'org.springframework.security.intercept.web.FilterSecurityInterceptor@a45ed31'
10:29:17.349 [http-apr-8080-exec-6] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Converted URL to
lowercase, from: '/tracking.xml'; to: '/tracking.xml'
10:29:17.349 [http-apr-8080-exec-6] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
tracking.xml'; pattern is /about.html; matched=false
10:29:17.350 [http-apr-8080-exec-6] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
tracking.xml'; pattern is /login.html*; matched=false
10:29:17.350 [http-apr-8080-exec-6] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
tracking.xml'; pattern is /**/*.swf; matched=false
10:29:17.351 [http-apr-8080-exec-6] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
tracking.xml'; pattern is /**/*.xml; matched=true
10:29:17.351 [http-apr-8080-exec-6] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Secure object: FilterInvocation:
URL: /tracking.xml; ConfigAttributes: [ROLE_USER]
10:29:17.352 [http-apr-8080-exec-6] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Previously Authenticated:
gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER
10:29:17.352 [http-apr-8080-exec-6] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Authorization successful
10:29:17.353 [http-apr-8080-exec-6] DEBUG
o.s.w.c.s.XmlWebApplicationContext - Publishing event in context
[org.springframework.web.context.support.XmlWebApplicationContext@282c1f9d]:
org.springframework.security.event.authorization.AuthorizedEvent[source=FilterInvocation:
URL: /tracking.xml]
10:29:17.353 [http-apr-8080-exec-6] DEBUG
o.s.s.i.AbstractSecurityInterceptor - RunAsManager did not change
Authentication object
10:29:17.354 [http-apr-8080-exec-6] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml reached end of
additional filter chain; proceeding with original chain
10:29:17.354 [http-apr-8080-exec-6] DEBUG
o.s.web.servlet.DispatcherServlet - DispatcherServlet with name
'dispatcher' received request for [/main/tracking.xml]
10:29:17.354 [http-apr-8080-exec-6] DEBUG
o.s.web.servlet.DispatcherServlet - Bound request context to thread:
org.springframework.security.wrapper.SavedRequestAwareWrapper@38cf0a88
10:29:17.355 [http-apr-8080-exec-6] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler map
[org.springframework.web.servlet.handler.BeanNameUrlHandlerMapping@20d37520]
in DispatcherServlet with name 'dispatcher'
10:29:17.355 [http-apr-8080-exec-6] DEBUG
o.s.w.s.h.BeanNameUrlHandlerMapping - Looking up handler for [/
tracking.xml]
10:29:17.355 [http-apr-8080-exec-6] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler adapter
[org.springframework.web.servlet.mvc.HttpRequestHandlerAdapter@1aae98b6]
10:29:17.355 [http-apr-8080-exec-6] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler adapter
[org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter@6d84f7a0]
10:29:17.356 [http-apr-8080-exec-6] DEBUG
o.s.b.f.s.DefaultListableBeanFactory - Returning cached instance of
singleton bean 'vljConnector999'
10:29:17.356 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkConnectionRequestInfo - Constructing request info
10:29:17.356 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkConnectionManager - allocating connection
10:29:17.356 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionFactory -
gov.va.med.edp.vistalink.adapter.spi.VistaLinkManagedConnectionFactory[]10.10.0.124[]8011[]1[adapterversion]1.5.0.026[]J2EE[fdi]1
Creating Managed connection->6
10:29:17.356 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=[Not Set]
Constructing
10:29:17.357 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkConnectionEventNotifier - Constructing
10:29:17.359 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=[Not Set]
Executing Init Socket interaction
10:29:17.359 [http-apr-8080-exec-6] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@20bc83db
10:29:17.360 [http-apr-8080-exec-6] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilder implementation:
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderImpl
10:29:17.361 [http-apr-8080-exec-6] DEBUG gov.va.med.xml.XmlUtilities
- XPath /VistaLink/Request returned 1nodes.
10:29:17.361 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=[Not Set]
Executing interaction
10:29:17.361 [http-apr-8080-exec-6] DEBUG gov.va.med.xml.XmlUtilities
- Using Transformer implementation:
com.sun.org.apache.xalan.internal.xsltc.trax.TransformerImpl
10:29:17.362 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=[Not Set]
Executing transfer with time out of 5000
10:29:18.398 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->234
10:29:18.600 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->121
10:29:18.600 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->Got EOT->121
10:29:18.601 [http-apr-8080-exec-6] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1239
10:29:18.602 [http-apr-8080-exec-6] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@3874afa7
10:29:18.604 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponseFactory - got response
attributes
10:29:18.605 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponseFactory - Retrieved Initial
Socket Response:
heartbeat rate = 604800000
M $JOB = 12646
Reauth session Timeout = 3600000
10:29:18.605 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponse - initSocket response
constructed[]604800000
10:29:18.606 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=[Not Set]
Heartbeat rate set successfully[]604800000
10:29:18.606 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
M $JOB set successfully[]12646
10:29:18.607 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Setting up authentication
10:29:18.610 [http-apr-8080-exec-6] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - -> sending AV.SetupAndIntroText
10:29:18.611 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Executing interaction
10:29:18.612 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Executing transfer with time out of 5000
10:29:19.624 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->231
10:29:19.626 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->512
10:29:19.626 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->512
10:29:19.627 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->512
10:29:19.628 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->512
10:29:19.629 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->512
10:29:19.629 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->512
10:29:19.631 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->512
10:29:19.631 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->512
10:29:19.632 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->430
10:29:19.632 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->Got EOT->430
10:29:19.633 [http-apr-8080-exec-6] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1020
10:29:19.633 [http-apr-8080-exec-6] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@62ac4540
10:29:19.638 [http-apr-8080-exec-6] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - Result: 1
10:29:19.639 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
executing first phase logon
10:29:19.642 [http-apr-8080-exec-6] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - -> sending AV.Logon
10:29:19.642 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Executing interaction
10:29:19.644 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Executing transfer with time out of 5000
10:29:20.664 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->226
10:29:20.865 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->130
10:29:20.866 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->Got EOT->130
10:29:20.867 [http-apr-8080-exec-6] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1222
10:29:20.868 [http-apr-8080-exec-6] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@36cdc2b3
10:29:20.872 [http-apr-8080-exec-6] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - Result: 1
10:29:20.873 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Added managedconnection to Heartbeat TimerTask
10:29:20.874 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionFactory -
gov.va.med.edp.vistalink.adapter.spi.VistaLinkManagedConnectionFactory[]10.10.0.124[]8011[]1[adapterversion]1.5.0.026[]J2EE[fdi]1
Created Managed connection->6
10:29:20.882 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
addConnectionEventListener
10:29:20.882 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkConnectionEventNotifier -
addConnectionEventListener
10:29:20.883 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Getting connection handle
10:29:20.884 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Connection handle available
10:29:20.884 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Connection re-authentication status: 'notauthenticated'. cri =
Con Req Info is null
10:29:20.885 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
addConHandle
10:29:20.885 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionFactory - elapsedMillis to add:
2
10:29:20.886 [http-apr-8080-exec-6] INFO
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
getConnection(...) processing time = 2
10:29:20.886 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection - About to execute RPC:
'EDPCTRL RPC', on connector configured with JNDI name: '',
primaryStation: '999', reauthentication type: 'duz', credentials:
'93'.
10:29:20.887 [http-apr-8080-exec-6] DEBUG
gov.va.med.vistalink.rpc.RpcRequest - Setting re-authentication
information
10:29:20.888 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Executing interaction
10:29:20.889 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Executing transfer with time out of 10000
10:29:20.898 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->216
10:29:21.097 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->512
10:29:21.097 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->405
10:29:21.098 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->Got EOT->405
10:29:21.098 [http-apr-8080-exec-6] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 208
10:29:21.099 [http-apr-8080-exec-6] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@38be7bc0
10:29:21.101 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection - Completed execution of RPC:
EDPCTRL RPC
10:29:21.101 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Closing handle
10:29:21.102 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
removeConHandle
10:29:21.102 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkConnectionEventNotifier - Connection closed
10:29:21.104 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Destroying managed connection
10:29:21.105 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
removed managedconnection to Heartbeat TimerTask
10:29:21.106 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Executing logout
10:29:21.109 [http-apr-8080-exec-6] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - -> sending AV.Logout
10:29:21.110 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Executing interaction
10:29:21.111 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Executing transfer with time out of 5000
10:29:22.124 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->227
10:29:22.333 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->98
10:29:22.334 [http-apr-8080-exec-6] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
read data->Got EOT->98
10:29:22.334 [http-apr-8080-exec-6] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1222
10:29:22.335 [http-apr-8080-exec-6] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@35bc2f85
10:29:22.338 [http-apr-8080-exec-6] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - Result: 1
10:29:22.339 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]6
M $JOB=12646
Socket has been successfully closed
10:29:22.340 [http-apr-8080-exec-6] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionEventListener -
VistaLinkManagedConnection destroyed via close() event and
VistaLinkManagedConnectionEventListener
10:29:22.341 [http-apr-8080-exec-6] DEBUG
o.s.web.servlet.DispatcherServlet - Rendering view
[gov.va.med.edp.web.view.XmlView: name 'xmlView'] in DispatcherServlet
with name 'dispatcher'
10:29:22.341 [http-apr-8080-exec-6] DEBUG
gov.va.med.edp.web.view.XmlView - Rendering view with name 'xmlView'
with model {xmlFragment=<logEntries status='new' token='62490,44198' >
<log bed="CT" id="1" last4="T6123" name="TEST,ONE" same="0" seq="50"
ssn="856456123" />
<log bed="CATH" id="2" last4="T6124" name="TESTING,TESTING M M"
same="0" seq="70" ssn="445566124" />
<log bed="SCLIN" id="3" name="ZZ PATIENT,TEST TWO" same="0" seq="100" /
>
</logEntries>
} and static attributes {}
10:29:22.346 [http-apr-8080-exec-6] DEBUG
o.s.web.servlet.DispatcherServlet - Cleared thread-bound request
context:
org.springframework.security.wrapper.SavedRequestAwareWrapper@38cf0a88
10:29:22.347 [http-apr-8080-exec-6] DEBUG
o.s.web.servlet.DispatcherServlet - Successfully completed request
10:29:22.348 [http-apr-8080-exec-6] DEBUG
o.s.w.c.s.XmlWebApplicationContext - Publishing event in context
[org.springframework.web.context.support.XmlWebApplicationContext@414128f7]:
ServletRequestHandledEvent: url=[/main/tracking.xml];
client=[127.0.0.1]; method=[POST]; servlet=[dispatcher];
session=[6705BD29FA9A6170465037EE2BEB1CAE]; user=[93@999];
time=[4994ms]; status=[OK]
10:29:22.349 [http-apr-8080-exec-6] DEBUG
o.s.w.c.s.XmlWebApplicationContext - Publishing event in context
[org.springframework.web.context.support.XmlWebApplicationContext@282c1f9d]:
ServletRequestHandledEvent: url=[/main/tracking.xml];
client=[127.0.0.1]; method=[POST]; servlet=[dispatcher];
session=[6705BD29FA9A6170465037EE2BEB1CAE]; user=[93@999];
time=[4994ms]; status=[OK]
10:29:22.350 [http-apr-8080-exec-6] DEBUG
o.s.s.ui.ExceptionTranslationFilter - Chain processed normally
10:29:22.351 [http-apr-8080-exec-6] DEBUG
o.s.s.c.HttpSessionContextIntegrationFilter - SecurityContextHolder
now cleared, as request processing completed
10:29:47.658 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - Converted URL to lowercase, from:
'/tracking.xml'; to: '/tracking.xml'
10:29:47.659 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - Candidate is: '/tracking.xml';
pattern is /logout.html*; matched=false
10:29:47.660 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - Converted URL to lowercase, from:
'/tracking.xml'; to: '/tracking.xml'
10:29:47.660 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - Candidate is: '/tracking.xml';
pattern is /**; matched=true
10:29:47.661 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 1 of 7
in additional filter chain; firing Filter:
'org.springframework.security.context.HttpSessionContextIntegrationFilter[ order=200; ]'
10:29:47.662 [http-apr-8080-exec-8] DEBUG
o.s.s.c.HttpSessionContextIntegrationFilter - Obtained a valid
SecurityContext from SPRING_SECURITY_CONTEXT to associate with
SecurityContextHolder:
'org.springframework.security.context.SecurityContextImpl@46e50923:
Authentication:
gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER'
10:29:47.662 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 2 of 7
in additional filter chain; firing Filter:
'gov.va.med.edp.springframework.security.ui.vistalink.VistaAuthenticationProcessingFilter[ order=700; ]'
10:29:47.663 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 3 of 7
in additional filter chain; firing Filter:
'org.springframework.security.wrapper.SecurityContextHolderAwareRequestFilter[ order=1100; ]'
10:29:47.663 [http-apr-8080-exec-8] DEBUG
o.s.s.ui.savedrequest.SavedRequest - pathInfo: both null (property
equals)
10:29:47.665 [http-apr-8080-exec-8] DEBUG
o.s.s.ui.savedrequest.SavedRequest - queryString: both null (property
equals)
10:29:47.667 [http-apr-8080-exec-8] DEBUG
o.s.s.ui.savedrequest.SavedRequest - requestURI: arg1=/main/
tracking.html;jsessionid=6705BD29FA9A6170465037EE2BEB1CAE; arg2=/main/
tracking.xml (property not equals)
10:29:47.668 [http-apr-8080-exec-8] DEBUG
o.s.s.w.SavedRequestAwareWrapper - Wrapper not replaced; SavedRequest
was: SavedRequest[http://localhost:8080/main/tracking.html]
10:29:47.670 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 4 of 7
in additional filter chain; firing Filter:
'org.springframework.security.providers.anonymous.AnonymousProcessingFilter[ order=1300; ]'
10:29:47.672 [http-apr-8080-exec-8] DEBUG
o.s.s.p.a.AnonymousProcessingFilter - SecurityContextHolder not
populated with anonymous token, as it already contained:
'gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER'
10:29:47.673 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 5 of 7
in additional filter chain; firing Filter:
'org.springframework.security.ui.ExceptionTranslationFilter[ order=1400; ]'
10:29:47.678 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 6 of 7
in additional filter chain; firing Filter:
'org.springframework.security.ui.SessionFixationProtectionFilter[ order=1600; ]'
10:29:47.679 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml at position 7 of 7
in additional filter chain; firing Filter:
'org.springframework.security.intercept.web.FilterSecurityInterceptor@a45ed31'
10:29:47.680 [http-apr-8080-exec-8] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Converted URL to
lowercase, from: '/tracking.xml'; to: '/tracking.xml'
10:29:47.682 [http-apr-8080-exec-8] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
tracking.xml'; pattern is /about.html; matched=false
10:29:47.683 [http-apr-8080-exec-8] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
tracking.xml'; pattern is /login.html*; matched=false
10:29:47.684 [http-apr-8080-exec-8] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
tracking.xml'; pattern is /**/*.swf; matched=false
10:29:47.685 [http-apr-8080-exec-8] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
tracking.xml'; pattern is /**/*.xml; matched=true
10:29:47.686 [http-apr-8080-exec-8] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Secure object: FilterInvocation:
URL: /tracking.xml; ConfigAttributes: [ROLE_USER]
10:29:47.686 [http-apr-8080-exec-8] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Previously Authenticated:
gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER
10:29:47.687 [http-apr-8080-exec-8] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Authorization successful
10:29:47.688 [http-apr-8080-exec-8] DEBUG
o.s.w.c.s.XmlWebApplicationContext - Publishing event in context
[org.springframework.web.context.support.XmlWebApplicationContext@282c1f9d]:
org.springframework.security.event.authorization.AuthorizedEvent[source=FilterInvocation:
URL: /tracking.xml]
10:29:47.688 [http-apr-8080-exec-8] DEBUG
o.s.s.i.AbstractSecurityInterceptor - RunAsManager did not change
Authentication object
10:29:47.689 [http-apr-8080-exec-8] DEBUG
o.s.security.util.FilterChainProxy - /tracking.xml reached end of
additional filter chain; proceeding with original chain
10:29:47.690 [http-apr-8080-exec-8] DEBUG
o.s.web.servlet.DispatcherServlet - DispatcherServlet with name
'dispatcher' received request for [/main/tracking.xml]
10:29:47.691 [http-apr-8080-exec-8] DEBUG
o.s.web.servlet.DispatcherServlet - Bound request context to thread:
org.springframework.security.wrapper.SavedRequestAwareWrapper@7d1ee2fc
10:29:47.691 [http-apr-8080-exec-8] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler map
[org.springframework.web.servlet.handler.BeanNameUrlHandlerMapping@20d37520]
in DispatcherServlet with name 'dispatcher'
10:29:47.692 [http-apr-8080-exec-8] DEBUG
o.s.w.s.h.BeanNameUrlHandlerMapping - Looking up handler for [/
tracking.xml]
10:29:47.693 [http-apr-8080-exec-8] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler adapter
[org.springframework.web.servlet.mvc.HttpRequestHandlerAdapter@1aae98b6]
10:29:47.694 [http-apr-8080-exec-8] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler adapter
[org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter@6d84f7a0]
10:29:47.695 [http-apr-8080-exec-8] DEBUG
o.s.b.f.s.DefaultListableBeanFactory - Returning cached instance of
singleton bean 'vljConnector999'
10:29:47.696 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkConnectionRequestInfo - Constructing request info
10:29:47.696 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkConnectionManager - allocating connection
10:29:47.697 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionFactory -
gov.va.med.edp.vistalink.adapter.spi.VistaLinkManagedConnectionFactory[]10.10.0.124[]8011[]1[adapterversion]1.5.0.026[]J2EE[fdi]1
Creating Managed connection->7
10:29:47.698 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=[Not Set]
Constructing
10:29:47.699 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkConnectionEventNotifier - Constructing
10:29:47.701 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=[Not Set]
Executing Init Socket interaction
10:29:47.702 [http-apr-8080-exec-8] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@76c84e90
10:29:47.704 [http-apr-8080-exec-8] DEBUG gov.va.med.xml.XmlUtilities
- XPath /VistaLink/Request returned 1nodes.
10:29:47.704 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=[Not Set]
Executing interaction
10:29:47.705 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=[Not Set]
Executing transfer with time out of 5000
10:29:48.746 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->234
10:29:48.948 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->121
10:29:48.948 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->Got EOT->121
10:29:48.949 [http-apr-8080-exec-8] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1243
10:29:48.950 [http-apr-8080-exec-8] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@589e0cdc
10:29:48.951 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponseFactory - got response
attributes
10:29:48.952 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponseFactory - Retrieved Initial
Socket Response:
heartbeat rate = 604800000
M $JOB = 12719
Reauth session Timeout = 3600000
10:29:48.952 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponse - initSocket response
constructed[]604800000
10:29:48.953 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=[Not Set]
Heartbeat rate set successfully[]604800000
10:29:48.953 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
M $JOB set successfully[]12719
10:29:48.955 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Setting up authentication
10:29:48.956 [http-apr-8080-exec-8] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - -> sending AV.SetupAndIntroText
10:29:48.957 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Executing interaction
10:29:48.958 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Executing transfer with time out of 5000
10:29:49.978 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->231
10:29:49.979 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->512
10:29:49.980 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->512
10:29:49.982 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->512
10:29:49.982 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->512
10:29:49.983 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->512
10:29:49.984 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->512
10:29:49.985 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->512
10:29:49.987 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->512
10:29:49.987 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->430
10:29:49.988 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->Got EOT->430
10:29:49.990 [http-apr-8080-exec-8] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1032
10:29:49.991 [http-apr-8080-exec-8] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@474405c3
10:29:49.994 [http-apr-8080-exec-8] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - Result: 1
10:29:49.995 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
executing first phase logon
10:29:49.996 [http-apr-8080-exec-8] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - -> sending AV.Logon
10:29:49.997 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Executing interaction
10:29:49.998 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Executing transfer with time out of 5000
10:29:50.085 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - Converted URL to lowercase, from:
'/board.xml'; to: '/board.xml'
10:29:50.086 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - Candidate is: '/board.xml';
pattern is /logout.html*; matched=false
10:29:50.089 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - Converted URL to lowercase, from:
'/board.xml'; to: '/board.xml'
10:29:50.089 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - Candidate is: '/board.xml';
pattern is /**; matched=true
10:29:50.089 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 1 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.context.HttpSessionContextIntegrationFilter[ order=200; ]'
10:29:50.090 [http-apr-8080-exec-10] DEBUG
o.s.s.c.HttpSessionContextIntegrationFilter - Obtained a valid
SecurityContext from SPRING_SECURITY_CONTEXT to associate with
SecurityContextHolder:
'org.springframework.security.context.SecurityContextImpl@46e50923:
Authentication:
gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER'
10:29:50.091 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 2 of 7 in
additional filter chain; firing Filter:
'gov.va.med.edp.springframework.security.ui.vistalink.VistaAuthenticationProcessingFilter[ order=700; ]'
10:29:50.091 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 3 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.wrapper.SecurityContextHolderAwareRequestFilter[ order=1100; ]'
10:29:50.092 [http-apr-8080-exec-10] DEBUG
o.s.s.ui.savedrequest.SavedRequest - pathInfo: both null (property
equals)
10:29:50.092 [http-apr-8080-exec-10] DEBUG
o.s.s.ui.savedrequest.SavedRequest - queryString: both null (property
equals)
10:29:50.093 [http-apr-8080-exec-10] DEBUG
o.s.s.ui.savedrequest.SavedRequest - requestURI: arg1=/main/
tracking.html;jsessionid=6705BD29FA9A6170465037EE2BEB1CAE; arg2=/main/
board.xml (property not equals)
10:29:50.093 [http-apr-8080-exec-10] DEBUG
o.s.s.w.SavedRequestAwareWrapper - Wrapper not replaced; SavedRequest
was: SavedRequest[http://localhost:8080/main/tracking.html]
10:29:50.094 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 4 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.providers.anonymous.AnonymousProcessingFilter[ order=1300; ]'
10:29:50.094 [http-apr-8080-exec-10] DEBUG
o.s.s.p.a.AnonymousProcessingFilter - SecurityContextHolder not
populated with anonymous token, as it already contained:
'gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER'
10:29:50.095 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 5 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.ui.ExceptionTranslationFilter[ order=1400; ]'
10:29:50.095 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 6 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.ui.SessionFixationProtectionFilter[ order=1600; ]'
10:29:50.095 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 7 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.intercept.web.FilterSecurityInterceptor@a45ed31'
10:29:50.096 [http-apr-8080-exec-10] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Converted URL to
lowercase, from: '/board.xml'; to: '/board.xml'
10:29:50.096 [http-apr-8080-exec-10] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
board.xml'; pattern is /about.html; matched=false
10:29:50.097 [http-apr-8080-exec-10] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
board.xml'; pattern is /login.html*; matched=false
10:29:50.097 [http-apr-8080-exec-10] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
board.xml'; pattern is /**/*.swf; matched=false
10:29:50.097 [http-apr-8080-exec-10] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
board.xml'; pattern is /**/*.xml; matched=true
10:29:50.097 [http-apr-8080-exec-10] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Secure object: FilterInvocation:
URL: /board.xml; ConfigAttributes: [ROLE_USER]
10:29:50.097 [http-apr-8080-exec-10] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Previously Authenticated:
gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER
10:29:50.097 [http-apr-8080-exec-10] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Authorization successful
10:29:50.098 [http-apr-8080-exec-10] DEBUG
o.s.w.c.s.XmlWebApplicationContext - Publishing event in context
[org.springframework.web.context.support.XmlWebApplicationContext@282c1f9d]:
org.springframework.security.event.authorization.AuthorizedEvent[source=FilterInvocation:
URL: /board.xml]
10:29:50.098 [http-apr-8080-exec-10] DEBUG
o.s.s.i.AbstractSecurityInterceptor - RunAsManager did not change
Authentication object
10:29:50.098 [http-apr-8080-exec-10] DEBUG
o.s.security.util.FilterChainProxy - /board.xml reached end of
additional filter chain; proceeding with original chain
10:29:50.098 [http-apr-8080-exec-10] DEBUG
o.s.web.servlet.DispatcherServlet - DispatcherServlet with name
'dispatcher' received request for [/main/board.xml]
10:29:50.103 [http-apr-8080-exec-10] DEBUG
o.s.web.servlet.DispatcherServlet - Bound request context to thread:
org.springframework.security.wrapper.SavedRequestAwareWrapper@42fcb590
10:29:50.103 [http-apr-8080-exec-10] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler map
[org.springframework.web.servlet.handler.BeanNameUrlHandlerMapping@20d37520]
in DispatcherServlet with name 'dispatcher'
10:29:50.104 [http-apr-8080-exec-10] DEBUG
o.s.w.s.h.BeanNameUrlHandlerMapping - Looking up handler for [/
board.xml]
10:29:50.105 [http-apr-8080-exec-10] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler adapter
[org.springframework.web.servlet.mvc.HttpRequestHandlerAdapter@1aae98b6]
10:29:50.105 [http-apr-8080-exec-10] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler adapter
[org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter@6d84f7a0]
10:29:50.106 [http-apr-8080-exec-10] DEBUG
o.s.b.f.s.DefaultListableBeanFactory - Returning cached instance of
singleton bean 'vljConnector999'
10:29:50.106 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkConnectionRequestInfo - Constructing request info
10:29:50.107 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkConnectionManager - allocating connection
10:29:50.107 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionFactory -
gov.va.med.edp.vistalink.adapter.spi.VistaLinkManagedConnectionFactory[]10.10.0.124[]8011[]1[adapterversion]1.5.0.026[]J2EE[fdi]1
Creating Managed connection->8
10:29:50.108 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=[Not Set]
Constructing
10:29:50.109 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkConnectionEventNotifier - Constructing
10:29:50.089 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - Converted URL to lowercase, from:
'/board.xml'; to: '/board.xml'
10:29:50.110 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - Candidate is: '/board.xml';
pattern is /logout.html*; matched=false
10:29:50.111 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - Converted URL to lowercase, from:
'/board.xml'; to: '/board.xml'
10:29:50.112 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - Candidate is: '/board.xml';
pattern is /**; matched=true
10:29:50.113 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=[Not Set]
Executing Init Socket interaction
10:29:50.116 [http-apr-8080-exec-10] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@5cf4234b
10:29:50.118 [http-apr-8080-exec-10] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilder implementation:
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderImpl
10:29:50.119 [http-apr-8080-exec-10] DEBUG gov.va.med.xml.XmlUtilities
- XPath /VistaLink/Request returned 1nodes.
10:29:50.120 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=[Not Set]
Executing interaction
10:29:50.124 [http-apr-8080-exec-10] DEBUG gov.va.med.xml.XmlUtilities
- Using Transformer implementation:
com.sun.org.apache.xalan.internal.xsltc.trax.TransformerImpl
10:29:50.129 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=[Not Set]
Executing transfer with time out of 5000
10:29:50.114 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 1 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.context.HttpSessionContextIntegrationFilter[ order=200; ]'
10:29:50.131 [http-apr-8080-exec-3] DEBUG
o.s.s.c.HttpSessionContextIntegrationFilter - Obtained a valid
SecurityContext from SPRING_SECURITY_CONTEXT to associate with
SecurityContextHolder:
'org.springframework.security.context.SecurityContextImpl@46e50923:
Authentication:
gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER'
10:29:50.132 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 2 of 7 in
additional filter chain; firing Filter:
'gov.va.med.edp.springframework.security.ui.vistalink.VistaAuthenticationProcessingFilter[ order=700; ]'
10:29:50.132 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 3 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.wrapper.SecurityContextHolderAwareRequestFilter[ order=1100; ]'
10:29:50.133 [http-apr-8080-exec-3] DEBUG
o.s.s.ui.savedrequest.SavedRequest - pathInfo: both null (property
equals)
10:29:50.133 [http-apr-8080-exec-3] DEBUG
o.s.s.ui.savedrequest.SavedRequest - queryString: both null (property
equals)
10:29:50.133 [http-apr-8080-exec-3] DEBUG
o.s.s.ui.savedrequest.SavedRequest - requestURI: arg1=/main/
tracking.html;jsessionid=6705BD29FA9A6170465037EE2BEB1CAE; arg2=/main/
board.xml (property not equals)
10:29:50.134 [http-apr-8080-exec-3] DEBUG
o.s.s.w.SavedRequestAwareWrapper - Wrapper not replaced; SavedRequest
was: SavedRequest[http://localhost:8080/main/tracking.html]
10:29:50.134 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 4 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.providers.anonymous.AnonymousProcessingFilter[ order=1300; ]'
10:29:50.135 [http-apr-8080-exec-3] DEBUG
o.s.s.p.a.AnonymousProcessingFilter - SecurityContextHolder not
populated with anonymous token, as it already contained:
'gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER'
10:29:50.135 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 5 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.ui.ExceptionTranslationFilter[ order=1400; ]'
10:29:50.136 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 6 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.ui.SessionFixationProtectionFilter[ order=1600; ]'
10:29:50.136 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - /board.xml at position 7 of 7 in
additional filter chain; firing Filter:
'org.springframework.security.intercept.web.FilterSecurityInterceptor@a45ed31'
10:29:50.137 [http-apr-8080-exec-3] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Converted URL to
lowercase, from: '/board.xml'; to: '/board.xml'
10:29:50.137 [http-apr-8080-exec-3] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
board.xml'; pattern is /about.html; matched=false
10:29:50.137 [http-apr-8080-exec-3] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
board.xml'; pattern is /login.html*; matched=false
10:29:50.138 [http-apr-8080-exec-3] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
board.xml'; pattern is /**/*.swf; matched=false
10:29:50.138 [http-apr-8080-exec-3] DEBUG
o.s.s.i.w.DefaultFilterInvocationDefinitionSource - Candidate is: '/
board.xml'; pattern is /**/*.xml; matched=true
10:29:50.139 [http-apr-8080-exec-3] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Secure object: FilterInvocation:
URL: /board.xml; ConfigAttributes: [ROLE_USER]
10:29:50.139 [http-apr-8080-exec-3] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Previously Authenticated:
gov.va.med.edp.springframework.security.providers.vistalink.VistaAuthenticationToken@46e50923:
Principal:
gov.va.med.edp.springframework.security.userdetails.vistalink.VistaUser@1def1283;
Password: [PROTECTED]; Authenticated: true; Details: 127.0.0.1;
Granted Authorities: ROLE_USER
10:29:50.139 [http-apr-8080-exec-3] DEBUG
o.s.s.i.AbstractSecurityInterceptor - Authorization successful
10:29:50.140 [http-apr-8080-exec-3] DEBUG
o.s.w.c.s.XmlWebApplicationContext - Publishing event in context
[org.springframework.web.context.support.XmlWebApplicationContext@282c1f9d]:
org.springframework.security.event.authorization.AuthorizedEvent[source=FilterInvocation:
URL: /board.xml]
10:29:50.140 [http-apr-8080-exec-3] DEBUG
o.s.s.i.AbstractSecurityInterceptor - RunAsManager did not change
Authentication object
10:29:50.141 [http-apr-8080-exec-3] DEBUG
o.s.security.util.FilterChainProxy - /board.xml reached end of
additional filter chain; proceeding with original chain
10:29:50.141 [http-apr-8080-exec-3] DEBUG
o.s.web.servlet.DispatcherServlet - DispatcherServlet with name
'dispatcher' received request for [/main/board.xml]
10:29:50.142 [http-apr-8080-exec-3] DEBUG
o.s.web.servlet.DispatcherServlet - Bound request context to thread:
org.springframework.security.wrapper.SavedRequestAwareWrapper@2039409a
10:29:50.142 [http-apr-8080-exec-3] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler map
[org.springframework.web.servlet.handler.BeanNameUrlHandlerMapping@20d37520]
in DispatcherServlet with name 'dispatcher'
10:29:50.142 [http-apr-8080-exec-3] DEBUG
o.s.w.s.h.BeanNameUrlHandlerMapping - Looking up handler for [/
board.xml]
10:29:50.143 [http-apr-8080-exec-3] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler adapter
[org.springframework.web.servlet.mvc.HttpRequestHandlerAdapter@1aae98b6]
10:29:50.143 [http-apr-8080-exec-3] DEBUG
o.s.web.servlet.DispatcherServlet - Testing handler adapter
[org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter@6d84f7a0]
10:29:50.144 [http-apr-8080-exec-3] DEBUG
o.s.b.f.s.DefaultListableBeanFactory - Returning cached instance of
singleton bean 'vljConnector999'
10:29:50.144 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkConnectionRequestInfo - Constructing request info
10:29:50.145 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkConnectionManager - allocating connection
10:29:50.145 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionFactory -
gov.va.med.edp.vistalink.adapter.spi.VistaLinkManagedConnectionFactory[]10.10.0.124[]8011[]1[adapterversion]1.5.0.026[]J2EE[fdi]1
Creating Managed connection->9
10:29:50.146 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
M $JOB=[Not Set]
Constructing
10:29:50.146 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkConnectionEventNotifier - Constructing
10:29:50.648 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
M $JOB=[Not Set]
Executing Init Socket interaction
10:29:50.649 [http-apr-8080-exec-3] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@ec04efd
10:29:50.653 [http-apr-8080-exec-3] DEBUG gov.va.med.xml.XmlUtilities
- XPath /VistaLink/Request returned 1nodes.
10:29:50.653 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
M $JOB=[Not Set]
Executing interaction
10:29:50.656 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
M $JOB=[Not Set]
Executing transfer with time out of 5000
10:29:51.020 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->226
10:29:51.145 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->234
10:29:51.222 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->130
10:29:51.223 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->Got EOT->130
10:29:51.223 [http-apr-8080-exec-8] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1225
10:29:51.224 [http-apr-8080-exec-8] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@4e5e685b
10:29:51.226 [http-apr-8080-exec-8] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - Result: 1
10:29:51.226 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Added managedconnection to Heartbeat TimerTask
10:29:51.227 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionFactory -
gov.va.med.edp.vistalink.adapter.spi.VistaLinkManagedConnectionFactory[]10.10.0.124[]8011[]1[adapterversion]1.5.0.026[]J2EE[fdi]1
Created Managed connection->7
10:29:51.227 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
addConnectionEventListener
10:29:51.228 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkConnectionEventNotifier -
addConnectionEventListener
10:29:51.229 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Getting connection handle
10:29:51.229 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Connection handle available
10:29:51.230 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Connection re-authentication status: 'notauthenticated'. cri =
Con Req Info is null
10:29:51.230 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
addConHandle
10:29:51.231 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionFactory - elapsedMillis to add:
2
10:29:51.232 [http-apr-8080-exec-8] INFO
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
getConnection(...) processing time = 2
10:29:51.232 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection - About to execute RPC:
'EDPCTRL RPC', on connector configured with JNDI name: '',
primaryStation: '999', reauthentication type: 'duz', credentials:
'93'.
10:29:51.233 [http-apr-8080-exec-8] DEBUG
gov.va.med.vistalink.rpc.RpcRequest - Setting re-authentication
information
10:29:51.234 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Executing interaction
10:29:51.237 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Executing transfer with time out of 10000
10:29:51.245 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->216
10:29:51.346 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->121
10:29:51.347 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->Got EOT->121
10:29:51.349 [http-apr-8080-exec-10] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1219
10:29:51.352 [http-apr-8080-exec-10] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@17b5a325
10:29:51.355 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponseFactory - got response
attributes
10:29:51.355 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponseFactory - Retrieved Initial
Socket Response:
heartbeat rate = 604800000
M $JOB = 12749
Reauth session Timeout = 3600000
10:29:51.359 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponse - initSocket response
constructed[]604800000
10:29:51.360 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=[Not Set]
Heartbeat rate set successfully[]604800000
10:29:51.361 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=12749
M $JOB set successfully[]12749
10:29:51.363 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=12749
Setting up authentication
10:29:51.371 [http-apr-8080-exec-10] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - -> sending AV.SetupAndIntroText
10:29:51.372 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=12749
Executing interaction
10:29:51.374 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=12749
Executing transfer with time out of 5000
10:29:51.453 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->512
10:29:51.454 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->405
10:29:51.456 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->Got EOT->405
10:29:51.457 [http-apr-8080-exec-8] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 220
10:29:51.459 [http-apr-8080-exec-8] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@2d015ad1
10:29:51.462 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection - Completed execution of RPC:
EDPCTRL RPC
10:29:51.463 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Closing handle
10:29:51.465 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
removeConHandle
10:29:51.467 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkConnectionEventNotifier - Connection closed
10:29:51.468 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Destroying managed connection
10:29:51.470 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
removed managedconnection to Heartbeat TimerTask
10:29:51.471 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Executing logout
10:29:51.476 [http-apr-8080-exec-8] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - -> sending AV.Logout
10:29:51.477 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Executing interaction
10:29:51.480 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Executing transfer with time out of 5000
10:29:51.680 [http-apr-8080-exec-3] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
read data->234
10:29:51.884 [http-apr-8080-exec-3] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
read data->121
10:29:51.885 [http-apr-8080-exec-3] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
read data->Got EOT->121
10:29:51.887 [http-apr-8080-exec-3] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1230
10:29:51.889 [http-apr-8080-exec-3] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@2d7b5718
10:29:51.893 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponseFactory - got response
attributes
10:29:51.894 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponseFactory - Retrieved Initial
Socket Response:
heartbeat rate = 604800000
M $JOB = 12765
Reauth session Timeout = 3600000
10:29:51.895 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkInitSocketResponse - initSocket response
constructed[]604800000
10:29:51.897 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
M $JOB=[Not Set]
Heartbeat rate set successfully[]604800000
10:29:51.898 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
M $JOB=12765
M $JOB set successfully[]12765
10:29:51.900 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
M $JOB=12765
Setting up authentication
10:29:51.905 [http-apr-8080-exec-3] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - -> sending AV.SetupAndIntroText
10:29:51.906 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
M $JOB=12765
Executing interaction
10:29:51.908 [http-apr-8080-exec-3] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]9
M $JOB=12765
Executing transfer with time out of 5000
10:29:52.392 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->231
10:29:52.393 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->512
10:29:52.395 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->512
10:29:52.397 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->512
10:29:52.398 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->512
10:29:52.402 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->512
10:29:52.405 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->512
10:29:52.405 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->512
10:29:52.407 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->512
10:29:52.409 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->430
10:29:52.410 [http-apr-8080-exec-10] DEBUG
gov.va.med.net.SocketManager -
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
read data->Got EOT->430
10:29:52.412 [http-apr-8080-exec-10] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1038
10:29:52.413 [http-apr-8080-exec-10] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@16e3f7a2
10:29:52.419 [http-apr-8080-exec-10] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - Result: 1
10:29:52.422 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=12749
executing first phase logon
10:29:52.425 [http-apr-8080-exec-10] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - -> sending AV.Logon
10:29:52.425 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=12749
Executing interaction
10:29:52.427 [http-apr-8080-exec-10] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]8
M $JOB=12749
Executing transfer with time out of 5000
10:29:52.494 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->227
10:29:52.696 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->98
10:29:52.698 [http-apr-8080-exec-8] DEBUG gov.va.med.net.SocketManager
-
gov.va.med.vistalink.adapter.spi.VistaSocketConnection[mdi]gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
read data->Got EOT->98
10:29:52.699 [http-apr-8080-exec-8] INFO g.v.m.v.a.s.V.AuditLog -
Socket xfer (milli-secs): 1218
10:29:52.702 [http-apr-8080-exec-8] DEBUG gov.va.med.xml.XmlUtilities
- Using DocumentBuilderFactory factory
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl@59ab8480;
and DocumentBuilder builder gov.va.med.xml.XmlUtilities
$ThreadLocalDocumentBuilder@b881d7e; InputStream xml =
org.xml.sax.InputSource@450be552
10:29:52.708 [http-apr-8080-exec-8] DEBUG
g.v.m.v.s.m.KernelSecurityHandshake - Result: 1
10:29:52.709 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnection -
gov.va.med.vistalink.adapter.spi.VistaLinkManagedConnection[]10.10.0.124[]8011[]1[]J2EE[fdi]1[mdi]7
M $JOB=12719
Socket has been successfully closed
10:29:52.710 [http-apr-8080-exec-8] DEBUG
g.v.m.v.a.s.VistaLinkManagedConnectionEventListener -
VistaLinkManagedConnection destroyed via close() event and
VistaLinkManagedConnectionEventListener
10:29:52.713 [http-apr-8080-exec-8] DEBUG
o.s.web.servlet.DispatcherServlet - Rendering view
[gov.va.med.edp.web.view.XmlView: name 'xmlView'] in DispatcherServlet
with name 'dispatcher'
10:29:52.715 [http-apr-8080-exec-8] DEBUG
gov.va.med.edp.web.view.XmlView - Rendering view with name 'xmlView'
with model {xmlFragment=<logEntries status='new' token='62490,44198' >
<log bed="CT" id="1" last4="T6123" name="TEST,ONE" same="0" seq="50"
ssn="856456123" />
<log bed="CATH" id="2" last4="T6124" name="TESTING,TESTING M M"
same="0" seq="70" ssn="445566124" />
<log bed="SCLIN" id="3" name="ZZ PATIENT,TEST TWO" same="0" seq="100" /
>
</logEntries>
} and static attributes {}
Regards,
Srikant
On Feb 5, 1:43 pm, Wasim Naffar <w0795930...@gmail.com> wrote:
> oohh, do you mean only the application server's console or the Debug item
> on the EDIS??!!
>
>
>
>
>
>
>
> On Sun, Feb 5, 2012 at 10:40 AM, Wasim Naffar <w0795930...@gmail.com> wrote:
> > Hi Srikant,
> > I guess the debug working on VistALink 1.6, already i run EDIS on
> > VistALink 1.5 and i never seen the debug item on the EDIS viewer, and i
> > have never use it, just i found it on the screenshots and EDIS manuals.
> > Anyway, i will try to find if there is a key or an option given to the
> > user!! maybe that is the case!!
>
> > Regards,
> > Wasim
>
Wasim Naffar
Feb 12, 2012, 7:40:30 AM2/12/12
to vista-emer...@googlegroups.com
We use log rotate for writing logs in daily logs, plus I guess that you can solve this issue from The application-Server itself, for example if you use Tomcat, you can search on how to configure "log4j properties" in Tomcat6.
Regards,
Wasim
Reply all
Reply to author
Forward
0 new messages