I have a question about interpreting Synapse logs, specifically
related to using a separate listener. The log in question is:
2009-01-14 15:52:41,994 [192.168.254.153-bmajur.local]
[HttpServerWorker-1] DEBUG FilterMediator Source : get-
property('Action') against : .*:RegistryStoredQueryAsync matches -
executing child mediators
2009-01-14 15:52:41,994 [192.168.254.153-bmajur.local]
[HttpServerWorker-1] DEBUG FilterMediator Sequence <FilterMediator> ::
mediate()
2009-01-14 15:52:41,995 [192.168.254.153-bmajur.local]
[HttpServerWorker-1] DEBUG SendMediator Start : Send mediator
2009-01-14 15:52:41,995 [192.168.254.153-bmajur.local]
[HttpServerWorker-1] DEBUG AddressEndpoint AddressEndpoint with name
'pub_async_sq' is in active state
2009-01-14 15:52:41,995 [192.168.254.153-bmajur.local]
[HttpServerWorker-1] DEBUG AddressEndpoint Start : Address Endpoint
2009-01-14 15:52:41,996 [192.168.254.153-bmajur.local]
[HttpServerWorker-1] DEBUG AddressEndpoint Sending message to
endpoint : pub_async_sq resolves to address = http://ihexds.nist.gov:9080/tf5/services/xdsregistrybas
2009-01-14 15:52:41,996 [192.168.254.153-bmajur.local]
[HttpServerWorker-1] DEBUG AddressEndpoint SOAPAction: urn:ihe:iti:2007:RegistryStoredQueryAsync
2009-01-14 15:52:41,996 [192.168.254.153-bmajur.local]
[HttpServerWorker-1] DEBUG AddressEndpoint WSA-Action: urn:ihe:iti:2007:RegistryStoredQueryAsync
2009-01-14 15:52:41,999 [192.168.254.153-bmajur.local]
[HttpServerWorker-1] DEBUG Axis2FlexibleMEPClient Sending [add = true]
[sec = false] [rm = false] [mtom = false] [swa = false] [format =
soap12] [force soap11=false] [force soap12=true] [pox=false]
[get=false] [encoding=null] [to Address: http://localhost:9080/tf5/services/xdsregistrybas
]
2009-01-14 15:52:42,013 [192.168.254.153-bmajur.local]
[HttpServerWorker-1] INFO TimeoutHandler This engine will expire all
callbacks after : 86400 seconds, irrespective of the timeout action,
after the specified or optional timeout
2009-01-14 15:52:42,019 [192.168.254.153-bmajur.local]
[HttpServerWorker-1] DEBUG SynapseCallbackReceiver Callback added.
Total callbacks waiting for : 1
2009-01-14 15:52:42,131 [192.168.254.153-bmajur.local]
[HttpServerWorker-1] DEBUG SendMediator End : Send mediator
2009-01-14 15:52:42,131 [192.168.254.153-bmajur.local]
[HttpServerWorker-1] DEBUG DropMediator Start : Drop mediator
2009-01-14 15:52:42,134 [192.168.254.153-bmajur.local]
[HttpServerWorker-1] DEBUG DropMediator End : Drop mediator
2009-01-14 15:52:42,134 [192.168.254.153-bmajur.local]
[HttpServerWorker-1] DEBUG InMediator End : In mediator
2009-01-14 15:52:42,135 [192.168.254.153-bmajur.local]
[HttpServerWorker-1] DEBUG SequenceMediator End : Sequence <main>
Now, the question relates to the red entry. The endpoint being sent to
looks like
<endpoint name="pub_async_sq">
<address uri="http://ihexds.nist.gov:9080/tf5/services/xdsregistrybas
" format="soap12" trace="enable">
<enableAddressing separateListener="true"/>
</address>
</endpoint>
Note that I am using a separateListener which I understand to mean
using asynchronous web services. In this mode I expect my request to
get an immediate HTTP 200 response and then the real response message
comes in a separate connection.
The question is: Does the time stamp on the SendMediator End log
entry relate to when the HTTP 200 was received? My installation is
working fine but a separate deployment of my system is seeing a 1
minute delay on the receipt of the HTTP 200. I am trying to
investigate and understanding the significance of the time stamps
produced by Synapse would help a great deal.
many thanks,
bill Majurski
