Fedora Account System
Red Hat Associate
Red Hat Customer
I am wondering about these problems: http://lists.jboss.org/pipermail/aerogear-dev/2014-October/009585.html http://lists.jboss.org/pipermail/aerogear-dev/2014-October/009586.html As said in the mails above, I think the (incorrect?) 504 causes the deletion of the server. But yeah, I was able to use it for a minute or two... than I got "removed" Now, I tried a second time, but this time I used it with "-d", and that worked... no errors
I noticed another issue, with the rhc tool: ➜ ~ rhc -d app create --no-git fooxsxoxmxething https://cartreflect-claytondev.rhcloud.com/reflect\?github\=matzew/ups-wildfly /Users/matzew/.rvm/gems/ruby-2.1.2@global/gems/highline-1.6.21/lib/highline/system_extensions.rb:230: warning: Insecure world writable dir /Apache/maven in PATH, mode 040777 DEBUG: Using config file /Users/matzew/.openshift/express.conf DEBUG: Authenticating with RHC::Auth::Token DEBUG: Connecting to https://openshift.redhat.com/broker/rest/api DEBUG: Getting all domains DEBUG: Client supports API versions 1.1, 1.2, 1.3, 1.4, 1.5, 1.6, 1.7 DEBUG: Created new httpclient DEBUG: Request GET https://openshift.redhat.com/broker/rest/api DEBUG: code 200 849 ms DEBUG: Server supports API versions 1.0, 1.1, 1.2, 1.3, 1.4, 1.5, 1.6, 1.7 DEBUG: Using API version 1.7 DEBUG: Client API version 1.7 is not current. Refetching API DEBUG: Request GET https://openshift.redhat.com/broker/rest/api DEBUG: code 200 208 ms DEBUG: Using token authentication DEBUG: Request GET https://openshift.redhat.com/broker/rest/domains DEBUG: code 200 215 ms DEBUG: Getting all domains DEBUG: Getting all cartridges DEBUG: Using token authentication DEBUG: Request GET https://openshift.redhat.com/broker/rest/cartridges DEBUG: code 200 496 ms The cartridge 'https://cartreflect-claytondev.rhcloud.com/reflect?github=matzew/ups-wildfly' will be downloaded and installed Application Options ------------------- Domain: pushee Cartridges: https://cartreflect-claytondev.rhcloud.com/reflect?github=matzew/ups-wildfly Gear Size: default Scaling: no Creating application 'fooxsxoxmxething' ... DEBUG: Creating application 'fooxsxoxmxething' with these options - {:cartridges=>[#<RHC::Rest::Cartridge:0x007f968790dbc8 @attributes={"url"=>"https://cartreflect-claytondev.rhcloud.com/reflect?github=matzew/ups-wildfly", "messages"=>[]}, @client=nil>]} DEBUG: Adding application fooxsxoxmxething to domain 51c99fc05973caba29000175 DEBUG: Using token authentication DEBUG: Request POST https://openshift.redhat.com/broker/rest/domain/pushee/applications DEBUG: code 422 302040 ms The supplied application name 'fooxsxoxmxething' already exists ================ Note, the fooxsxoxmxething NEVER existed before I executed the command Perhaps this is a different bug ?
I checked this myself and it looks like a resource issue. On busier nodes, the timeout is too low to download (300MB?!) the huge app and build it, so if the timeout is met and control start did not return a proper value, it terminates the build and removes the app. However, I'm not sure about that existing name, I guess this is probably a race condition when rhc tries to re-create it, but the gear hasn't been removed yet. It looks to be working just fine on large gears. October 30 06:59:55 INFO [request_id=1aba5d187b0bae85df6aff09592b88cc,app_uuid=545218d65973ca5ba3000178] openshift-agent: request end: action=cartridge_do, requestid=c25da06591bc551e9751002f46bf6199, senderid=mcollect.cloud.redhat.com, statuscode=1, data={:time=>nil, :output=>"Shell command '/sbin/runuser -s /bin/sh 545218d65973ca5ba3000178 -c \"exec /usr/bin/runcon 'unconfined_u:system_r:openshift_t:s0:c5,c641' /bin/sh -c \\\"set -e; /var/lib/openshift/545218d65973ca5ba3000178/aerogear-push/bin/control start \\\"\"' exceeded timeout of 232\n\n", :exitcode=>157, :addtl_params=>nil} October 30 07:00:02 INFO [request_id=1aba5d187b0bae85df6aff09592b88cc,app_uuid=545218d65973ca5ba3000178] openshift-agent: request start: action=cartridge_do requestid=c5b854c89073516380851852580b3065, senderid=mcollect.cloud.redhat.com, data={:cartridge=>"openshift-origin-node", :action=>"app-destroy", :args=>{"--with-app-uuid"=>"545218d65973ca5ba3000178", "--with-app-name"=>"mmahut8test", "--with-expose-ports"=>false, "--with-container-uuid"=>"545218d65973ca5ba3000178", "--with-container-name"=>"mmahut8test", "--with-namespace"=>"mmahut", "--with-uid"=>5741, "--with-request-id"=>"1aba5d187b0bae85df6aff09592b88cc", "--cart-name"=>"openshift-origin-node"}, :process_results=>true} If you want, we should move it to the rhc/broker component for better error reporting in this specific case.
And one more note: the app could have started after the timeout reached, but the broker is going to remove it anyway, as it cannot guarantee the build went fine. That's few seconds when you could spot it alive and deleted shortly after.
there is already a community issue to address the 'size' https://issues.jboss.org/browse/AGPUSH-1008
Derek: Can you please check what the sequence of events is and what the broker can/should do, if anything, to make things more clear.
I am getting now this: Unable to complete the requested operation due to: An invalid exit code (157) was returned from the server ex-std-node452.prod.rhcloud.com. This indicates an unexpected problem during the execution of your request. Reference ID: 0f90e250ab9ebf97f0a96b15fd394fb0
matzew - we were experiencing outages yesterday and today on OpenShift Online so its possible your latest experience is due to that and not your original reported issue.
Tried to reproduce on a devenv, and was able to successfully download cart and create the app. Need to look for where and when the broker would throw a 504.
Looking through broker code, I see no place we explicitly throw a 504 either with 504 or :gateway_timeout constant.
I was able to reproduce on OpenShift Online, but it's not 100% of the time. RE: the situation where you get rhc to state "The supplied application name #appname already exists" This message is comming from applications_controller.rb line 205, and I view it as a case of the message not really being accurate with the situation. We could improve the logic here to see if Mongo is throwing to make a more accurate determination of what happened. Right now it treats any "OperationFailure" exception from Mongo as a duplicate key. All that said, I was able to reproduce the situation where the app appears created, but you get a less than accurate Error message displayed, followed by a brief period of time where the app shows in rhc before the broker cleans it up. [decarr@localhost scripts]$ rhc app create --no-git myapp https://cartreflect-claytondev.rhcloud.com/reflect\?github\=matzew/ups-wildfly The cartridge 'https://cartreflect-claytondev.rhcloud.com/reflect?github=matzew/ups-wildfly' will be downloaded and installed Application Options ------------------- Domain: decarr Cartridges: https://cartreflect-claytondev.rhcloud.com/reflect?github=matzew/ups-wildfly Gear Size: default Scaling: no Creating application 'myapp' ... The supplied application name 'myapp' already exists [decarr@localhost scripts]$ rhc apps myapp @ http://myapp-decarr.rhcloud.com/ (uuid: 545d39794382ecfd2a000202) ------------------------------------------------------------------------- Domain: decarr Created: 4:28 PM Gears: 1 (defaults to small) Git URL: ssh://545d39794382ecfd2a000202.com/~/git/myapp.git/ SSH: 545d39794382ecfd2a000202.com Deployment: auto (on git push) aerogear-aerogear-push-1.0.1 (AeroGear Push Server 1.0.1 and WildFly) --------------------------------------------------------------------- From: https://cartreflect-claytondev.rhcloud.com/reflect?github=matzew/ups-wildfly Website: http://www.aerogear.org Gears: Located with mysql-5.5 mysql-5.5 (MySQL 5.5) --------------------- Gears: Located with aerogear-aerogear-push-1.0.1 Connection URL: mysql://$OPENSHIFT_MYSQL_DB_HOST:$OPENSHIFT_MYSQL_DB_PORT/ Database Name: myapp Password: qHzeq-cV4EKQ Username: adminAyQ7f35 You have access to 1 application. [decarr@localhost scripts]$ rhc apps myapp @ http://myapp-decarr.rhcloud.com/ (uuid: 545d39794382ecfd2a000202) ------------------------------------------------------------------------- Domain: decarr Created: 4:28 PM Gears: 1 (defaults to small) Git URL: ssh://545d39794382ecfd2a000202.com/~/git/myapp.git/ SSH: 545d39794382ecfd2a000202.com Deployment: auto (on git push) aerogear-aerogear-push-1.0.1 (AeroGear Push Server 1.0.1 and WildFly) --------------------------------------------------------------------- From: https://cartreflect-claytondev.rhcloud.com/reflect?github=matzew/ups-wildfly Website: http://www.aerogear.org Gears: Located with mysql-5.5 mysql-5.5 (MySQL 5.5) --------------------- Gears: Located with aerogear-aerogear-push-1.0.1 Connection URL: mysql://$OPENSHIFT_MYSQL_DB_HOST:$OPENSHIFT_MYSQL_DB_PORT/ Database Name: myapp Password: qHzeq-cV4EKQ Username: adminAyQ7f35 You have access to 1 application. [decarr@localhost scripts]$ rhc apps No applications. Use 'rhc create-app'.
I have debugged this further. The longest running operation when testing this on a devenv is the PostConfigureComp: 2014-11-10 19:17:45.488 [DEBUG] Execute PostConfigureCompOp comp_spec=component:aerogear-aerogear-push-1.0.1/aerogear-aerogear-push-1.0.1/5461557b9ec4c30173000045 gear_id=5461557b9ec4c30173000046 (pid:144) 2014-11-10 19:17:45.497 [DEBUG] DEBUG: rpc_client.custom_request('cartridge_do', {:cartridge=>"aerogear-aerogear-push-1.0.1", :action=>"post-configure", :args=>{"--with-app-uuid"=>"5461557b9ec4c30173000046", "--with-app-name"=>"myapp", "--with-expose-ports"=>false, "--with-container-uuid"=>"5461557b9ec4c30173000046", "--with-container-name"=>"myapp", "--with-namespace"=>"mydomain", "--with-request-id"=>"7b04ffea4208411aafb585c2956547c9", "--component-name"=>"aerogear-aerogear-push-1.0.1", "--cart-name"=>"aerogear-push-1.0.1", "--with-software-version"=>"1.0.1", "--cartridge-vendor"=>"aerogear"}}, ip-10-230-128-154, {'identity' => ip-10-230-128-154}) (Request ID: 7b04ffea4208411aafb585c2956547c9) (pid:144) 2014-11-10 19:18:32.353 [DEBUG] DEBUG: [#<MCollective::RPC::Result:0x0000000725deb8 @agent="openshift", @action="cartridge_do", @results={:sender=>"ip-10-230-128-154", :statuscode=>0, :statusmsg=>"OK", :data=>{:time=>nil, :output=>"Starting aerogear-push cart\nFound 127.1.244.129:8080 listening port\nFound 127.1.244.129:9990 listening port\nCLIENT_MESSAGE: Could not connect to WildFly management interface, skipping deployment verification\n", :exitcode=>0, :addtl_params=>{:deployments=>[{:id=>"2bf4e08e", :ref=>"master", :sha1=>"d16ee7f", :force_clean_build=>nil, :hot_deploy=>nil, :created_at=>1415665021.985, :activations=>[1415665066.2974288]}]}}}>] (Request ID: 7b04ffea4208411aafb585c2956547c9) (pid:144) On the devenv, that process can take almost a minute to complete. I then tried to take an alternative cartridge and see what happens if I change the cartridge post_install script to just cause a timeout with an extended sleep. Attempting this caused the following: Unable to complete the requested operation due to: An invalid exit code (157) was returned from the server ip-10-230-128-154. This indicates an unexpected problem during the execution of your request. Reference ID: 6c0112cfa1a2f4fed66725cacc1415a5 I was not able to cause a 504 Gateway Timeout, but that may be a consequence of the Online environment throwing a different error in response to not getting a reply from MCollective when a long operation occurs.
When reproduced using OpenShift Online, I get following output in broker log that implies it is taking too long for the aerogear-push/bin/control start command to complete and is resulting in a timeout. I am not sure how to debug this further, is there anything we can do to improve the start-up speed? This seems to happen more frequently with the free tier user, when I am using a better CPU in our devenvs, I am unable to reproduce. 2014-11-10T17:08:37.059182-05:00 ex-srv1 openshift-broker[21546]: [DEBUG] src=app DEBUG: [#<MCollective::RPC::Result:0x0000000891d248 @agent="openshift", @action="cartridge_do", @results={:sender=>"ex-std-node483.prod.rhcloud.com", :statuscode=>1, :statusmsg=>"cartridge_do_action failed 157. Output Shell command '/sbin/runuser -s /bin/sh 54613637e0b8cd149700007d -c \"exec /usr/bin/runcon 'unconfined_u:system_r:openshift_t:s0:c4,c27' /bin/sh -c \\\"set -e; /var/lib/openshift/54613637e0b8cd149700007d/aerogear-push/bin/control start \\\"\"' exceeded timeout of 230\n\n", :data=>{:time=>nil, :output=>"Shell command '/sbin/runuser -s /bin/sh 54613637e0b8cd149700007d -c \"exec /usr/bin/runcon 'unconfined_u:system_r:openshift_t:s0:c4,c27' /bin/sh -c \\\"set -e; /var/lib/openshift/54613637e0b8cd149700007d/aerogear-push/bin/control start \\\"\"' exceeded timeout of 230\n\n", :exitcode=>157, :addtl_params=>nil}}>] (Request ID: ca782b990be7075668895b2ff7f5b9a4) 2014-11-10T17:08:37.059207-05:00 ex-srv1 openshift-broker[21546]: [DEBUG] src=app DEBUG: MCollective Response Time (execute_direct: post-configure): 234.37056025s (Request ID: ca782b990be7075668895b2ff7f5b9a4) 2014-11-10T17:08:37.059215-05:00 ex-srv1 openshift-broker[21546]: [DEBUG] src=app DEBUG: server results: Shell command '/sbin/runuser -s /bin/sh 54613637e0b8cd149700007d -c "exec /usr/bin/runcon 'unconfined_u:system_r:openshift_t:s0:c4,c27' /bin/sh -c \"set -e; /var/lib/openshift/54613637e0b8cd149700007d/aerogear-push/bin/control start \""' exceeded timeout of 230 2014-11-10T17:08:37.059222-05:00 ex-srv1 openshift-broker[21546]: [DEBUG] src=app DEBUG: server results: 2014-11-10T17:08:37.059229-05:00 ex-srv1 openshift-broker[21546]: [ERROR] src=app An invalid exit code (157) was returned from the server ex-std-node483.prod.rhcloud.com. This indicates an unexpected problem during the execution of your request. 2014-11-10T17:08:37.059237-05:00 ex-srv1 openshift-broker[21546]: [ERROR] src=app /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-msg-broker-mcollective-1.30.6/lib/openshift/mcollective_application_container_proxy.rb:2779:in `parse_result' /var/www/openshift/broker/config/initializers/new_relic.rb:37:in `parse_result' /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-msg-broker-mcollective-1.30.6/lib/openshift/mcollective_application_container_proxy.rb:2956:in `run_cartridge_command' /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-msg-broker-mcollective-1.30.6/lib/openshift/mcollective_application_container_proxy.rb:848:in `post_configure_component' /opt/rh/ruby193/root/usr/share/gems/gems/newrelic_rpm-3.6.6.147/lib/new_relic/agent/method_tracer.rb:518:in `block in post_configure_component_with_trace_Custom_OpenShift_MCollectiveApplicationContainerProxy_post_configure_component' /opt/rh/ruby193/root/usr/share/gems/gems/newrelic_rpm-3.6.6.147/lib/new_relic/agent/method_tracer.rb:268:in `trace_execution_scoped' /opt/rh/ruby193/root/usr/share/gems/gems/newrelic_rpm-3.6.6.147/lib/new_relic/agent/method_tracer.rb:513:in `post_configure_component_with_trace_Custom_OpenShift_MCollectiveApplicationContainerProxy_post_configure_component' /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.31.8/app/models/gear.rb:196:in `post_configure_component' /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.31.8/app/pending_ops_models/post_configure_comp_op.rb:12:in `execute' /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.31.8/app/models/pending_app_op_group.rb:104:in `block in execute' /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.31.8/app/models/pending_app_op_group.rb:94:in `each' /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.31.8/app/models/pending_app_op_group.rb:94:in `execute' /opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.31.8/app/models/application.rb:1754:in `run_jobs' /opt/rh/ruby 2014-11-10T17:08:37.059248-05:00 ex-srv1 openshift-broker[21546]: [ERROR] src=app Encountered error during execute 'An invalid exit code (157) was returned from the server ex-std-node483.prod.rhcloud.com. This indicates an unexpected problem during the execution of your request.' 2014-11-10T17:08:37.059256-05:00 ex-srv1 openshift-broker[21546]: [DEBUG] src=app ["/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-msg-broker-mcollective-1.30.6/lib/openshift/mcollective_application_container_proxy.rb:2779:in `parse_result'", "/var/www/openshift/broker/config/initializers/new_relic.rb:37:in `parse_result'", "/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-msg-broker-mcollective-1.30.6/lib/openshift/mcollective_application_container_proxy.rb:2956:in `run_cartridge_command'", "/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-msg-broker-mcollective-1.30.6/lib/openshift/mcollective_application_container_proxy.rb:848:in `post_configure_component'", "/opt/rh/ruby193/root/usr/share/gems/gems/newrelic_rpm-3.6.6.147/lib/new_relic/agent/method_tracer.rb:518:in `block in post_configure_component_with_trace_Custom_OpenShift_MCollectiveApplicationContainerProxy_post_configure_component'", "/opt/rh/ruby193/root/usr/share/gems/gems/newrelic_rpm-3.6.6.147/lib/new_relic/agent/method_tracer.rb:268:in `trace_execution_scoped'", "/opt/rh/ruby193/root/usr/share/gems/gems/newrelic_rpm-3.6.6.147/lib/new_relic/agent/method_tracer.rb:513:in `post_configure_component_with_trace_Custom_OpenShift_MCollectiveApplicationContainerProxy_post_configure_component'", "/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.31.8/app/models/gear.rb:196:in `post_configure_component'", "/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.31.8/app/pending_ops_models/post_configure_comp_op.rb:12:in `execute'", "/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.31.8/app/models/pending_app_op_group.rb:104:in `block in execute'", "/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.31.8/app/models/pending_app_op_group.rb:94:in `each'", "/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.31.8/app/models/pending_app_op_group.rb:94:in `execute'", "/opt/rh/ruby193/root/usr/share/gems/gems/openshift-origin-controller-1.31.8/app/models/applicat 2014-11-10T17:08:37.096115-05:00 ex-srv1 openshift-broker[21546]: [DEBUG] src=app Rollback PostConfigureCompOp comp_spec=component:aerogear-aerogear-push-1.0.1/aerogear-aerogear-push-1.0.1/54613636e0b8cd149700007c gear_id=54613637e0b8cd149700007d
I wonder, what's needed to get our cartridge working again the PR to remove old version is failing for all of us https://github.com/aerogear/openshift-origin-cartridge-aerogear-push/pull/12
At this point we are not sure what we can do here
The 504 Gateway Timeout Application Options ------------------- Domain: decarr Cartridges: https://cartreflect-claytondev.rhcloud.com/reflect?github=matzew/ups-wildfly Gear Size: default Scaling: no Creating application 'derekapp' ... DEBUG: Creating application 'derekapp' with these options - {:cartridges=>[#<RHC::Rest::Cartridge:0x00000000ff2828 @attributes={"url"=>"https://cartreflect-claytondev.rhcloud.com/reflect?github=matzew/ups-wildfly", "messages"=>[]}, @client=nil>]} DEBUG: Adding application derekapp to domain 538890905973cad0e200001b DEBUG: Using token authentication DEBUG: Request POST https://openshift.redhat.com/broker/rest/domain/decarr/applications DEBUG: code 504 300230 ms DEBUG: Response did not include a message from server: invalid character at "<html><bod" Server returned an unexpected error code: 504 I tried to grep the production logs when this occurs, and it appears when this occurs rhc never actually made the request to the broker.
Have more data on this now. I have receieved 3 possible outcomes to the rhc command: HTTP 504 Log analysis shows that in this situation, the start-up of the cartridge is exceeding the mco timeout. This results in the broker rolling back the operation. A 504 is recieved by the client if the rollback by the broker does not complete in time before the HTTP request times out. The rollback by the broker does continue to process in the background and the application is ultimately removed. HTTP 157 This occurs when the mco timeout occurs, and the broker rollback completes in time. HTTP 422 (which occurs when the app with name already exists error appears) This appears to occur when you try to create the application again after receiving a 504. In this case, the application is not created because rollback of the previous app is still in progress.
it looks like wildfly is running out processes (limited to 250) in online which causes the deployment of the aerogear war to fail and ultimately the app times out on creation as a result. not sure why this would start happening now unless something changed in either wildfly or aerogear, but it means it won't deploy on small gears as it stands today. https://gist.github.com/bparees/f5c08ba4e0454c0cef7d
probably related to https://bugzilla.redhat.com/show_bug.cgi?id=1090092
Test on INT(devenv_5294) Always got the error "Application creation is taking longer than expected. Please wait a few minutes, then refresh this page." when creating a non-scaling aerogear app.
the aerogear team switched this cart to use AS7 instead of Wildfly which has solved the problem for now. i've validated the cart can be created in online.
Verified with INT(devenv_5297) and devenv-stage_1106 Could create aerogear without timeout error and could access the url. $ rhc domain show aerogear @ http://aerogear-xiu.dev.rhcloud.com/ (uuid: 54649b8f5f2bd02a65000127) -------------------------------------------------------------------------------- Domain: xiu Created: 7:52 PM Gears: 1 (defaults to small) Git URL: ssh://54649b8f5f2bd02a65000127.rhcloud.com/~/git/aerogear.git/ SSH: 54649b8f5f2bd02a65000127.rhcloud.com Deployment: auto (on git push) aerogear-aerogear-push-1.0.2 (AeroGear Unified Push Server 1.0.2 on JBoss) -------------------------------------------------------------------------- From: https://cartreflect-claytondev.rhcloud.com/reflect?github=aerogear/openshift-origin-cartridge-aerogear-push#AeroGear Website: http://aerogear.org Gears: Located with mysql-5.5 mysql-5.5 (MySQL 5.5) --------------------- Gears: Located with aerogear-aerogear-push-1.0.2 Connection URL: mysql://$OPENSHIFT_MYSQL_DB_HOST:$OPENSHIFT_MYSQL_DB_PORT/ Database Name: aerogear Password: qsz4sj-qq8E4 Username: adminAjcqpND
Matthias Wessendorf <matthias> updated the status of jira AGPUSH-1008 to Resolved