D4Science Infrastructure

The same error again on D4Research scope. On ResourceManager service deployed on resourcemanager-d4research I have the following error when I try to add a scope to sharelatex:

2017-10-30 12:47:12,398 DEBUG impl.DefaultScopeProvider [ServiceThread-60,set:38] setting scope /d4science.research-infrastructures.eu in thread 93
2017-10-30 12:47:12,403 INFO  delegates.DirectDelegate [ServiceThread-60,make:42] calling whn-manager/gcube/vremanagement/ws/whnmanager @ <?xml version="1.0" encoding="UTF-8" standalone="yes"?><EndpointReference xmlns="http://www.w
3.org/2005/08/addressing"><Address>http://sharelatex.d4science.org:80/whn-manager/gcube/vremanagement/ws/whnmanager</Address><ReferenceParameters/><Metadata/></EndpointReference>
2017-10-30 12:47:12,404 DEBUG jaxws.StubFactory [ServiceThread-60,at:38] contcting endpoint http://sharelatex.d4science.org:80/whn-manager/gcube/vremanagement/ws/whnmanager?wsdl
2017-10-30 12:47:12,417 DEBUG proxies.MethodRetriever [ServiceThread-60,getProxy:18] for interface org.gcube.resourcemanagement.whnmanager.api.WhnManager the proxy class is com.sun.proxy.$Proxy80
2017-10-30 12:47:12,417 TRACE provider.CalledMethodProvider [ServiceThread-60,set:33] setting calledMethod as addToContext in thread 93
2017-10-30 12:47:12,418 TRACE handlers.JaxWSHandler [ServiceThread-60,handleMessage:43] handling message
2017-10-30 12:47:12,418 TRACE calls.Interceptors [ServiceThread-60,executeRequestChain:37] executing request chain
2017-10-30 12:47:12,418 TRACE interceptors.ScopeInterceptor [ServiceThread-60,handleRequest:25] scope set in the header is  /d4science.research-infrastructures.eu
2017-10-30 12:47:12,419 WARN  interceptors.AuthorizationInterceptor [ServiceThread-60,handleRequest:22] security token is not set
2017-10-30 12:47:12,419 TRACE provider.CalledMethodProvider [ServiceThread-60,get:26] getting calledMethod as addToContext in thread 93
2017-10-30 12:47:12,419 TRACE interceptors.CalledMethodInterceptor [ServiceThread-60,handleRequest:22] called method set in the header is  addToContext
2017-10-30 12:47:12,420 ERROR proxies.MethodRetriever [ServiceThread-60,invoke:30] error invoking method addToContext in service com.sun.proxy.$Proxy79 using proxy 
2017-10-30 12:47:12,420 ERROR resources.ScopedGHN [ServiceThread-60,error:72] ScopedGHN: Resource [id=d915d613-29ce-4301-a41c-12a824484ae4, type=GHN, timestamp=null, scope=/d4science.research-infrastructures.eu/D4Research, status=ADDREQUESTED, hostedOn=sharelatex.d4science.org:80]: Unable to manage the resource Failed to add WHN to scope /d4science.research-infrastructures.eu/D4Research
org.gcube.common.clients.exceptions.ServiceException: com.sun.xml.internal.ws.client.ClientTransportException: HTTP transport error: java.net.ConnectException: Connection refused (Connection refused)
        at org.gcube.common.clients.exceptions.FaultDSL$AsClause.asServiceException(FaultDSL.java:38)
        at org.gcube.common.vremanagement.whnmanager.client.proxies.DefaultWHNManagerProxy.addToContext(DefaultWHNManagerProxy.java:57)
        at org.gcube.vremanagement.resourcemanager.impl.resources.ScopedGHN.addToScope(ScopedGHN.java:59)
        at org.gcube.vremanagement.resourcemanager.impl.resources.ScopedResource.doAction(ScopedResource.java:129)
        at org.gcube.vremanagement.resourcemanager.impl.state.observers.Executor.addResourceToScope(Executor.java:121)
        at org.gcube.vremanagement.resourcemanager.impl.state.observers.Executor.scopeChanged(Executor.java:81)
        at org.gcube.vremanagement.resourcemanager.impl.state.observers.ScopeObserver.update(ScopeObserver.java:31)
        at java.util.Observable.notifyObservers(Observable.java:159)
        at org.gcube.vremanagement.resourcemanager.impl.state.ScopeState.notifyObservers(ScopeState.java:233)
        at java.util.Observable.notifyObservers(Observable.java:115)
        at org.gcube.vremanagement.resourcemanager.impl.state.ScopeState.notifyObservers(ScopeState.java:239)
        at org.gcube.vremanagement.resourcemanager.impl.state.observers.Publisher.scopeChanged(Publisher.java:30)
        at org.gcube.vremanagement.resourcemanager.impl.state.observers.ScopeObserver.update(ScopeObserver.java:31)
        at java.util.Observable.notifyObservers(Observable.java:159)
        at org.gcube.vremanagement.resourcemanager.impl.state.ScopeState.notifyObservers(ScopeState.java:233)
        at java.util.Observable.notifyObservers(Observable.java:115)
        at org.gcube.vremanagement.resourcemanager.impl.state.ScopeState.notifyObservers(ScopeState.java:239)
        at org.gcube.vremanagement.resourcemanager.impl.state.ScopeState.addResources(ScopeState.java:105)
        at org.gcube.vremanagement.resourcemanager.impl.operators.ScopedResourceManagerOperator.exec(ScopedResourceManagerOperator.java:54)
        at org.gcube.vremanagement.resourcemanager.impl.operators.Operator.run(Operator.java:32)
        at org.gcube.vremanagement.resourcemanager.impl.operators.AddResourcesOperator.exec(AddResourcesOperator.java:47)
        at org.gcube.vremanagement.resourcemanager.impl.operators.Operator.run(Operator.java:32)
        at org.gcube.vremanagement.resourcemanager.porttypes.ResourceBinder.addResources(ResourceBinder.java:47)
        at sun.reflect.GeneratedMethodAccessor82.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.apache.axis.providers.java.RPCProvider.invokeMethod(RPCProvider.java:384)
        at org.globus.axis.providers.RPCProvider.invokeMethodSub(RPCProvider.java:107)
        at org.globus.axis.providers.RPCProvider.invokeMethod(RPCProvider.java:90)
        at org.apache.axis.providers.java.RPCProvider.processMessage(RPCProvider.java:281)
        at org.apache.axis.providers.java.JavaProvider.invoke(JavaProvider.java:319)
        at org.apache.axis.strategies.InvocationStrategy.visit(InvocationStrategy.java:32)
        at org.apache.axis.SimpleChain.doVisiting(SimpleChain.java:118)
        at org.apache.axis.SimpleChain.invoke(SimpleChain.java:83)
        at org.apache.axis.handlers.soap.SOAPService.invoke(SOAPService.java:450)
        at org.apache.axis.server.AxisServer.invoke(AxisServer.java:285)
        at org.globus.wsrf.container.ServiceThread.doPost(ServiceThread.java:664)
        at org.globus.wsrf.container.ServiceThread.process(ServiceThread.java:382)
        at org.globus.wsrf.container.ServiceThread.run(ServiceThread.java:291)
Caused by: com.sun.xml.internal.ws.client.ClientTransportException: HTTP transport error: java.net.ConnectException: Connection refused (Connection refused)
        at com.sun.xml.internal.ws.transport.http.client.HttpClientTransport.getOutput(HttpClientTransport.java:117)
        at com.sun.xml.internal.ws.transport.http.client.HttpTransportPipe.process(HttpTransportPipe.java:194)
        at com.sun.xml.internal.ws.transport.http.client.HttpTransportPipe.processRequest(HttpTransportPipe.java:122)
        at com.sun.xml.internal.ws.transport.DeferredTransportPipe.processRequest(DeferredTransportPipe.java:95)
        at com.sun.xml.internal.ws.api.pipe.Fiber.__doRun(Fiber.java:626)
        at com.sun.xml.internal.ws.api.pipe.Fiber._doRun(Fiber.java:585)
        at com.sun.xml.internal.ws.api.pipe.Fiber.doRun(Fiber.java:570)
        at com.sun.xml.internal.ws.api.pipe.Fiber.runSync(Fiber.java:467)
        at com.sun.xml.internal.ws.client.Stub.process(Stub.java:308)
        at com.sun.xml.internal.ws.client.sei.SEIStub.doProcess(SEIStub.java:163)
        at com.sun.xml.internal.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:98)
        at com.sun.xml.internal.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:78)
        at com.sun.xml.internal.ws.client.sei.SEIStub.invoke(SEIStub.java:135)
        at com.sun.proxy.$Proxy79.addToContext(Unknown Source)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.gcube.common.calls.jaxws.proxies.MethodRetriever.invoke(MethodRetriever.java:25)
        at com.sun.proxy.$Proxy80.addToContext(Unknown Source)
        at org.gcube.common.vremanagement.whnmanager.client.proxies.DefaultWHNManagerProxy$2.call(DefaultWHNManagerProxy.java:48)
        at org.gcube.common.vremanagement.whnmanager.client.proxies.DefaultWHNManagerProxy$2.call(DefaultWHNManagerProxy.java:44)
        at org.gcube.common.clients.delegates.DirectDelegate.make(DirectDelegate.java:53)
        at org.gcube.common.vremanagement.whnmanager.client.proxies.DefaultWHNManagerProxy.addToContext(DefaultWHNManagerProxy.java:52)
        ... 37 more
Caused by: java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
        at java.net.Socket.connect(Socket.java:580)
        at java.net.Socket.connect(Socket.java:529)
        at sun.net.NetworkClient.doConnect(NetworkClient.java:180)
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:449)
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:544)
        at sun.net.www.http.HttpClient.<init>(HttpClient.java:228)
        at sun.net.www.http.HttpClient.New(HttpClient.java:325)
        at sun.net.www.http.HttpClient.New(HttpClient.java:343)
        at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1044)
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1023)
        at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:898)
        at sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1139)
        at com.sun.xml.internal.ws.transport.http.client.HttpClientTransport.getOutput(HttpClientTransport.java:105)
        ... 60 more

Still, I can see successful connections from IP addresses other than the nagios monitoring:

146.48.123.148 - - [30/Oct/2017:12:47:12 +0100] "GET /whn-manager/gcube/vremanagement/ws/whnmanager?wsdl HTTP/1.1" 200 2752 "-" "Java/1.7.0_131"
146.48.85.73 - - [30/Oct/2017:12:54:34 +0100] "GET /whn-manager/gcube/vremanagement/ws/whnmanager HTTP/1.1" 401 2395 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/59.0.3071.115 Safari/537.36"
146.48.85.73 - - [30/Oct/2017:12:54:44 +0100] "GET /favicon.ico HTTP/1.1" 301 178 "http://sharelatex.d4science.org/whn-manager/gcube/vremanagement/ws/whnmanager" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/59.0.3071.115 Safari/537.36"

(the last one is a redirect to the https URL, but it's the browser behaviour. There's no http -> https redirection for the whn-manager requests)

The wsdl resource is correctly discovered by resourcemanager as you can see from logs:

2017-10-30 12:47:12,404 DEBUG jaxws.StubFactory [ServiceThread-60,at:38] contcting endpoint http://sharelatex.d4science.org:80/whn-manager/gcube/vremanagement/ws/whnmanager?wsdl
2017-10-30 12:47:12,417 DEBUG proxies.MethodRetriever [ServiceThread-60,getProxy:18] for interface org.gcube.resourcemanagement.whnmanager.api.WhnManager the proxy class is com.sun.proxy.$Proxy80
2017-10-30 12:47:12,417 TRACE provider.CalledMethodProvider [ServiceThread-60,set:33] setting calledMethod as addToContext in thread 93
2017-10-30 12:47:12,418 TRACE handlers.JaxWSHandler [ServiceThread-60,handleMessage:43] handling message
2017-10-30 12:47:12,418 TRACE calls.Interceptors [ServiceThread-60,executeRequestChain:37] executing request chain
2017-10-30 12:47:12,418 TRACE interceptors.ScopeInterceptor [ServiceThread-60,handleRequest:25] scope set in the header is  /d4science.research-infrastructures.eu
2017-10-30 12:47:12,419 WARN  interceptors.AuthorizationInterceptor [ServiceThread-60,handleRequest:22] security token is not set
2017-10-30 12:47:12,419 TRACE provider.CalledMethodProvider [ServiceThread-60,get:26] getting calledMethod as addToContext in thread 93
2017-10-30 12:47:12,419 TRACE interceptors.CalledMethodInterceptor [ServiceThread-60,handleRequest:22] called method set in the header is  addToContext
2017-10-30 12:47:12,420 ERROR proxies.MethodRetriever [ServiceThread-60,invoke:30] error invoking method addToContext in service com.sun.proxy.$Proxy79 using proxy 

I see the error when is invoking the addToContext method.

I think I've found the issue.
The problem is in the wsdl.

As you can see the wsdl have a bad hostname set:

<definitions xmlns:soap="http://schemas.xmlsoap.org/wsdl/soap/" xmlns:tns="http://gcube-system.org/" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns="http://schemas.xmlsoap.org/wsdl/" targetNamespace="http://gcube-system.org/" name="gcube/vremanagement/ws/whnmanager">
<types>
<xsd:schema>
<xsd:import namespace="http://gcube-system.org/" schemaLocation="http://localhost:9000/whn-manager/gcube/vremanagement/ws/whnmanager?xsd=1"/>
</xsd:schema>
</types>
<message name="addToContext">
<part name="addToContext" element="tns:addToContext"/>
</message>

So the request is forwarded to localhost and not to sharelatex VM.

leftovers of some other manual operation, maybe?

The wsdl in http (used by resourcemanager) has localhost setted but the wsdl in https has the right hostname setted:

https://sharelatex.d4science.org/whn-manager/gcube/vremanagement/ws/whnmanager?wsdl
http://sharelatex.d4science.org/whn-manager/gcube/vremanagement/ws/whnmanager?wsdl

Have you any idea about this different behavior?

Not at all.

We can do that, but as we didn't to set it up until now we should investigate further. The hostname of the VM is set up correctly, so tomcat has all what's needed to populate its headers correctly.

Andrea Dell'Amico wrote:

We can do that, but as we didn't to set it up until now we should investigate further. The hostname of the VM is set up correctly, so tomcat has all what's needed to populate its headers correctly.

I agree with you, we need further investigation. For sure it's better to keep in mind this solution if there will be other similar cases.