Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Che Server | Ping Ws Agent IllegalArgumentException #736

Closed
regismachado opened this issue Mar 17, 2016 · 15 comments
Closed

Che Server | Ping Ws Agent IllegalArgumentException #736

regismachado opened this issue Mar 17, 2016 · 15 comments

Comments

@regismachado
Copy link

Hi,

I'm running che server native in a Centos7 machine.

And Docker in same machine.

I can start ws-agent, but for some reason the process never end because the exeception bellow:

2016-03-17 10:44:33,085[kspaceManager-2] [INFO ] [o.e.c.a.m.s.MachineManager 166] - Creating machine [ws = workspacelsqomas2wphdpv3m: env = wksp-iao3: machine = ws-machine]
Exception in thread "WorkspaceManager-2" java.lang.RuntimeException: java.lang.IllegalArgumentException: protocol = http host = null
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1455)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1441)
at sun.net.www.protocol.http.HttpURLConnection.getHeaderField(HttpURLConnection.java:2979)
at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:489)
at org.eclipse.che.api.core.rest.DefaultHttpJsonRequest.doRequest(DefaultHttpJsonRequest.java:239)
at org.eclipse.che.api.core.rest.DefaultHttpJsonRequest.request(DefaultHttpJsonRequest.java:145)
at org.eclipse.che.api.machine.server.WsAgentLauncherImpl.pingWsAgent(WsAgentLauncherImpl.java:125)
at org.eclipse.che.api.machine.server.WsAgentLauncherImpl.startWsAgent(WsAgentLauncherImpl.java:98)
at org.eclipse.che.api.machine.server.MachineManager.createInstance(MachineManager.java:366)
at org.eclipse.che.api.machine.server.MachineManager.createMachine(MachineManager.java:333)
at org.eclipse.che.api.machine.server.MachineManager.createMachineSync(MachineManager.java:167)
at org.eclipse.che.api.workspace.server.RuntimeWorkspaceRegistry.createMachine(RuntimeWorkspaceRegistry.java:421)
at org.eclipse.che.api.workspace.server.RuntimeWorkspaceRegistry.startEnvironment(RuntimeWorkspaceRegistry.java:320)
at org.eclipse.che.api.workspace.server.RuntimeWorkspaceRegistry.start(RuntimeWorkspaceRegistry.java:146)
at org.eclipse.che.api.workspace.server.WorkspaceManager.performSyncStart(WorkspaceManager.java:637)
at org.eclipse.che.api.workspace.server.WorkspaceManager.lambda$performAsyncStart$2(WorkspaceManager.java:608)
at org.eclipse.che.commons.lang.concurrent.CopyThreadLocalRunnable.run(CopyThreadLocalRunnable.java:28)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalArgumentException: protocol = http host = null
at sun.net.spi.DefaultProxySelector.select(DefaultProxySelector.java:176)
at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1099)
at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:999)
at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:933)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1513)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1441)
at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:480)
... 16 more

My startup command is:

./eclipse-che/bin/che.sh -r:172.10.1.43 -d -g start

Where "r" is the machine ip, i tried with localhost too without success.

My docker ps result:

CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
739482fa8a10 eclipse-che/che_workspacelsqomas2wphdpv3m_ws-machine_jg1am "/bin/sh -c 'sudo /us" 45 minutes ago Up 45 minutes 0.0.0.0:32783->22/tcp, 0.0.0.0:32782->4401/tcp, 0.0.0.0:32780->4403/tcp, 0.0.0.0:32781->4403/tcp, 0.0.0.0:32779->4411/tcp, 0.0.0.0:32778->8000/tcp, 0.0.0.0:32777->8080/tcp, 0.0.0.0:32776->9876/tcp che_workspacelsqomas2wphdpv3m_ws-machine_jg1am
48d5ffac0537 eclipse-che/che_workspacenlw9jbw8oga7iuj4_ws-machine_88210 "/bin/sh -c 'sudo /us" 18 hours ago Up 18 hours 0.0.0.0:32775->22/tcp, 0.0.0.0:32774->4401/tcp, 0.0.0.0:32772->4403/tcp, 0.0.0.0:32773->4403/tcp, 0.0.0.0:32771->4411/tcp, 0.0.0.0:32770->8000/tcp, 0.0.0.0:32769->8080/tcp, 0.0.0.0:32768->9876/tcp che_workspacenlw9jbw8oga7iuj4_ws-machine_88210
2b6159855070 registry:2 "/bin/registry /etc/d" 36 hours ago Up 18 hours 0.0.0.0:5000->5000/tcp registry

I can access ws-agent containers, the tomcat inside machines looks good:

[STDOUT] Listening for transport dt_socket at address: 4403
[STDOUT] 2016-03-16 20:16:45,152[main] [INFO ] [o.a.c.s.VersionLoggerListener 89] - Server version: Apache Tomcat/8.0.29
[STDOUT] 2016-03-16 20:16:45,154[main] [INFO ] [o.a.c.s.VersionLoggerListener 91] - Server built: Nov 20 2015 09:18:00 UTC
[STDOUT] 2016-03-16 20:16:45,159[main] [INFO ] [o.a.c.s.VersionLoggerListener 93] - Server number: 8.0.29.0
[STDOUT] 2016-03-16 20:16:45,160[main] [INFO ] [o.a.c.s.VersionLoggerListener 95] - OS Name: Linux
[STDOUT] 2016-03-16 20:16:45,160[main] [INFO ] [o.a.c.s.VersionLoggerListener 97] - OS Version: 3.10.0-327.10.1.el7.x86_64
[STDOUT] 2016-03-16 20:16:45,160[main] [INFO ] [o.a.c.s.VersionLoggerListener 99] - Architecture: amd64
[STDOUT] 2016-03-16 20:16:45,160[main] [INFO ] [o.a.c.s.VersionLoggerListener 101] - Java Home: /opt/jdk1.8.0_45/jre
[STDOUT] 2016-03-16 20:16:45,161[main] [INFO ] [o.a.c.s.VersionLoggerListener 103] - JVM Version: 1.8.0_45-b14
[STDOUT] 2016-03-16 20:16:45,161[main] [INFO ] [o.a.c.s.VersionLoggerListener 105] - JVM Vendor: Oracle Corporation
[STDOUT] 2016-03-16 20:16:45,161[main] [INFO ] [o.a.c.s.VersionLoggerListener 107] - CATALINA_BASE: /home/user/che/ws-agent
[STDOUT] 2016-03-16 20:16:45,161[main] [INFO ] [o.a.c.s.VersionLoggerListener 109] - CATALINA_HOME: /home/user/che/ws-agent
[STDOUT] 2016-03-16 20:16:45,162[main] [INFO ] [o.a.c.s.VersionLoggerListener 115] - Command line argument: -Djava.util.logging.config.file=/home/user/che/ws-agent/conf/logging.properties
[STDOUT] 2016-03-16 20:16:45,162[main] [INFO ] [o.a.c.s.VersionLoggerListener 115] - Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
[STDOUT] 2016-03-16 20:16:45,162[main] [INFO ] [o.a.c.s.VersionLoggerListener 115] - Command line argument: -Xms256m
[STDOUT] 2016-03-16 20:16:45,162[main] [INFO ] [o.a.c.s.VersionLoggerListener 115] - Command line argument: -Xmx1024m
[STDOUT] 2016-03-16 20:16:45,162[main] [INFO ] [o.a.c.s.VersionLoggerListener 115] - Command line argument: -Djava.security.egd=file:/dev/./urandom
[STDOUT] 2016-03-16 20:16:45,163[main] [INFO ] [o.a.c.s.VersionLoggerListener 115] - Command line argument: -Dche.logs.dir=/home/user/che/ws-agent/logs
[STDOUT] 2016-03-16 20:16:45,163[main] [INFO ] [o.a.c.s.VersionLoggerListener 115] - Command line argument: -Dcom.sun.management.jmxremote
[STDOUT] 2016-03-16 20:16:45,163[main] [INFO ] [o.a.c.s.VersionLoggerListener 115] - Command line argument: -Dcom.sun.management.jmxremote.ssl=false
[STDOUT] 2016-03-16 20:16:45,163[main] [INFO ] [o.a.c.s.VersionLoggerListener 115] - Command line argument: -Dcom.sun.management.jmxremote.authenticate=false
[STDOUT] 2016-03-16 20:16:45,164[main] [INFO ] [o.a.c.s.VersionLoggerListener 115] - Command line argument: -Dche.local.conf.dir=/mnt/che/conf
[STDOUT] 2016-03-16 20:16:45,164[main] [INFO ] [o.a.c.s.VersionLoggerListener 115] - Command line argument: -agentlib:jdwp=transport=dt_socket,address=4403,server=y,suspend=n
[STDOUT] 2016-03-16 20:16:45,164[main] [INFO ] [o.a.c.s.VersionLoggerListener 115] - Command line argument: -Djava.endorsed.dirs=/home/user/che/ws-agent/endorsed
[STDOUT] 2016-03-16 20:16:45,164[main] [INFO ] [o.a.c.s.VersionLoggerListener 115] - Command line argument: -Dcatalina.base=/home/user/che/ws-agent
[STDOUT] 2016-03-16 20:16:45,164[main] [INFO ] [o.a.c.s.VersionLoggerListener 115] - Command line argument: -Dcatalina.home=/home/user/che/ws-agent
[STDOUT] 2016-03-16 20:16:45,165[main] [INFO ] [o.a.c.s.VersionLoggerListener 115] - Command line argument: -Djava.io.tmpdir=/home/user/che/ws-agent/temp
[STDOUT] 2016-03-16 20:16:45,311[main] [INFO ] [o.a.c.http11.Http11NioProtocol 425] - Initializing ProtocolHandler ["http-nio-4401"]
[STDOUT] 2016-03-16 20:16:45,327[main] [INFO ] [o.a.t.util.net.NioSelectorPool 72] - Using a shared selector for servlet write/read
[STDOUT] 2016-03-16 20:16:45,330[main] [INFO ] [o.a.catalina.startup.Catalina 587] - Initialization processed in 444 ms
[STDOUT] 2016-03-16 20:16:45,407[main] [INFO ] [c.m.JmxRemoteLifecycleListener 332] - The JMX Remote Listener has configured the registry on port 32002 and the server on port 32102 for the Platform server
[STDOUT] 2016-03-16 20:16:45,407[main] [INFO ] [o.a.c.core.StandardService 433] - Starting service Catalina
[STDOUT] 2016-03-16 20:16:45,407[main] [INFO ] [o.a.c.core.StandardEngine 259] - Starting Servlet Engine: Apache Tomcat/8.0.29
[STDOUT] 2016-03-16 20:16:45,468[ost-startStop-1] [INFO ] [o.a.c.startup.HostConfig 916] - Deploying web application archive /home/user/che/ws-agent/webapps/ide.war
[STDOUT] Wed Mar 16 20:16:50 UTC 2016 - [localhost-startStop-1] Product-specified preferences called before plugin is started
[STDOUT] 2016-03-16 20:16:50,738[rrest.WSClient1] [INFO ] [.c.a.c.n.WSocketEventBusClient 223] - Open connection to ws://che-host:8080/ide/api/eventbus/?token=dummy_token.
[STDOUT] 2016-03-16 20:16:50,822[ost-startStop-1] [INFO ] [o.a.c.startup.HostConfig 980] - Deployment of web application archive /home/user/che/ws-agent/webapps/ide.war has finished in 5,354 ms
[STDOUT] 2016-03-16 20:16:50,827[main] [INFO ] [o.a.c.http11.Http11NioProtocol 470] - Starting ProtocolHandler ["http-nio-4401"]
[STDOUT] 2016-03-16 20:16:50,834[main] [INFO ] [o.a.catalina.startup.Catalina 638] - Server startup in 5503 ms
[STDOUT] 2016-03-16 20:47:10,024[lient-AsyncIO-2] [INFO ] [.c.a.c.n.WSocketEventBusClient 192] - Close connection to ws://che-host:8080/ide/api/eventbus/?token=dummy_token with status 1000 message Http session destroyed.
[STDOUT] 2016-03-16 20:47:10,024[lient-AsyncIO-2] [INFO ] [.c.a.c.n.WSocketEventBusClient 193] - Init connection task ws://che-host:8080/ide/api/eventbus/?token=dummy_token
[STDOUT] 2016-03-16 20:47:10,030[rrest.WSClient2] [INFO ] [.c.a.c.n.WSocketEventBusClient 223] - Open connection to ws://che-host:8080/ide/api/eventbus/?token=dummy_token.
[STDOUT] 2016-03-16 21:17:10,078[lient-AsyncIO-2] [INFO ] [.c.a.c.n.WSocketEventBusClient 192] - Close connection to ws://che-host:8080/ide/api/eventbus/?token=dummy_token with status 1000 message Http session destroyed.

I think, for some reason, the Che can't find the containers socket/host/ip to start a comunication.
@ghost
Copy link

ghost commented Mar 17, 2016

What is your Docker version and do you have DOCKER_HOST env variable exported in your system?

The first log is from the server, and it looks like it cannot connect to workspace.

@regismachado
Copy link
Author

I revised the docker config and docker host isn't set in env variable and docker daemon doesn't have a ipv4 host associated.

  • I make some changes.
  • First, edited daemon to use localhost port 4243
  • in file /usr/lib/systemd/system/docker.service

/usr/bin/docker daemon -H tcp://127.0.0.1:4243 -H fd://

  • I used netstat -ant |grep 4243 to check the daemon config

tcp 0 0 127.0.0.1:4243 0.0.0.0:* LISTEN

  • Then i set de env in .bashrc and check config

echo $DOCKER_HOST
tcp://127.0.0.1:4243

  • But the error persist.

Exception in thread "WorkspaceManager-0" java.lang.RuntimeException: java.lang.IllegalArgumentException: protocol = http host = null
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1455)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1441)
at sun.net.www.protocol.http.HttpURLConnection.getHeaderField(HttpURLConnection.java:2979)
at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:489)
at org.eclipse.che.api.core.rest.DefaultHttpJsonRequest.doRequest(DefaultHttpJsonRequest.java:239)
at org.eclipse.che.api.core.rest.DefaultHttpJsonRequest.request(DefaultHttpJsonRequest.java:145)
at org.eclipse.che.api.machine.server.WsAgentLauncherImpl.pingWsAgent(WsAgentLauncherImpl.java:125)
at org.eclipse.che.api.machine.server.WsAgentLauncherImpl.startWsAgent(WsAgentLauncherImpl.java:98)

@ghost
Copy link

ghost commented Mar 18, 2016

What is your Docker version?

@regismachado
Copy link
Author

My docker version 1.10.3, build 20f81dd

Looking in journalctl -u docker i found this log msg each time i try to run a workspace

Mar 17 18:48:12 gstmapp011p.gestum.local docker[15051]: time="2016-03-17T18:48:12.314548532-03:00" level=error msg="attach: stdout: write tcp 127.0.0.1:4243->127.0.0.1:46825: write: broken pipe"
Mar 18 08:48:03 gstmapp011p.gestum.local docker[15051]: time="2016-03-18T08:48:03.523248913-03:00" level=error msg="Error running exec in container: attach failed with error: write tcp 127.0.0.1:4243->127.0.0.1:46825: write: broken pipe\n"

I changed the Docker_host and Docker daemon parameters to use the machine ip instead of localhost. Then the errors above stopped.

But the error below continue:

Exception in thread "WorkspaceManager-0" java.lang.RuntimeException: java.lang.IllegalArgumentException: protocol = http host = null
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1455)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1441)
at sun.net.www.protocol.http.HttpURLConnection.getHeaderField(HttpURLConnection.java:2979)
at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:489)
at org.eclipse.che.api.core.rest.DefaultHttpJsonRequest.doRequest(DefaultHttpJsonRequest.java:239)
at org.eclipse.che.api.core.rest.DefaultHttpJsonRequest.request(DefaultHttpJsonRequest.java:145)
at org.eclipse.che.api.machine.server.WsAgentLauncherImpl.pingWsAgent(WsAgentLauncherImpl.java:125)

Exist some way to debug the WsAgentLauncherImpl parameters and to see why host and protocol is going null?

@ghost
Copy link

ghost commented Mar 18, 2016

If you go to /tomcat/conf/logback.xml and change <root level="INFO"> to <root level="SEVERE"> you will have a detailed log. Make sure you delete /tomcat/logs/2016 dir before you run Che in this mode.

Share log file with us please.

Another thing you can do is to run Che, run a workspace, get your usual error but then try to ping a workspace agent from your localhost:

localhost:${port} where ${port} is the port mapped to 4401 in a container, for example:

curl -v localhost:32810

@regismachado
Copy link
Author

Follows the full log

2016-03-18 15:45:21,419[nio-8080-exec-2] [DEBUG] [o.a.t.util.http.Parameters 99] - Set query string encoding to UTF-8
2016-03-18 15:45:21,419[nio-8080-exec-2] [DEBUG] [o.a.c.connector.CoyoteAdapter 1100] - The variable [uriBC] has value [/ide/api/recipe/recipeu05v2cwcwa7fxqs1/script]
2016-03-18 15:45:21,419[nio-8080-exec-2] [DEBUG] [o.a.c.connector.CoyoteAdapter 1102] - The variable [semicolon] has value [-1]
2016-03-18 15:45:21,419[nio-8080-exec-2] [DEBUG] [o.a.c.connector.CoyoteAdapter 1104] - The variable [enc] has value [utf-8]
2016-03-18 15:45:21,419[nio-8080-exec-2] [DEBUG] [o.a.c.valves.RemoteIpValve 652] - Incoming request /ide/api/recipe/recipeu05v2cwcwa7fxqs1/script with originalRemoteAddr '172.10.1.43', originalRemoteHost='172.10.1.43', originalSecure='false', originalScheme='http' will be seen as newRemoteAddr='172.10.1.43', newRemoteHost='172.10.1.43', newScheme='http', newSecure='false'
2016-03-18 15:45:21,423[nio-8080-exec-1] [DEBUG] [o.a.c.h.AbstractOutputBuffer 296] - Flushing the gzip filter at position 1 of the filter chain...
2016-03-18 15:45:21,423[nio-8080-exec-1] [DEBUG] [o.a.c.h.f.GzipOutputFilter 100] - Flushing the compression stream!
2016-03-18 15:45:21,426[nio-8080-exec-1] [DEBUG] [o.a.t.util.http.Parameters 92] - Set encoding to UTF-8
2016-03-18 15:45:21,426[nio-8080-exec-1] [DEBUG] [o.a.t.util.http.Parameters 177] - Decoding query null UTF-8
2016-03-18 15:45:21,426[nio-8080-exec-1] [DEBUG] [o.a.t.util.http.Parameters 239] - Start processing with input [environment=wksp-6giu]
2016-03-18 15:45:21,428[nio-8080-exec-1] [DEBUG] [o.a.c.http11.Http11NioProtocol 717] - Socket: [org.apache.tomcat.util.net.NioEndpoint$KeyAttachment@74644726:org.apache.tomcat.util.net.NioChannel@6ec358c2:java.nio.channels.SocketChannel[connected local=/172.10.1.43:8080 remote=/172.10.1.13:55648]], Status in: [OPEN_READ], State out: [CLOSED]
2016-03-18 15:45:21,431[nio-8080-exec-1] [DEBUG] [o.a.t.util.threads.LimitLatch 126] - Counting down[http-nio-8080-exec-1] latch=2
2016-03-18 15:45:21,437[nio-8080-exec-2] [DEBUG] [o.a.t.util.http.Parameters 92] - Set encoding to ISO-8859-1
2016-03-18 15:45:21,438[nio-8080-exec-2] [DEBUG] [o.a.t.util.http.Parameters 177] - Decoding query null UTF-8
2016-03-18 15:45:21,438[nio-8080-exec-2] [DEBUG] [o.a.t.util.http.Parameters 239] - Start processing with input [token=dummy_token]
2016-03-18 15:45:21,440[nio-8080-exec-2] [DEBUG] [o.a.c.http11.Http11NioProtocol 717] - Socket: [org.apache.tomcat.util.net.NioEndpoint$KeyAttachment@55ccbccf:org.apache.tomcat.util.net.NioChannel@641b4c00:java.nio.channels.SocketChannel[connected local=/127.0.0.1:8080 remote=/172.10.1.43:46122]], Status in: [OPEN_READ], State out: [OPEN]
2016-03-18 15:45:21,448[kspaceManager-0] [DEBUG] [o.e.c.a.c.n.EventService 104] - Publish event {"machineId":"machinen3n6e4zdluu54f10","eventType":"CREATING","dev":true,"machineName":"ws-machine","workspaceId":"workspacebf0kq0fs0zse4q0b"} for org.eclipse.che.api.core.notification.WSocketEventBusServer$1@65af3310
2016-03-18 15:45:21,449[kspaceManager-0] [DEBUG] [o.e.c.a.c.n.EventService 104] - Publish event {"machineId":"machinen3n6e4zdluu54f10","eventType":"CREATING","dev":true,"machineName":"ws-machine","workspaceId":"workspacebf0kq0fs0zse4q0b"} for org.eclipse.che.api.machine.server.event.MachineStateMessenger@396c1f61
2016-03-18 15:45:21,449[kspaceManager-0] [DEBUG] [o.e.c.a.c.n.EventService 104] - Publish event {"machineId":"machinen3n6e4zdluu54f10","eventType":"CREATING","dev":true,"machineName":"ws-machine","workspaceId":"workspacebf0kq0fs0zse4q0b"} for org.eclipse.che.plugin.docker.machine.ext.DockerMachineTerminalLauncher$1@210de53e
2016-03-18 15:45:21,449[kspaceManager-0] [DEBUG] [o.e.c.a.c.n.EventService 104] - Publish event {"machineId":"machinen3n6e4zdluu54f10","eventType":"CREATING","dev":true,"machineName":"ws-machine","workspaceId":"workspacebf0kq0fs0zse4q0b"} for org.eclipse.che.api.workspace.server.event.MachineStateListener@1a112518
2016-03-18 15:45:21,450[kspaceManager-0] [DEBUG] [o.e.c.a.c.n.EventService 104] - Publish event {"machineId":"machinen3n6e4zdluu54f10","eventType":"CREATING","dev":true,"machineName":"ws-machine","workspaceId":"workspacebf0kq0fs0zse4q0b"} for org.eclipse.che.ide.ext.machine.server.ssh.KeysInjector$1@7ca34c64
2016-03-18 15:45:26,983[kspaceManager-0] [DEBUG] [.e.c.a.m.s.WsAgentLauncherImpl 92] - Starts pinging ws agent. Workspace ID:workspacebf0kq0fs0zse4q0b. Url:DefaultHttpJsonRequest{url='http:/ide/ext/', timeout=2000, method='GET', body=null, queryParams=null}. Timestamp:1458326726983
2016-03-18 15:45:26,984[achineManager-0] [DEBUG] [o.e.c.a.c.n.EventService 104] - Publish event {"machineId":"machinen3n6e4zdluu54f10","eventType":"STARTED","processId":1} for org.eclipse.che.api.core.notification.WSocketEventBusServer$1@65af3310
2016-03-18 15:45:26,985[achineManager-0] [DEBUG] [o.e.c.a.c.n.EventService 104] - Publish event {"machineId":"machinen3n6e4zdluu54f10","eventType":"STARTED","processId":1} for org.eclipse.che.api.machine.server.event.MachineProcessMessenger@532c33f0
2016-03-18 15:45:26,985[achineManager-0] [DEBUG] [o.e.c.a.c.n.EventService 104] - Publish event {"machineId":"machinen3n6e4zdluu54f10","eventType":"STARTED","processId":1} for org.eclipse.che.plugin.docker.machine.DockerInstanceProcessesCleaner@6a44b62a
Exception in thread "WorkspaceManager-0" java.lang.RuntimeException: java.lang.IllegalArgumentException: protocol = http host = null
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1455)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1441)
at sun.net.www.protocol.http.HttpURLConnection.getHeaderField(HttpURLConnection.java:2979)
at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:489)
at org.eclipse.che.api.core.rest.DefaultHttpJsonRequest.doRequest(DefaultHttpJsonRequest.java:239)
at org.eclipse.che.api.core.rest.DefaultHttpJsonRequest.request(DefaultHttpJsonRequest.java:145)
at org.eclipse.che.api.machine.server.WsAgentLauncherImpl.pingWsAgent(WsAgentLauncherImpl.java:125)
at org.eclipse.che.api.machine.server.WsAgentLauncherImpl.startWsAgent(WsAgentLauncherImpl.java:98)
at org.eclipse.che.api.machine.server.MachineManager.createInstance(MachineManager.java:366)
at org.eclipse.che.api.machine.server.MachineManager.createMachine(MachineManager.java:333)
at org.eclipse.che.api.machine.server.MachineManager.createMachineSync(MachineManager.java:167)
at org.eclipse.che.api.workspace.server.RuntimeWorkspaceRegistry.createMachine(RuntimeWorkspaceRegistry.java:421)
at org.eclipse.che.api.workspace.server.RuntimeWorkspaceRegistry.startEnvironment(RuntimeWorkspaceRegistry.java:320)
at org.eclipse.che.api.workspace.server.RuntimeWorkspaceRegistry.start(RuntimeWorkspaceRegistry.java:146)
at org.eclipse.che.api.workspace.server.WorkspaceManager.performSyncStart(WorkspaceManager.java:637)
at org.eclipse.che.api.workspace.server.WorkspaceManager.lambda$performAsyncStart$2(WorkspaceManager.java:608)
at org.eclipse.che.commons.lang.concurrent.CopyThreadLocalRunnable.run(CopyThreadLocalRunnable.java:28)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalArgumentException: protocol = http host = null
at sun.net.spi.DefaultProxySelector.select(DefaultProxySelector.java:176)
at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1099)
at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:999)
at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:933)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1513)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1441)
at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:480)
... 16 more
2016-03-18 15:45:31,448[nio-8080-exec-3] [DEBUG] [o.a.c.h.Http11NioProcessor 1038] - Error parsing HTTP request header
java.io.EOFException: Unexpected EOF read on the socket
at org.apache.coyote.http11.InternalNioInputBuffer.fill(InternalNioInputBuffer.java:152) ~[tomcat-coyote.jar:8.0.29]
at org.apache.coyote.http11.AbstractNioInputBuffer.parseRequestLine(AbstractNioInputBuffer.java:190) ~[tomcat-coyote.jar:8.0.29]
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1010) ~[tomcat-coyote.jar:8.0.29]
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:674) [tomcat-coyote.jar:8.0.29]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500) [tomcat-coyote.jar:8.0.29]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456) [tomcat-coyote.jar:8.0.29]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_71]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_71]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-util.jar:8.0.29]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_71]
2016-03-18 15:45:31,449[nio-8080-exec-3] [DEBUG] [o.a.c.http11.Http11NioProtocol 717] - Socket: [org.apache.tomcat.util.net.NioEndpoint$KeyAttachment@55ccbccf:org.apache.tomcat.util.net.NioChannel@641b4c00:java.nio.channels.SocketChannel[connected local=/127.0.0.1:8080 remote=/172.10.1.43:46122]], Status in: [OPEN_READ], State out: [CLOSED]
2016-03-18 15:45:31,449[nio-8080-exec-3] [DEBUG] [o.a.t.util.threads.LimitLatch 126] - Counting down[http-nio-8080-exec-3] latch=1
2016-03-18 15:45:33,480[8080-Acceptor-0] [DEBUG] [o.a.t.util.threads.LimitLatch 113] - Counting up[http-nio-8080-Acceptor-0] latch=1
2016-03-18 15:45:33,483[nio-8080-exec-4] [DEBUG] [o.a.c.h.InternalNioInputBuffer 208] - Received [GET /ide/api/ HTTP/1.1
Accept: application/json
Cache-Control: no-cache
Pragma: no-cache
User-Agent: Java/1.8.0_45
Host: che-host:8080
Connection: keep-alive

]
2016-03-18 15:45:33,483[nio-8080-exec-4] [DEBUG] [o.a.c.connector.CoyoteAdapter 1100] - The variable [uriBC] has value [/ide/api/]
2016-03-18 15:45:33,483[nio-8080-exec-4] [DEBUG] [o.a.c.connector.CoyoteAdapter 1102] - The variable [semicolon] has value [-1]
2016-03-18 15:45:33,483[nio-8080-exec-4] [DEBUG] [o.a.c.connector.CoyoteAdapter 1104] - The variable [enc] has value [utf-8]
2016-03-18 15:45:33,484[nio-8080-exec-4] [DEBUG] [o.a.c.valves.RemoteIpValve 652] - Incoming request /ide/api/ with originalRemoteAddr '172.17.0.3', originalRemoteHost='172.17.0.3', originalSecure='false', originalScheme='http' will be seen as newRemoteAddr='172.17.0.3', newRemoteHost='172.17.0.3', newScheme='http', newSecure='false'
2016-03-18 15:45:33,494[nio-8080-exec-4] [DEBUG] [o.a.t.util.http.Parameters 92] - Set encoding to ISO-8859-1
2016-03-18 15:45:33,495[nio-8080-exec-4] [DEBUG] [o.a.c.http11.Http11NioProtocol 717] - Socket: [org.apache.tomcat.util.net.NioEndpoint$KeyAttachment@281ce8da:org.apache.tomcat.util.net.NioChannel@641b4c00:java.nio.channels.SocketChannel[connected local=/172.17.0.1:8080 remote=/172.17.0.3:55454]], Status in: [OPEN_READ], State out: [OPEN]
2016-03-18 15:45:33,609[8080-Acceptor-0] [DEBUG] [o.a.t.util.threads.LimitLatch 113] - Counting up[http-nio-8080-Acceptor-0] latch=2
2016-03-18 15:45:33,618[nio-8080-exec-5] [DEBUG] [o.a.c.h.InternalNioInputBuffer 208] - Received [GET /ide/api/eventbus/?token=dummy_token HTTP/1.1
Sec-WebSocket-Key: FZxfPmZsZkZD5lQ0hs4N+A==
Connection: upgrade
Sec-WebSocket-Version: 13
Host: che-host:8080
Upgrade: websocket

]
2016-03-18 15:45:33,619[nio-8080-exec-5] [DEBUG] [o.a.c.connector.CoyoteAdapter 1100] - The variable [uriBC] has value [/ide/api/eventbus/]
2016-03-18 15:45:33,619[nio-8080-exec-5] [DEBUG] [o.a.c.connector.CoyoteAdapter 1102] - The variable [semicolon] has value [-1]
2016-03-18 15:45:33,619[nio-8080-exec-5] [DEBUG] [o.a.c.connector.CoyoteAdapter 1104] - The variable [enc] has value [utf-8]
2016-03-18 15:45:33,619[nio-8080-exec-5] [DEBUG] [o.a.c.valves.RemoteIpValve 652] - Incoming request /ide/api/eventbus/ with originalRemoteAddr '172.17.0.3', originalRemoteHost='172.17.0.3', originalSecure='false', originalScheme='http' will be seen as newRemoteAddr='172.17.0.3', newRemoteHost='172.17.0.3', newScheme='http', newSecure='false'
2016-03-18 15:45:33,633[nio-8080-exec-5] [DEBUG] [o.a.t.util.http.Parameters 92] - Set encoding to ISO-8859-1
2016-03-18 15:45:33,633[nio-8080-exec-5] [DEBUG] [o.a.t.util.http.Parameters 177] - Decoding query null UTF-8
2016-03-18 15:45:33,633[nio-8080-exec-5] [DEBUG] [o.a.t.util.http.Parameters 239] - Start processing with input [token=dummy_token]
2016-03-18 15:45:33,655[nio-8080-exec-5] [DEBUG] [o.a.tomcat.websocket.WsSession 194] - Created WebSocket session [0]
2016-03-18 15:45:33,667[nio-8080-exec-5] [DEBUG] [o.e.w.WSConnectionContext 92] - Open connection WSConnectionImpl{id=1, wsSession=0, httpSession=A9800998CF3CC2E0543C3061C3ED80DE, channels=[]}
2016-03-18 15:45:33,684[nio-8080-exec-5] [DEBUG] [o.a.c.http11.Http11NioProtocol 717] - Socket: [org.apache.tomcat.util.net.NioEndpoint$KeyAttachment@49fa8440:org.apache.tomcat.util.net.NioChannel@6ec358c2:java.nio.channels.SocketChannel[connected local=/172.17.0.1:8080 remote=/172.17.0.3:55455]], Status in: [OPEN_READ], State out: [UPGRADING]
2016-03-18 15:45:33,684[nio-8080-exec-5] [DEBUG] [o.a.c.http11.Http11NioProtocol 717] - Socket: [org.apache.tomcat.util.net.NioEndpoint$KeyAttachment@49fa8440:org.apache.tomcat.util.net.NioChannel@6ec358c2:java.nio.channels.SocketChannel[connected local=/172.17.0.1:8080 remote=/172.17.0.3:55455]], Status in: [OPEN_READ], State out: [UPGRADED]
2016-03-18 15:45:33,727[nio-8080-exec-6] [DEBUG] [o.a.c.http11.Http11NioProtocol 717] - Socket: [org.apache.tomcat.util.net.NioEndpoint$KeyAttachment@49fa8440:org.apache.tomcat.util.net.NioChannel@6ec358c2:java.nio.channels.SocketChannel[connected local=/172.17.0.1:8080 remote=/172.17.0.3:55455]], Status in: [OPEN_READ], State out: [UPGRADED]
2016-03-18 15:45:33,737[ocalhost-/ide-1] [DEBUG] [o.e.w.message.MessageSender 149] - SendQueue size 0 , maxNumberOfMessageInQueue 1000000000 result true
2016-03-18 15:45:43,502[nio-8080-exec-7] [DEBUG] [o.a.c.h.Http11NioProcessor 1038] - Error parsing HTTP request header
java.io.EOFException: Unexpected EOF read on the socket
at org.apache.coyote.http11.InternalNioInputBuffer.fill(InternalNioInputBuffer.java:152) ~[tomcat-coyote.jar:8.0.29]
at org.apache.coyote.http11.AbstractNioInputBuffer.parseRequestLine(AbstractNioInputBuffer.java:190) ~[tomcat-coyote.jar:8.0.29]
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1010) ~[tomcat-coyote.jar:8.0.29]
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:674) [tomcat-coyote.jar:8.0.29]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500) [tomcat-coyote.jar:8.0.29]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456) [tomcat-coyote.jar:8.0.29]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_71]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_71]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-util.jar:8.0.29]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_71]
2016-03-18 15:45:43,502[nio-8080-exec-7] [DEBUG] [o.a.c.http11.Http11NioProtocol 717] - Socket: [org.apache.tomcat.util.net.NioEndpoint$KeyAttachment@281ce8da:org.apache.tomcat.util.net.NioChannel@641b4c00:java.nio.channels.SocketChannel[connected local=/172.17.0.1:8080 remote=/172.17.0.3:55454]], Status in: [OPEN_READ], State out: [CLOSED]
2016-03-18 15:45:43,502[nio-8080-exec-7] [DEBUG] [o.a.t.util.threads.LimitLatch 126] - Counting down[http-nio-8080-exec-7] latch=2
2016-03-18 15:45:51,444[FileCleaner] [DEBUG] [o.e.c.a.core.util.FileCleaner 90] - Delete file '/home/gestum/eclipse-che/tomcat/temp/recipe6001381270740025501.tmp'
2016-03-18 15:45:51,444[FileCleaner] [DEBUG] [o.e.c.a.core.util.FileCleaner 90] - Delete file '/home/gestum/eclipse-che/tomcat/temp/4356486392077201796.tar'
2016-03-18 15:45:51,444[FileCleaner] [DEBUG] [o.e.c.a.core.util.FileCleaner 90] - Delete file '/home/gestum/eclipse-che/tomcat/temp/1962722623367647495'

In the log, this line caught my attention:

2016-03-18 15:45:26,983[kspaceManager-0] [DEBUG] [.e.c.a.m.s.WsAgentLauncherImpl 92] - Starts pinging ws agent. Workspace ID:workspacebf0kq0fs0zse4q0b. Url:DefaultHttpJsonRequest{url='http:/ide/ext/', timeout=2000, method='GET', body=null, queryParams=null}. Timestamp:1458326726983

Folows my curl test:

curl -v localhost:32782/ide/

* About to connect() to localhost port 32782 (#0)
*   Trying ::1...
* Connected to localhost (::1) port 32782 (#0)
 GET /ide/ HTTP/1.1
 User-Agent: curl/7.29.0
 Host: localhost:32782
 Accept: */*


 HTTP/1.1 404 Not Found
 Server: Apache-Coyote/1.1
 Content-Type: text/html;charset=utf-8
 Content-Language: en
 Content-Length: 1002
 Date: Fri, 18 Mar 2016 19:03:25 GMT

* Connection #0 to host localhost left intact

<!DOCTYPE html><html><head><title>Apache Tomcat/8.0.29 - Error report</title><style type="text/css">H1 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:22px;} H2 
{font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:16px;} H3 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:14px;} 
BODY {font-family:Tahoma,Arial,sans-serif;color:black;background-color:white;} B {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;} 
P {font-family:Tahoma,Arial,sans-serif;background:white;color:black;font-size:12px;}A {color : black;}A.name {color : black;}.line {height: 1px; background-color: #525D76; border: none;}</style> 
</head><body><h1>HTTP Status 404 - /ide/</h1><div class="line"></div><p><b>type</b> Status report</p><p><b>message</b> 
<u>/ide/</u></p><p><b>description</b> <u>The requested resource is not available.</u></p><hr class="line"><h3>Apache Tomcat/8.0.29</h3></bo
```dy>

@ghost
Copy link

ghost commented Mar 18, 2016

Can you just run curl -v localhost:32782? Without /ide/ext

@regismachado
Copy link
Author

Yes, follows


curl -v localhost:32782
* About to connect() to localhost port 32782 (#0)
*   Trying ::1...
* Connected to localhost (::1) port 32782 (#0)
> GET / HTTP/1.1
> User-Agent: curl/7.29.0
> Host: localhost:32782
> Accept: */*
>
< HTTP/1.1 404 Not Found
< Server: Apache-Coyote/1.1
< Content-Length: 0
< Date: Fri, 18 Mar 2016 19:22:53 GMT
<
* Connection #0 to host localhost left intact

@ghost
Copy link

ghost commented Mar 18, 2016

Looks like you have ipv4 disabled. Pinging localhost should normally use 127.0.0.1

Is that true for your system?

@regismachado
Copy link
Author

Uhn..
Looks like docker containers receive only ipv6.

docker0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet 172.17.0.1  netmask 255.255.0.0  broadcast 0.0.0.0
        inet6 fe80::42:f0ff:fe2b:bfc8  prefixlen 64  scopeid 0x20<link>
        ether 02:42:f0:2b:bf:c8  txqueuelen 0  (Ethernet)
        RX packets 2526  bytes 206105 (201.2 KiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 2124  bytes 255537 (249.5 KiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

eth0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet 172.10.1.43  netmask 255.255.255.0  broadcast 172.10.1.255
        inet6 fe80::cc65:cfff:fe20:a6da  prefixlen 64  scopeid 0x20<link>
        ether ce:65:cf:20:a6:da  txqueuelen 1000  (Ethernet)
        RX packets 3219290  bytes 1172719969 (1.0 GiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 2487355  bytes 273199146 (260.5 MiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

lo: flags=73<UP,LOOPBACK,RUNNING>  mtu 65536
        inet 127.0.0.1  netmask 255.0.0.0
        inet6 ::1  prefixlen 128  scopeid 0x10<host>
        loop  txqueuelen 0  (Local Loopback)
        RX packets 3351652  bytes 168306589 (160.5 MiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 3351652  bytes 168306589 (160.5 MiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

veth216574f: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet6 fe80::1c9d:87ff:fef5:be27  prefixlen 64  scopeid 0x20<link>
        ether 1e:9d:87:f5:be:27  txqueuelen 0  (Ethernet)
        RX packets 50  bytes 3096 (3.0 KiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 486  bytes 35768 (34.9 KiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

veth6627bf8: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet6 fe80::905d:adff:feeb:89f0  prefixlen 64  scopeid 0x20<link>
        ether 92:5d:ad:eb:89:f0  txqueuelen 0  (Ethernet)
        RX packets 22  bytes 1493 (1.4 KiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 121  bytes 8768 (8.5 KiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0

@ghost
Copy link

ghost commented Mar 18, 2016

Praps this can help - https://docs.docker.com/engine/userguide/networking/default_network/ipv6/

You may want to re-run Docker daemon with IPv4 enabled

@ghost ghost mentioned this issue Mar 20, 2016
Closed
@regismachado
Copy link
Author

Hi,

I have deleted the che project and make a fresh install using the eclipse-che-latest.jar, this is the same installer I used before and now the workspace respond the ping.

Looks like the installer created some files config based on wrong enviroments variables used by me, after I adjust the variables and make a reinstall, the problem was solved.

Now, looking in the logs I see the ping request url correct

2016-03-20 14:54:26,731[kspaceManager-0] [DEBUG] [.e.c.a.m.s.WsAgentLauncherImpl 92] - Starts pinging ws agent. Workspace ID:workspacews511a1jb4e7ggr3. Url:DefaultHttpJsonRequest{**url='http://172.10.1.43:32854/ide/ext/'**, timeout=2000, method='GET', body=null, queryParams=null}. Timestamp:1458496466731

@ghost
Copy link

ghost commented Mar 20, 2016

@regismachado When you ping localhost, it is still not 127.0.0.1?

There's a similar issue here - #261

Can you please share the solution? At least smth that worked for you.

@ghost ghost mentioned this issue Mar 21, 2016
Closed
@regismachado
Copy link
Author

@eivantsov, yes.

My connection try first through IPV6 and then if it fail, tries with IPV4, but IPV6 is responding well

@ghost
Copy link

ghost commented Apr 5, 2016

Closing the issue as the original problem seems to have been resolved. I'll add a note in docs about IPv4/6

@ghost ghost closed this as completed Apr 5, 2016
This issue was closed.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@regismachado