test/end-to-end/core test/end-to-end/core.sh:38: executing 'curl -s -X POST http://172.30.156.163:5432/keys/foo -d value=1337' expecting any result and text 'Key created'

[0xmichalis]

=== BEGIN TEST CASE ===
test/end-to-end/core.sh:38: executing 'curl -s -X POST http://172.30.156.163:5432/keys/foo -d value=1337' expecting any result and text 'Key created'; re-trying every 0.2s until completion or 60.000s
FAILURE after 59.280s: test/end-to-end/core.sh:38: executing 'curl -s -X POST http://172.30.156.163:5432/keys/foo -d value=1337' expecting any result and text 'Key created'; re-trying every 0.2s until completion or 60.000s: the command timed out
Standard output from the command:
<h1>Internal Server Error</h1>
... repeated 267 times
Standard error from the command:
=== END TEST CASE ===

https://ci.openshift.redhat.com/jenkins/job/test_pull_request_origin_end_to_end/9240/consoleFull#-12440632375898c58db7602c31c0eab717

/kind test-flake

[mfojtik]

Quick investigation:

The internal error is coming from:

172.18.12.190 - - [08/Feb/2018:07:47:01 +0000] "POST /keys/foo HTTP/1.1" 500 30 0.0018
Updating key foo to 1337
2018-02-08 07:47:01 - ActiveRecord::StatementInvalid - Mysql2::Error: Table 'root.key_pairs' doesn't exist: SHOW FULL FIELDS FROM `key_pairs`:
	/opt/app-root/src/bundle/ruby/gems/mysql2-0.4.10/lib/mysql2/client.rb:120:in `_query'
	/opt/app-root/src/bundle/ruby/gems/mysql2-0.4.10/lib/mysql2/client.rb:120:in `block in query'
	/opt/app-root/src/bundle/ruby/gems/mysql2-0.4.10/lib/mysql2/client.rb:119:in `handle_interrupt'
	/opt/app-root/src/bundle/ruby/gems/mysql2-0.4.10/lib/mysql2/client.rb:119:in `query'
	/opt/app-root/src/bundle/ruby/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:214:in `block (2 levels) in execute'
	/opt/app-root/src/bundle/ruby/gems/activesupport-5.1.4/lib/active_support/dependencies/interlock.rb:46:in `block in permit_concurrent_loads'
	/opt/app-root/src/bundle/ruby/gems/activesupport-5.1.4/lib/active_support/concurrency/share_lock.rb:185:in `yield_shares'
	/opt/app-root/src/bundle/ruby/gems/activesupport-5.1.4/lib/active_support/dependencies/interlock.rb:45:in `permit_concurrent_loads'
	/opt/app-root/src/bundle/ruby/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:213:in `block in execute'
	/opt/app-root/src/bundle/ruby/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract_adapter.rb:612:in `block (2 levels) in log'
	/opt/rh/rh-ruby22/root/usr/share/ruby/monitor.rb:211:in `mon_synchronize'
	/opt/app-root/src/bundle/ruby/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract_adapter.rb:611:in `block in log'
	/opt/app-root/src/bundle/ruby/gems/activesupport-5.1.4/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
	/opt/app-root/src/bundle/ruby/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract_adapter.rb:603:in `log'
	/opt/app-root/src/bundle/ruby/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:212:in `execute'
	/opt/app-root/src/bundle/ruby/gems/activerecord-5.1.4/lib/active_record/connection_adapters/mysql/database_statements.rb:26:in `execute'
	/opt/app-root/src/bundle/ruby/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:223:in `execute_and_free'
	/opt/app-root/src/bundle/ruby/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:854:in `column_definitions'
	/opt/app-root/src/bundle/ruby/gems/activerecord-5.1.4/lib/active_record/connection_adapters/abstract_adapter.rb:166:in `columns'
	/opt/app-root/src/bundle/ruby/gems/activerecord-5.1.4/lib/active_record/connection_adapters/schema_cache.rb:67:in `columns'
	/opt/app-root/src/bundle/ruby/gems/activerecord-5.1.4/lib/active_record/connection_adapters/schema_cache.rb:73:in `columns_hash'
	/opt/app-root/src/bundle/ruby/gems/activerecord-5.1.4/lib/active_record/model_schema.rb:471:in `load_schema!'
	/opt/app-root/src/bundle/ruby/gems/activerecord-5.1.4/lib/active_record/attributes.rb:233:in `load_schema!'
	/opt/app-root/src/bundle/ruby/gems/activerecord-5.1.4/lib/active_record/attribute_decorators.rb:50:in `load_schema!'
	/opt/app-root/src/bundle/ruby/gems/activerecord-5.1.4/lib/active_record/model_schema.rb:464:in `block in load_schema'
	/opt/rh/rh-ruby22/root/usr/share/ruby/monitor.rb:211:in `mon_synchronize'
	/opt/app-root/src/bundle/ruby/gems/activerecord-5.1.4/lib/active_record/model_schema.rb:461:in `load_schema'

Which indicates the database schema was not created?

[mfojtik]

Hrm. it seems like the hook was not finished in time?

Running test/end-to-end/core.sh:25: executing 'oc logs dc/frontend -n test' expecting success...
SUCCESS after 0.428s: test/end-to-end/core.sh:25: executing 'oc logs dc/frontend -n test' expecting success
Standard output from the command:
--> pre: Running hook pod ...
--> pre: Success
--> Scaling frontend-1 to 2
--> post: Running hook pod ...

[tnozicka]

looks like the the post hook pod was started

test                    1m          1m           1         frontend-1-hook-post.15114a0aa344519c            Pod                                                                 Normal    Scheduled                      default-scheduler              Successfully assigned frontend-1-hook-post to localhost
test                    1m          1m           1         frontend-1-hook-post.15114a0ab1c127bc            Pod                                                                 Normal    SuccessfulMountVolume          kubelet, localhost             MountVolume.SetUp succeeded for volume "default-token-xj4xp" 
test                    1m          1m           1         frontend-1-hook-post.15114a0b0ab20087            Pod                     spec.containers{lifecycle}                  Normal    Pulled                         kubelet, localhost             Container image "172.30.1.1:5000/test/origin-ruby-sample@sha256:800ace82b87ece0891ab4e93b8f58e59a2288b5080865be84a50d1a98e9e61ea" already present on machine
test                    1m          1m           1         frontend-1-hook-post.15114a0b3bebfdb2            Pod                     spec.containers{lifecycle}                  Normal    Created                        kubelet, localhost             Created container
test                    1m          1m           1         frontend-1-hook-post.15114a0b50b118a6            Pod                     spec.containers{lifecycle}                  Normal    Started                        kubelet, localhost             Started container

not sure why it didn't wait for the rollout to complete

[mfojtik]

Interestingly this is also failing for OSE 3.6 branch:

FAILURE after 60.035s: test/end-to-end/core.sh:37: executing 'curl -s -X POST http://172.30.102.61:5432/keys/foo -d value=1337' expecting any result and text 'Key created'; re-trying every 0.2s until completion or 60.000s: the command timed out

I'm 95% sure there is something broken in the images or templates or DockerHub :-)

[mfojtik]

@tnozicka it might be the script for hook pod ran but it does not have set -e so it might have failed but the hook succeeded?

[0xmichalis]

This job is officially broken since yesterday
https://openshift-gce-devel.appspot.com/builds/origin-ci-test/pr-logs/pull/batch/test_pull_request_origin_end_to_end/
https://deck-ci.svc.ci.openshift.org/?job=test_pull_request_origin_end_to_end

[0xmichalis]

/priority P0
/remove-priority P1

[mfojtik]

The revert openshift/ruby-hello-world#67 fixed the e2e tests (they are green again).

[junaruga]

The reason of the above error is the PR https://github.com/openshift/ruby-hello-world/pull/66/files that I sent to update Gemfile.lock. I created Gemfile.lock again.
The new version of activerecord and mysql2 related to the error.

What I wanted to do is to run ruby-hello-world without errors and warnings on Ruby 2.5.
Shall we start to use conditional Gemfile for [1] by RUBY_VERSION like [2]?

[1] https://github.com/openshift/ruby-hello-world/blob/master/Gemfile
[2] https://github.com/rspec/rspec-rails/blob/master/Gemfile

[bparees]

@mfojtik if the breakage is reverted why did you reopen this?