Container-wait-time heartbeat?

moliveira · January 12, 2018, 6:44pm

Hi!

When trying to launch my app, the container is unresponsive on the first try. When this happens, the following Error is shown on the browser:

Error
Status code: 404

Message:

Stack Trace:

However, it is always successfully launched on the second try.
This is what appears on the ShinyProxy logs:

2018-01-12 18:31:11.292  INFO 34950 --- [  XNIO-2 task-5] c.s.docker.client.DefaultDockerClient    : Starting container with Id: 68722ab696d5f124df724bc4a4749645fd542c0c22ae65121e6ae86ec2333b0d
2018-01-12 18:31:13.895  WARN 34950 --- [  XNIO-2 task-5] eu.openanalytics.services.DockerService  : Container unresponsive, trying again (2/15): http://localhost:20000
2018-01-12 18:31:16.335  INFO 34950 --- [  XNIO-2 task-5] eu.openanalytics.services.DockerService  : Proxy activated [user: 1G_XolpLntsR9dVy2554IS9SgyhxaJU2A5KIa7FV] [app: replid] [port: 20000]

After the last line appears on the logs, if I refresh the page on the browser, the app will be working correctly. However, other users may not know that refreshing once is enough (and it is inconvenient even if they do).

The inclusion of “container-wait-time” as an option has been very useful to me.
I was wondering if you think a configuration value that would function for container-wait-time similarly to how “heartbeat-rate” functions for “heartbeat-timeout” would fix this issue.
If so, do you have plans for (or would you consider) adding a configurable value like this in the future?

Thanks in advance,
Mariana

fmichielssen · January 16, 2018, 12:27pm

Hi Mariana,

I don’t fully understand this problem. When a user is launching an app, and they are seeing the loading animation, only two things can happen:

After some time (max: the value of the container-wait-time property) the message “Proxy activated” appears in the logs and the user is redirected to the app page.
If the startup fails or the timout is exceeded, the user is redirected to an error page. In this case, an error should be logged in the shinyproxy logs as well.

I wonder where this 404 response is coming from… could you perhaps use the browser’s dev console to see which specific request got the 404 response?

moliveira · January 17, 2018, 1:46pm

Hi,

Thanks for the quick response.
What seems to be happening is that when a new user signs in and tries to start up a heavier app, the container takes a while to respond. When “Creating container with ContainerConfig” and “Starting container with Id” appears in the logs, the “Launching app” animation is showing. The empty 404 error appears on the browser when “Container unresponsive, trying again (2/15)” appears on the logs. The time between “Starting container” and the warning “Container unresponsive” does not seem to change with container-wait-time, rather just the number of tries before the container is finally considered unresponsive (if it failed to start after the total number of times, a different “final” error would show and refreshing would not solve it). After “Proxy activated” appears on the logs, if the user refreshes the page, the error will disappear and the app will be running normally. This also does not seem to be entirely consistent behaviour as the error does not appear every time. However, I haven’t yet figured out why.

I am including the relevant part of the logs below.

Thanks,
Mariana

2018-01-17 13:24:35.512  INFO 56521 --- [  XNIO-2 task-3] c.s.docker.client.DefaultDockerClient    : Starting container with Id: 46156325d6cbec328407b9720dac6718ba8dbe5ef06e8f1471161306fbca355d
2018-01-17 13:24:39.287  WARN 56521 --- [  XNIO-2 task-3] eu.openanalytics.services.DockerService  : Container unresponsive, trying again (2/15): http://localhost:20000
2018-01-17 13:24:41.290  WARN 56521 --- [  XNIO-2 task-3] eu.openanalytics.services.DockerService  : Container unresponsive, trying again (3/15): http://localhost:20000
2018-01-17 13:24:43.815  INFO 56521 --- [  XNIO-2 task-3] eu.openanalytics.services.DockerService  : Proxy activated [user: jkGH1Vb5pHv8BAc_ZfLDVHsw_szjIhNnzwXCpQCP] [app: replid] [port: 20000]

Sasha · March 20, 2018, 4:08pm

Hi Mariana,

Did you manage to solve this problem please? I have come across exactly the same issue…

Tx!

moliveira · March 20, 2018, 4:22pm

Hi Sasha,

No, I am still having the same problem…

Sasha · March 20, 2018, 6:18pm

Hi,

I have exactly the same problem as Mariana:
the message ‘Proxy activated’ appears in log file, however the redirect to the app page does not happen. In my case the HTML output is ‘undefined’, there is no error page. Then I just need to reload and I am connected to the container which was successfully created with the first login.
I have inserted some debugging output in ‘app.html’ of Shinyproxy, can see that after the first login (the one which end with HTML ‘undefined’) this code

var source = $("#shinyframe").attr(“src”);
if (source == “”) { …never executes, although the var src is “”…}

so, there is no path to the container available. Maybe, I am not explaining it correctly.

Could it be some timing issue? My app takes some time to start, has lots of data on load.

Tx!

akenny · March 22, 2018, 5:46pm

Hi @Sasha, does this happen with the smaller sample applications?

Sasha · March 22, 2018, 6:47pm

Hi,

yep, I have just tried it, have build the image of a smaller app with the same docker-compose.yml. The result is the same: “undefined” as HTML output.

I have different machines:

the server on the AWS: my app with Postgre DB, lots of data on load, images are build with docker-compose - everything is ok;
Debian 8.9 on the VirtualBox VM: the result as described, with ‘undefined’;
Debian 9.3 on the VirtualBox VM: the result as described, with ‘undefined’;

Previously everything worked ok also on VirtualBox VMs, the issue cropped up after the rebuilding the app’s image.

I am using shinyproxy 1.0.2

To troubleshoot it I have inserted additional debugging output in the jar file and re-compiled.
I can see that the only reference to error 404 (which Mariana has) is in ShinyProxyApplication.java file here:

HttpHandler handler = new ProxyHandler(proxyClient, ResponseCodeHandler.HANDLE_404);

Could it be that ‘undefined’ HTML output appears because I have some other response, which is not handled here?

Tx!

tharris · December 14, 2018, 6:47am

Hi @sasha, @moliveira did you ever get an answer to this question. I am having the same problem:

App works when running the docker image and bashing into it. But then, when running the image on ShinyProxy, I get an ‘undefined’ in the HTML, and nothing else. Bizarrely, the page works on refresh :s

I have successfully built the Euler container and it works, but the app with my data (fairly large, custom JS…) does not.

Any ideas? Here are the logs from ShinyProxy (truncated)
2018-12-14 17:25:37.684 INFO 32763 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/webjars/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler] 2018-12-14 17:25:37.685 INFO 32763 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler] 2018-12-14 17:25:37.824 INFO 32763 --- [ main] .m.m.a.ExceptionHandlerExceptionResolver : Detected @ExceptionHandler methods in baseController.RestErrorHandler 2018-12-14 17:25:37.960 INFO 32763 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/**/favicon.ico] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler] 2018-12-14 17:25:38.610 INFO 32763 --- [ main] o.s.b.a.w.s.WelcomePageHandlerMapping : Adding welcome page template: index 2018-12-14 17:25:38.847 INFO 32763 --- [ main] o.s.l.c.support.AbstractContextSource : Property 'userDn' not set - anonymous context will be used for read-write operations 2018-12-14 17:25:39.257 INFO 32763 --- [ main] o.s.j.e.a.AnnotationMBeanExporter : Registering beans for JMX exposure on startup 2018-12-14 17:25:39.264 INFO 32763 --- [ main] o.s.j.e.a.AnnotationMBeanExporter : Bean with name 'dataSource' has been autodetected for JMX exposure 2018-12-14 17:25:39.292 INFO 32763 --- [ main] o.s.j.e.a.AnnotationMBeanExporter : Located MBean 'dataSource': registering with JMX server as MBean [com.zaxxer.hikari:name=dataSource,type=HikariDataSource] 2018-12-14 17:25:39.499 INFO 32763 --- [ main] o.s.b.w.e.u.UndertowServletWebServer : Undertow started on port(s) 3838 (http) with context path '' 2018-12-14 17:25:39.512 INFO 32763 --- [ main] e.o.c.ContainerProxyApplication : Started ContainerProxyApplication in 20.778 seconds (JVM running for 22.27) 2018-12-14 17:25:42.267 INFO 32763 --- [ XNIO-2 task-1] io.undertow.servlet : Initializing Spring FrameworkServlet 'dispatcherServlet' 2018-12-14 17:25:42.271 INFO 32763 --- [ XNIO-2 task-1] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization started 2018-12-14 17:25:42.402 INFO 32763 --- [ XNIO-2 task-1] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization completed in 129 ms 2018-12-14 17:25:53.031 INFO 32763 --- [ XNIO-2 task-6] c.s.docker.client.DefaultDockerClient : Starting container with Id: e25a51c04f93ef4b42e488ab980014fcf21ba8d042250655d2122e6fd021326e 2018-12-14 17:25:56.483 INFO 32763 --- [ XNIO-2 task-6] e.o.containerproxy.service.ProxyService : Proxy activated [user: YzrmiY3uAVWoJE9JuBQeuxT2PKi0pI_mIiXAHufk] [spec: shinyproxytim] [id: 743faa5e-aa10-42d8-ab48-97174bfaef96] 2018-12-14 17:26:13.991 INFO 32763 --- [ XNIO-2 task-8] c.s.docker.client.DefaultDockerClient : Starting container with Id: 1e68b244e93250b14ebe6a354c78941bbe553e24cb7eab43180195572f108216 2018-12-14 17:26:16.709 WARN 32763 --- [ XNIO-2 task-8] e.o.shinyproxy.ShinyProxyTestStrategy : Container unresponsive, trying again (2/10): http://localhost:20001 2018-12-14 17:26:18.718 WARN 32763 --- [ XNIO-2 task-8] e.o.shinyproxy.ShinyProxyTestStrategy : Container unresponsive, trying again (3/10): http://localhost:20001 2018-12-14 17:26:23.163 INFO 32763 --- [ XNIO-2 task-8] e.o.containerproxy.service.ProxyService : Proxy activated [user: YzrmiY3uAVWoJE9JuBQeuxT2PKi0pI_mIiXAHufk] [spec: customer_dashboardy] [id: fdb10fe9-c890-4093-ac68-f4e8ee7d81cf] 2018-12-14 17:27:10.628 INFO 32763 --- [tiveProxyKiller] e.o.c.service.HeartbeatService : Releasing inactive proxy [user: YzrmiY3uAVWoJE9JuBQeuxT2PKi0pI_mIiXAHufk] [spec: shinyproxytim] [id: 743faa5e-aa10-42d8-ab48-97174bfaef96] [silence: 73209ms] 2018-12-14 17:27:11.006 INFO 32763 --- [pool-2-thread-1] e.o.containerproxy.service.ProxyService : Proxy released [user: YzrmiY3uAVWoJE9JuBQeuxT2PKi0pI_mIiXAHufk] [spec: shinyproxytim] [id: 743faa5e-aa10-42d8-ab48-97174bfaef96]

WillP · December 4, 2019, 9:05pm

Hi all,
I am also having this problem. My app is very heavy compared to any of the samples. Often, I will find I will go to the site (after having logged in previously), and the 404 error will appear as first described. I then refresh, and everything works normally.

Would be great to find out how to rectify this issue.

Will